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

@zevgeny @olivierlambert For anyone that comes across this under a different guise - we found exactly the same issue and couldn't work out why some VMs were migrating just fine and others were not.

It turned out that we are running a Continuous Replication task which means that there is a UUID conflict when moving the relevant VM across.

So we have Primary Host A & Secondary Host B. The VM is running on the Primary, and we use CR to keep a copy on the Secondary. However, when we want to upgrade the Primary without causing downtime on the VM, we attempt to migrate VM to the Secondary but it fails, as we already have the CR entity on that host.

I can see why this occurs - we are trying to create two versions of the same VM on the same host, however I'd have thought that the Use Case was fairly common. Primary Server running, replicates to a Secondary Server, but wants to move running VM to avoid downtime without having to delete the replicas in case there are any issues. With a copied VM the UUID conflict does not occur, but with the migrate it does.

(In our case, on each host we have a large SATA array for backups that we replicate to, with live VMs running off the SSD array. Hence there is still value in keeping the replica - it protects against disk failure or corruption despite being on the same host for a short period whilst we upgrade the Primary).

Discussion - should one be permitted to update the UUID for replicas (perhaps under advanced settings in Backups?) to avoid these conflicts - or would it cause more widespread issues? Or is our Use Case unique ?

Thanks!

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)"
}