backblaze b2 / amazon s3 as remote in xoa

[nraynaud]

@shorian thank you for your help. can you tell me what kind of backup you were launching and at what phase the error happened ?

[shorian]

@nraynaud Normal backup to B2, concurrency set to 1, compression set to zsd - no other settings (ie no 'delete before' or 'with memory' - just a standard backup with zstd compression). I have also tried without compression without any variation in outcome.

Error occurs immediately after snapshot (about 5 mins later, but its the next line in the debug log), but we don't fail out for another 18 minutes; we get the bad allocation error every second until we finally die with a terminal 'bad allocation' error and completely fall over with an auto-restart of the script:

2021-01-16T22:20:00.164Z xo:xo-server ERROR uncaught exception {
  error: RangeError: Array buffer allocation failed
      at new ArrayBuffer (<anonymous>)
      at new Uint8Array (<anonymous>)
      at new FastBuffer (internal/buffer.js:950:1)
      at createUnsafeBuffer (buffer.js:149:12)
      at allocate (buffer.js:419:10)
      at Function.allocUnsafe (buffer.js:384:10)
      at Function.concat (buffer.js:564:25)
      at ManagedUpload.fillStream (/opt/xen-orchestra/node_modules/aws-sdk/lib/s3/managed_upload.js:433:38)
      at Transform.<anonymous> (/opt/xen-orchestra/node_modules/aws-sdk/lib/s3/managed_upload.js:188:44)
      at Transform.apply (events.js:314:20)
      at Transform.patchedEmit (/opt/xen-orchestra/@xen-orchestra/log/src/configure.js:92:17)
      at Transform.EventEmitter.emit (domain.js:483:12)
      at emitReadable_ (/opt/xen-orchestra/@xen-orchestra/fs/node_modules/readable-stream/lib/_stream_readable.js:538:12)
      at processTicksAndRejections (internal/process/task_queues.js:83:21)
}
terminate called after throwing an instance of 'std::bad_alloc'
  what():  std::bad_alloc
error: Forever detected script was killed by signal: SIGABRT
error: Script restart attempt #2
2021-01-16T22:20:17.950Z app-conf /opt/xen-orchestra/packages/xo-server/config.toml
2021-01-16T22:20:17.956Z app-conf /root/.config/xo-server/config.toml
2021-01-16T22:20:17.957Z app-conf /root/.config/xo-server/config.z-auto.json
2021-01-16T22:20:17.960Z xo:main INFO Configuration loaded.
2021-01-16T22:20:17.963Z xo:main INFO Web server listening on http://[::]:80

Interestingly I've left the backup process to keep running every few hours, and we're now getting some success - I've yet to have the 3 VMs in question all back up in one pass, but the last couple of passes have resulted in one or two of them completing successfully. See sample logs:

2021-01-18T09_00_00.011Z - backup NG.log.txt

2021-01-18T03_00_00.009Z - backup NG.log.txt

In summary, we are now we are getting some timeouts - different than the 12,000ms that we were seeing originally, but now with the new errors in the attached logs of 'no object with UUID or opaque ref'.

If I lower the memory back down to 4gb we revert back to the buffer allocation errors.

I'm very happy to send over more extensive logs but would prefer to do so 1:1 rather than into a public forum.

[nraynaud]

@shorian thank you I will look at all that.

[nraynaud]

@shorian

I just did a test with this configuration, would you mind checking that it as close as possible as yours? I got a backup to work with this configuration. That suggest we have to search for a limit and not plainly search for a bug.

If it's the same backup configuration, we'll have to look for a difference in the VMs (mine transfers 11.77 GiB of data).

Can you describe your VM please? in particular the number and size of the disks.

thank you for your help.

[shorian]

@nraynaud Identical setup, except using B2 not S3.

Initially looking at backing up 3 VMs, each with a single disk sized 100gb, 150gb and 25gb respectively, SR is thin provisioned (ext4), total backup size (compressed) is about 76gb over a 1gbps connection; takes about 90 mins for a clean backup.

Individually they back up fine, as a group they don't. (In total have about 1.2tb of VMs to back up but not trying for that one just yet).

[shorian]

Footnote to this - I have just tried to back up 20 small VMs and they all backed up fine; seems to be a function of VM size?

[nraynaud]

@shorian yes, VM size would make sense as a limit, I'll try to run with less memory.

[shorian]

@nraynaud I've been playing about with the larger VMs. It may be coincidence, but if I clear out the target (B2), then the backup seems to work ok with the XO that has 16gb mem. However, the second time the same back up is run, the larger machines fail with errors like the following:

