@nraynaud Bizarre isn't it; I'm so very grateful for your efforts.

Some more news - it seems that one big challenge is around concurrency - things improve dramatically if concurrency is set to 1. As soon as something else is running in parallel, we run into the socket failures. I'm expanding things to try your change on another box to see if the outcomes are different - but in summary what I'm seeing so far:

• Concurrency = 1 - works fine first time, fails occasionally (20% of the time?) thereafter
• Concurrency > 1 - almost impossible to get it to run, but sometimes one or two VMs backup ok but not enough to be predictable and never the entire group
• Anything fails - impossible to get a clean run again until the S3 target has been cleaned entirely

So it appears that somewhere there perhaps is a lock occurring when more than one stream is running, and additionally there's some kind of conflict when things have terminated prematurely and the target is therefore not in its expected state on the next run.

Always

@florent Can't wait!

Ok, spent weekend having backups running continuously across a number of boxes.

Good news - the fix seems to have solved things, providing one only ever uses concurrency “1” and there are no conflicting or overlapping backups.

Restores are working fine for me too.

In short @nraynaud - it’s a substantial improvement and for me makes this now usable. A huge thank you.

@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.

I'll try a fresh install over the next couple of days and see if it reoccurs. Looking at the other boxes, I have the same error on one of the other hosts, but it's not across all of them despite identical installs and hardware.

Thanks for your efforts and help, shame there wasn't an easy answer but let's see if it reoccurs after a completely fresh install.

@stormi I confess we're now encountering the same error message on nearly all our backups, including CR to a local host. Started from fresh install and cleaned SRs; to avoid memory being the culprit we have upped the memory for Dom0 to 16gb (128gb machine) and XO is running with 16gb of mem of which 12gb is allocated to node.

We've got the same problem occurring across all our hosts. Over 90% of backups error out with the VDI_IO_ERROR, however (weirdly) looking at the target end, I'd say that 75% of the backups 'seem' to complete successfully. Need to restore a couple to find out for sure but confess I've been concentrating on finding out what triggers the error rather than whether it is misleading.

I've gone through the logs in detail and unfortunately nothing jumps out, I'm going to take time to extract the relevant sections from them all to see if you can see something that I can't, but apart from lots of memory messages from squeezed there aren't any obvious errors.

Bizarrely SMlog is pretty clean - it's almost like it receives a termination signal from somewhere rather than erroring out of its own accord - for example tapdisk shuts down with "Closing after 0 errors" and no further explanation. I have found some talk that tapdisk can trigger a target reset after excessive i/o activity but I've not managed to prove that yet.

I'll keep digging into things ; in short it's not something only experienced by @fachex but I haven't yet recreated it in XOA - it's on my todo list.

(If you want me to download all the logs and send them across directly, or to do anything under the covers of XOA, please do let me know. I'm dipping into this when I get time so its not a continuous effort I'm afraid.)

Update to my earlier post - We found the connection timeout issue was solved by allocating more memory to XO. Even though above I said that the memory didn't appear to be a problem, it turned out that Debian was swapping out so as to keep a chunk of free memory available, so we mistakenly assumed that not using all the memory meant we had sufficient. However being memory restricted combined with a slow disk meant that the swap was growing faster than it was being processed.

Substantially increasing the XO VM memory (4->16gb) seems to have solved the timeout issues (so yes, root cause was user error), and we're now finding that the S3 api to B2 (a lot cheaper than Amazon) is working really well for us.

Well done to the XO dev team - the S3 api has completely changed how we use backups and freed up a lot infrastructure that we previously had had to dedicate to this; thank you

For anyone else who comes across the same issue, we had this occur with XCP-ng 8.2 , XO-server 5.71.2 which we isolated to using Zstd compression. It was solved by reducing concurrency and assigning a couple of extra vCPUs.

In response to @olivierlambert's point above - it is 100% reproducible if you have an under-resourced XO and fast target remote so the bottleneck becomes the CPU rather than iowait or memory acting as a throttle, but in our instance only for VMs of a reasonable size (>50gb) containing complex databases with lots of incompressible data.

@florent Can't wait!

As an aside, using the same build I am also getting problems when running CR over a slower WAN, with the following error. Just mentioning it here in case it's related.

"message": "VDI_IO_ERROR(Device I/O errors)",
            "name": "XapiError",
            "stack": "XapiError: VDI_IO_ERROR(Device I/O errors)\n    at Function.wrap (/opt/xo/xo-builds/xen-orchestra-202105081131/packages/xen-api/dist/_XapiError.js:26:12)\n    at _default (/opt/xo/xo-builds/xen-orchestra-202105081131/packages/xen-api/dist/_getTaskResult.js:24:38)\n    at Xapi._addRecordToCache (/opt/xo/xo-builds/xen-orchestra-202105081131/packages/xen-api/dist/index.js:761:51)\n    at /opt/xo/xo-builds/xen-orchestra-202105081131/packages/xen-api/dist/index.js:789:14\n    at Array.forEach (<anonymous>)\n    at Xapi._processEvents (/opt/xo/xo-builds/xen-orchestra-202105081131/packages/xen-api/dist/index.js:774:12)\n    at Xapi._watchEvents (/opt/xo/xo-builds/xen-orchestra-202105081131/packages/xen-api/dist/index.js:931:14)\n    at runMicrotasks (<anonymous>)\n    at processTicksAndRejections (internal/process/task_queues.js:93:5)"
          }
        }
      ],
      "end": 1620864312824,
      "result": {
        "message": "all targets have failed, step: writer.transfer()",
        "name": "Error",
        "stack": "Error: all targets have failed, step: writer.transfer()\n    at VmBackup._callWriters (/opt/xo/xo-builds/xen-orchestra-202105081131/@xen-orchestra/backups/_VmBackup.js:118:13)\n    at runMicrotasks (<anonymous>)\n    at processTicksAndRejections (internal/process/task_queues.js:93:5)\n    at async VmBackup._copyDelta (/opt/xo/xo-builds/xen-orchestra-202105081131/@xen-orchestra/backups/_VmBackup.js:190:5)\n    at async VmBackup.run (/opt/xo/xo-builds/xen-orchestra-202105081131/@xen-orchestra/backups/_VmBackup.js:371:9)"

CR to a local machine is working fine, the remote one is failing every iteration.

New S3 function (albeit using Backblaze) seems to be working really well for small backups; I'm now seeing almost 100% success.

However larger backups are consistently failing with

"message": "Error calling AWS.S3.upload: aborted",
            "name": "Error",
            "stack": "Error: Error calling AWS.S3.upload: aborted\n    at rethrow (/opt/xo/xo-builds/xen-orchestra-202105081131/node_modules/@sullux/aws-sdk/index.js:254:24)\n    at runMicrotasks (<anonymous>)\n    at processTicksAndRejections (internal/process/task_queues.js:93:5)\n    at async S3Handler._outputStream (/opt/xo/xo-builds/xen-orchestra-202105081131/@xen-orchestra/fs/dist/s3.js:100:5)\n    at async S3Handler.outputStream (/opt/xo/xo-builds/xen-orchestra-202105081131/@xen-orchestra/fs/dist/abstract.js:250:5)\n    at async RemoteAdapter.outputStream (/opt/xo/xo-builds/xen-orchestra-202105081131/@xen-orchestra/backups/RemoteAdapter.js:509:5)\n    at async /opt/xo/xo-builds/xen-orchestra-202105081131/@xen-orchestra/backups/writers/FullBackupWriter.js:69:7"

Running with xo-server 5.79.3 , xo-web 5.81.0

I'm having the same issue across different buckets in B2 and from different servers.

Any ideas?

@nraynaud Getting the "not implemented" error on all branches at the moment - is there a functioning, albeit not perfect branch that we can run with as a temporary measure? Thanks chap

@nraynaud Bit of a hiccup I'm afraid ; errors out with "Not Implemented":

{
  "data": {
    "mode": "full",
    "reportWhen": "failure"
  },
  "id": "1615570162008",
  "jobId": "b947a31c-35f7-45d9-af88-628ec027c71e",
  "jobName": "B2",
  "message": "backup",
  "scheduleId": "8481e1b8-3d22-4502-abb7-9f0413aca0a3",
  "start": 1615570162008,
  "status": "pending",
  "infos": [
    {
      "data": {
        "vms": [
          "25a4e2a6-b116-7cee-b94b-f3553fe001f2",
          "24103ce1-e47b-fe12-4029-d643e0382f08",
          "60ac886d-8adf-9e21-4baa-b14e0fc1b2bb"
        ]
      },
      "message": "vms"
    }
  ],
  "tasks": [
    {
      "data": {
        "type": "VM",
        "id": "25a4e2a6-b116-7cee-b94b-f3553fe001f2"
      },
      "id": "1615570162050",
      "message": "backup VM",
      "start": 1615570162050,
      "status": "pending",
      "tasks": [
        {
          "id": "1615570162064",
          "message": "snapshot",
          "start": 1615570162064,
          "status": "success",
          "end": 1615570163265,
          "result": "294d65fc-ddc7-b8ad-68b8-d14e36b6838e"
        },
        {
          "data": {
            "id": "df07dd6b-753e-40f2-89be-75404bac2c1e",
            "type": "remote",
            "isFull": true
          },
          "id": "1615570163286",
          "message": "export",
          "start": 1615570163286,
          "status": "failure",
          "tasks": [
            {
              "id": "1615570164234",
              "message": "transfer",
              "start": 1615570164234,
              "status": "failure",
              "end": 1615570164257,
              "result": {
                "message": "Not implemented",
                "name": "Error",
                "stack": "Error: Not implemented\n    at S3Handler._createWriteStream (/opt/xo/xo-builds/xen-orchestra-202103121606/@xen-orchestra/fs/src/abstract.js:428:11)\n    at S3Handler._createOutputStream (/opt/xo/xo-builds/xen-orchestra-202103121606/@xen-orchestra/fs/src/abstract.js:412:25)\n    at S3Handler.createOutputStream (/opt/xo/xo-builds/xen-orchestra-202103121606/@xen-orchestra/fs/src/abstract.js:129:12)\n    at RemoteAdapter.outputStream (/opt/xo/xo-builds/xen-orchestra-202103121606/@xen-orchestra/backups/RemoteAdapter.js:513:34)\n    at /opt/xo/xo-builds/xen-orchestra-202103121606/@xen-orchestra/backups/_FullBackupWriter.js:70:7\n    at FullBackupWriter.run (/opt/xo/xo-builds/xen-orchestra-202103121606/@xen-orchestra/backups/_FullBackupWriter.js:69:5)\n    at Array.<anonymous> (/opt/xo/xo-builds/xen-orchestra-202103121606/@xen-orchestra/backups/_VmBackup.js:209:9)"
              }
            }
          ],
          "end": 1615570164258,
          "result": {
            "message": "Not implemented",
            "name": "Error",
            "stack": "Error: Not implemented\n    at S3Handler._createWriteStream (/opt/xo/xo-builds/xen-orchestra-202103121606/@xen-orchestra/fs/src/abstract.js:428:11)\n    at S3Handler._createOutputStream (/opt/xo/xo-builds/xen-orchestra-202103121606/@xen-orchestra/fs/src/abstract.js:412:25)\n    at S3Handler.createOutputStream (/opt/xo/xo-builds/xen-orchestra-202103121606/@xen-orchestra/fs/src/abstract.js:129:12)\n    at RemoteAdapter.outputStream (/opt/xo/xo-builds/xen-orchestra-202103121606/@xen-orchestra/backups/RemoteAdapter.js:513:34)\n    at /opt/xo/xo-builds/xen-orchestra-202103121606/@xen-orchestra/backups/_FullBackupWriter.js:70:7\n    at FullBackupWriter.run (/opt/xo/xo-builds/xen-orchestra-202103121606/@xen-orchestra/backups/_FullBackupWriter.js:69:5)\n    at Array.<anonymous> (/opt/xo/xo-builds/xen-orchestra-202103121606/@xen-orchestra/backups/_VmBackup.js:209:9)"
          }
        }
      ]
    }
  ]
}

I'll try over the weekend with a fresh install. Backing up to Backblaze B2 rather than S3 - likely to be the issue?

@olivierlambert Ahhh, ok. Was focusing on XO; that's pointed me in the right direction. Thanks...and have a great weekend!

@nraynaud Building XO now; will run a few backups overnight.

Anything in particular you'd like me to look for / test ?

Having repeated errors migrating VMs off secondary server back to the primary that they originated from. Same error message for all 17 VMs - all linux unlike the Win machines described in other similar posts.

Any thoughts?

vm.migrate
{
  "vm": "761e6088-2c1c-2113-6f39-214cde1026e1",
  "mapVifsNetworks": {
    "60bcd3b6-4800-631e-7e74-8af907ff8a25": "11fb32b0-ac18-cc90-3b01-d8ec76471db2"
  },
  "migrationNetwork": "1d23ef9c-7d04-bbe9-a6a6-505e3b4dd1f5",
  "sr": "31735171-91da-832f-a335-060227e19339",
  "targetHost": "8b7ead55-4a9f-46e5-99f7-da1ba170e3bd"
}
{
  "code": 21,
  "data": {
    "objectId": "761e6088-2c1c-2113-6f39-214cde1026e1",
    "code": "INTERNAL_ERROR"
  },
  "message": "operation failed",
  "name": "XoError",
  "stack": "XoError: operation failed
    at factory (/home/node/xen-orchestra/packages/xo-common/src/api-errors.js:21:32)
    at /home/node/xen-orchestra/packages/xo-server/src/api/vm.js:487:15
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (internal/process/task_queues.js:93:5)
    at runNextTicks (internal/process/task_queues.js:62:3)
    at processImmediate (internal/timers.js:431:9)
    at Object.migrate (/home/node/xen-orchestra/packages/xo-server/src/api/vm.js:474:3)
    at Api.callApiMethod (/home/node/xen-orchestra/packages/xo-server/src/xo-mixins/api.js:304:20)"
}

xo-web 5.77.0
xo-server 5.74.1
Latest XCP-ng fully patched.

Thanks for any thoughts!

@danp Sorry, since it seems to be a design item rather than a bug I didn't think to put the logs in. Here you go:

vm.migrate
{
  "vm": "24103ce1-e47b-fe12-4029-d643e0382f08",
  "mapVifsNetworks": {
    "7457d175-8d01-613e-7b47-fb1714693074": "b62c7a9a-222a-e8e9-754e-982839e00d0e"
  },
  "migrationNetwork": "ef24440c-fda5-d88b-ce4a-fd12b7ad1d4d",
  "sr": "cf2dbaa3-21f3-903b-0fd1-fbe68539f897",
  "targetHost": "98da99c3-4ec2-4db8-ab1b-a1cb6ffd329a"
}
{
  "code": 21,
  "data": {
    "objectId": "24103ce1-e47b-fe12-4029-d643e0382f08",
    "code": "DUPLICATE_VM"
  },
  "message": "operation failed",
  "name": "XoError",
  "stack": "XoError: operation failed
    at factory (/opt/xo/xo-builds/xen-orchestra-202102171611/packages/xo-common/src/api-errors.js:21:32)
    at /opt/xo/xo-builds/xen-orchestra-202102171611/packages/xo-server/src/api/vm.js:487:15
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (internal/process/task_queues.js:97:5)
    at runNextTicks (internal/process/task_queues.js:66:3)
    at processImmediate (internal/timers.js:434:9)
    at Object.migrate (/opt/xo/xo-builds/xen-orchestra-202102171611/packages/xo-server/src/api/vm.js:474:3)
    at Api.callApiMethod (/opt/xo/xo-builds/xen-orchestra-202102171611/packages/xo-server/src/xo-mixins/api.js:304:20)"
}