Error calling AWS.S3.upload: class java.net.SocketTimeoutException - Read timed out (https://pod-xxx.backblaze.com/bz_internal/upload_part) after 324446 ms.

I'll run some tests over the course of the next day or so to see if the above is 100% repeatable or a coincidence...

[nraynaud]

@shorian thank you for your help.

[shorian]

@nraynaud Good of you to say; we have a common end goal, and I'm very grateful for your development efforts that are somewhat more useful than mine!

Ok, quick update - I left the backup process running for the larger VMs to see what happened, and somehow the issue seems to flush through? After clearing out the target (Backblaze), the 3 VMs back up fine first time around, the second backup failed with two VMs not backing up but the third went through successfully, then on the second backup only one failed, and now they're all backing up fine. I then had 3 full backups in a row go through cleanly using the XO with 16gb memory and your code from the new master.

I've then cleared down the target, repeated the above, and had the exact same outcome. First pass, all 3 back up, second pass only 1 backs up, third pass 2 back up, third, fourth and fifth all 3 back up fine. Go figure.

Clearly there's something not quite right, but it seems to flush through in time - which is unusual for a technical issue

[nraynaud]

@shorian it's been a bit of time, would you mind updating your xen-orchestra and re-trying the bug byt starting a backup with low node.js memory please ?

I have not changed anything, but I'm hopping you had a problem of cached code last time.

[shorian]

@nraynaud Afraid re-occurs - it's size of VM dependent; small VMs go through fine, larger VMs as above.

• xo-server 5.74.1
• xo-web 5.77.0

[nraynaud]

@shorian Thank you very much, I'll dig deeper.

[nraynaud]

I just had a getaddrinfo EAI_AGAIN error after 3h when trying a big backup towards AWS S3. According to stack overflow, it's generally a timeout on a DNS query. That seems close to your timeout error on the server side. I guess the immediate hypothesis is that the network side of XOA VM is choking on things.

In my last change I added support for keepalive in the AWS library, I will look in this direction.

[nraynaud]

@shorian I forget if you're building from sources, would you mind trying this code with a small amount of memory ? https://github.com/vatesfr/xen-orchestra/pull/5579 ?

I removed the keepalive in there.

nraynaud opened this pull request in vatesfr/xen-orchestra

open WiP: try to fix S3 network issues on big backups #5579

[shorian]

@nraynaud superb! I can’t get into this until tomorrow evening but will be on it as soon as I can. Bear with....

[shorian]

@nraynaud Ok, so far so good; haven't had a timeout yet. However the backups are reported as being much much smaller ; overall cumulative size has dropped from over 20gb to under 5gb, which would avoid the problem in any case.

There are no changes to the settings (zstd, normal snapshot without memory), all I can think of is that maybe there were a lot of resends resulting in the large data size being reported within XO, but unless I've picked up a much improved algorithm by building that commit compared with the released branch, I'm a little confused.

I will take a look at the size of the actual backups as held on the remote (Backblaze B2) compared with the reported size in XO to see if I can substantiate the above paragraph.

Meanwhile, I'll keep running backups to soak test it but so far we're looking good!

[DustinB]

@shorian Just a point, don't forget to test your restoration as well.

Making a backup is only half of having working backups.

[shorian]

@dustinb Concur 100%; my current focus is on confirming the error doesn't reoccur and understanding the change in what I'm seeing compared with previous backups, before this goes into production I 100% agree it should be tested for restores. I shall do so myself once I've got confidence that the symptom has been resolved.

[shorian]

@nraynaud Unfortunately after a good start I'm now seeing AWS.S3.upload socket hang up errors:

                "message": "Error calling AWS.S3.upload: socket hang up",
                "name": "Error",
                "stack": "Error: Error calling AWS.S3.upload: socket hang up\n    at rethrow (/opt/xo/xo-builds/xen-orchestra-202102171611/node_modules/@sullux/aws-sdk/webpack:/lib/proxy.js:114:1)\n    at tryCatcher (/opt/xo/xo-builds/xen-orchestra-202102171611/node_modules/bluebird/js/release/util.js:16:23)\n    at Promise._settlePromiseFromHandler (/opt/xo/xo-builds/xen-orchestra-202102171611/node_modules/bluebird/js/release/promise.js:547:31)\n    at Promise._settlePromise (/opt/xo/xo-builds/xen-orchestra-202102171611/node_modules/bluebird/js/release/promise.js:604:18)\n    at Promise._settlePromise0 (/opt/xo/xo-builds/xen-orchestra-202102171611/node_modules/bluebird/js/release/promise.js:649:10)\n    at Promise._settlePromises (/opt/xo/xo-builds/xen-orchestra-202102171611/node_modules/bluebird/js/release/promise.js:725:18)\n    at _drainQueueStep (/opt/xo/xo-builds/xen-orchestra-202102171611/node_modules/bluebird/js/release/async.js:93:12)\n    at _drainQueue (/opt/xo/xo-builds/xen-orchestra-202102171611/node_modules/bluebird/js/release/async.js:86:9)\n    at Async._drainQueues (/opt/xo/xo-builds/xen-orchestra-202102171611/node_modules/bluebird/js/release/async.js:102:5)\n    at Immediate.Async.drainQueues [as _onImmediate] (/opt/xo/xo-builds/xen-orchestra-202102171611/node_modules/bluebird/js/release/async.js:15:14)\n    at processImmediate (internal/timers.js:461:21)"
              }

This is not occurring for all the VMs being uploaded, usually only for one out of the three. The tasks then stays open and runs until the timeout after 3 hours, despite normally taking about 30 minutes for this particular batch.

After 3 successful runs, this has now occurred each time on the following 3 runs. I am going to clear out the target completely and see if that makes any difference. (Note that I am using BackBlaze B2 not AWS.). Let me know if you want me to send you the full log or an extract of SMlog or anything else.

To @DustinB's point above, I have tried one restore and it came up fine, but please don't consider this a full and comprehensive test.