Backup fails but works (Expected values to be strictly equal)
-
@olivierlambert Another backup issue....
Delta backups to S3 have been working. Now two VM backups have failing with errors. The delta backup shows up in the restore list as an option to restore. If i run a delta backup again it still fails with an error.I tried a restore verify and it says success. If I force a full backup it seems to have the same backup error.
If I delete the S3 backup for the VM and the snapshots then it runs a full backup and is happy again and additional delta backups work.
I'm running XO Source (commit d847f).
{ "data": { "mode": "delta", "reportWhen": "failure" }, "id": "1657830236073", "jobId": "f9405e51-da48-4eb1-980d-99da34359b3c", "jobName": "wasabi-Backup", "message": "backup", "scheduleId": "4b919ebd-37cf-4048-ab9f-745772b4a97d", "start": 1657830236073, "status": "failure", "infos": [ { "data": { "vms": [ "450015b0-e878-5067-e8b6-8d0513a750f6" ] }, "message": "vms" } ], "tasks": [ { "data": { "type": "VM", "id": "450015b0-e878-5067-e8b6-8d0513a750f6" }, "id": "1657830236871:0", "message": "backup VM", "start": 1657830236871, "status": "failure", "tasks": [ { "id": "1657830238205", "message": "clean-vm", "start": 1657830238205, "status": "failure", "tasks": [ { "id": "1657830242897", "message": "merge", "start": 1657830242897, "status": "failure", "end": 1657830243321, "result": { "generatedMessage": true, "code": "ERR_ASSERTION", "actual": "00000000-0000-0000-0000-000000000000", "expected": "316d0f45-ccf5-4bac-918b-89951a6eac07", "operator": "strictEqual", "message": "Expected values to be strictly equal:\n+ actual - expected\n\n+ '00000000-0000-0000-0000-000000000000'\n- '316d0f45-ccf5-4bac-918b-89951a6eac07'", "name": "AssertionError", "stack": "AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:\n+ actual - expected\n\n+ '00000000-0000-0000-0000-000000000000'\n- '316d0f45-ccf5-4bac-918b-89951a6eac07'\n at Function.<anonymous> (/opt/xo/xo-builds/xen-orchestra-202207111050/packages/vhd-lib/merge.js:123:14)\n at AsyncGenerator.next (<anonymous>)\n at wrapCall (/opt/xo/xo-builds/xen-orchestra-202207111050/node_modules/promise-toolbox/wrapCall.js:7:23)\n at loop (/opt/xo/xo-builds/xen-orchestra-202207111050/node_modules/promise-toolbox/Disposable.js:116:25)\n at onEvalDisposable (/opt/xo/xo-builds/xen-orchestra-202207111050/node_modules/promise-toolbox/Disposable.js:112:42)\n at runMicrotasks (<anonymous>)\n at processTicksAndRejections (node:internal/process/task_queues:96:5)" } } ], "end": 1657830243321, "result": { "generatedMessage": true, "code": "ERR_ASSERTION", "actual": "00000000-0000-0000-0000-000000000000", "expected": "316d0f45-ccf5-4bac-918b-89951a6eac07", "operator": "strictEqual", "message": "Expected values to be strictly equal:\n+ actual - expected\n\n+ '00000000-0000-0000-0000-000000000000'\n- '316d0f45-ccf5-4bac-918b-89951a6eac07'", "name": "AssertionError", "stack": "AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:\n+ actual - expected\n\n+ '00000000-0000-0000-0000-000000000000'\n- '316d0f45-ccf5-4bac-918b-89951a6eac07'\n at Function.<anonymous> (/opt/xo/xo-builds/xen-orchestra-202207111050/packages/vhd-lib/merge.js:123:14)\n at AsyncGenerator.next (<anonymous>)\n at wrapCall (/opt/xo/xo-builds/xen-orchestra-202207111050/node_modules/promise-toolbox/wrapCall.js:7:23)\n at loop (/opt/xo/xo-builds/xen-orchestra-202207111050/node_modules/promise-toolbox/Disposable.js:116:25)\n at onEvalDisposable (/opt/xo/xo-builds/xen-orchestra-202207111050/node_modules/promise-toolbox/Disposable.js:112:42)\n at runMicrotasks (<anonymous>)\n at processTicksAndRejections (node:internal/process/task_queues:96:5)" } }, { "id": "1657830248129", "message": "snapshot", "start": 1657830248129, "status": "success", "end": 1657830250613, "result": "93d1e2e8-65f0-eea0-31de-994104d1b70c" }, { "data": { "id": "db9ad0a8-bce6-4a2b-b9fd-5c4cecf059c4", "isFull": false, "type": "remote" }, "id": "1657830250613:0", "message": "export", "start": 1657830250613, "status": "failure", "tasks": [ { "id": "1657830250935", "message": "transfer", "start": 1657830250935, "status": "success", "end": 1657830262588, "result": { "size": 279022592 } }, { "id": "1657830263170", "message": "clean-vm", "start": 1657830263170, "status": "failure", "tasks": [ { "id": "1657830268058", "message": "merge", "start": 1657830268058, "status": "failure", "end": 1657830268549, "result": { "generatedMessage": true, "code": "ERR_ASSERTION", "actual": "00000000-0000-0000-0000-000000000000", "expected": "316d0f45-ccf5-4bac-918b-89951a6eac07", "operator": "strictEqual", "message": "Expected values to be strictly equal:\n+ actual - expected\n\n+ '00000000-0000-0000-0000-000000000000'\n- '316d0f45-ccf5-4bac-918b-89951a6eac07'", "name": "AssertionError", "stack": "AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:\n+ actual - expected\n\n+ '00000000-0000-0000-0000-000000000000'\n- '316d0f45-ccf5-4bac-918b-89951a6eac07'\n at Function.<anonymous> (/opt/xo/xo-builds/xen-orchestra-202207111050/packages/vhd-lib/merge.js:123:14)\n at AsyncGenerator.next (<anonymous>)\n at wrapCall (/opt/xo/xo-builds/xen-orchestra-202207111050/node_modules/promise-toolbox/wrapCall.js:7:23)\n at loop (/opt/xo/xo-builds/xen-orchestra-202207111050/node_modules/promise-toolbox/Disposable.js:116:25)\n at onEvalDisposable (/opt/xo/xo-builds/xen-orchestra-202207111050/node_modules/promise-toolbox/Disposable.js:112:42)\n at runMicrotasks (<anonymous>)\n at processTicksAndRejections (node:internal/process/task_queues:96:5)" } } ], "end": 1657830268549, "result": { "generatedMessage": true, "code": "ERR_ASSERTION", "actual": "00000000-0000-0000-0000-000000000000", "expected": "316d0f45-ccf5-4bac-918b-89951a6eac07", "operator": "strictEqual", "message": "Expected values to be strictly equal:\n+ actual - expected\n\n+ '00000000-0000-0000-0000-000000000000'\n- '316d0f45-ccf5-4bac-918b-89951a6eac07'", "name": "AssertionError", "stack": "AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:\n+ actual - expected\n\n+ '00000000-0000-0000-0000-000000000000'\n- '316d0f45-ccf5-4bac-918b-89951a6eac07'\n at Function.<anonymous> (/opt/xo/xo-builds/xen-orchestra-202207111050/packages/vhd-lib/merge.js:123:14)\n at AsyncGenerator.next (<anonymous>)\n at wrapCall (/opt/xo/xo-builds/xen-orchestra-202207111050/node_modules/promise-toolbox/wrapCall.js:7:23)\n at loop (/opt/xo/xo-builds/xen-orchestra-202207111050/node_modules/promise-toolbox/Disposable.js:116:25)\n at onEvalDisposable (/opt/xo/xo-builds/xen-orchestra-202207111050/node_modules/promise-toolbox/Disposable.js:112:42)\n at runMicrotasks (<anonymous>)\n at processTicksAndRejections (node:internal/process/task_queues:96:5)" } } ], "end": 1657830268599 } ], "end": 1657830268599 } ], "end": 1657830268599 } -
@julien-f Another one...
{ "data": { "mode": "delta", "reportWhen": "failure" }, "id": "1658666407109", "jobId": "f9405e51-da48-4eb1-980d-99da34359b3c", "jobName": "wasabi-Backup", "message": "backup", "scheduleId": "4b919ebd-37cf-4048-ab9f-745772b4a97d", "start": 1658666407109, "status": "failure", "infos": [ { "data": { "vms": [ "ce202f0c-b270-d319-89ea-1cf103c51f45" ] }, "message": "vms" } ], "tasks": [ { "data": { "type": "VM", "id": "ce202f0c-b270-d319-89ea-1cf103c51f45" }, "id": "1658666407929", "message": "backup VM", "start": 1658666407929, "status": "failure", "tasks": [ { "id": "1658666409284", "message": "clean-vm", "start": 1658666409284, "status": "failure", "tasks": [ { "id": "1658666415123", "message": "merge", "start": 1658666415123, "status": "failure", "end": 1658666415954, "result": { "generatedMessage": true, "code": "ERR_ASSERTION", "actual": "00000000-0000-0000-0000-000000000000", "expected": "c4f148fe-0077-492b-8c51-392d05a44663", "operator": "strictEqual", "message": "Expected values to be strictly equal:\n+ actual - expected\n\n+ '00000000-0000-0000-0000-000000000000'\n- 'c4f148fe-0077-492b-8c51-392d05a44663'", "name": "AssertionError", "stack": "AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:\n+ actual - expected\n\n+ '00000000-0000-0000-0000-000000000000'\n- 'c4f148fe-0077-492b-8c51-392d05a44663'\n at Function.<anonymous> (/opt/xo/xo-builds/xen-orchestra-202207212212/packages/vhd-lib/merge.js:123:14)\n at AsyncGenerator.next (<anonymous>)\n at wrapCall (/opt/xo/xo-builds/xen-orchestra-202207212212/node_modules/promise-toolbox/wrapCall.js:7:23)\n at loop (/opt/xo/xo-builds/xen-orchestra-202207212212/node_modules/promise-toolbox/Disposable.js:116:25)\n at onEvalDisposable (/opt/xo/xo-builds/xen-orchestra-202207212212/node_modules/promise-toolbox/Disposable.js:112:42)\n at runMicrotasks (<anonymous>)\n at processTicksAndRejections (node:internal/process/task_queues:96:5)" } } ], "end": 1658666415954, "result": { "generatedMessage": true, "code": "ERR_ASSERTION", "actual": "00000000-0000-0000-0000-000000000000", "expected": "c4f148fe-0077-492b-8c51-392d05a44663", "operator": "strictEqual", "message": "Expected values to be strictly equal:\n+ actual - expected\n\n+ '00000000-0000-0000-0000-000000000000'\n- 'c4f148fe-0077-492b-8c51-392d05a44663'", "name": "AssertionError", "stack": "AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:\n+ actual - expected\n\n+ '00000000-0000-0000-0000-000000000000'\n- 'c4f148fe-0077-492b-8c51-392d05a44663'\n at Function.<anonymous> (/opt/xo/xo-builds/xen-orchestra-202207212212/packages/vhd-lib/merge.js:123:14)\n at AsyncGenerator.next (<anonymous>)\n at wrapCall (/opt/xo/xo-builds/xen-orchestra-202207212212/node_modules/promise-toolbox/wrapCall.js:7:23)\n at loop (/opt/xo/xo-builds/xen-orchestra-202207212212/node_modules/promise-toolbox/Disposable.js:116:25)\n at onEvalDisposable (/opt/xo/xo-builds/xen-orchestra-202207212212/node_modules/promise-toolbox/Disposable.js:112:42)\n at runMicrotasks (<anonymous>)\n at processTicksAndRejections (node:internal/process/task_queues:96:5)" } }, { "id": "1658666421228", "message": "snapshot", "start": 1658666421228, "status": "success", "end": 1658666423609, "result": "d6d6fc6d-e182-772a-850e-499ad0d003ae" }, { "data": { "id": "db9ad0a8-bce6-4a2b-b9fd-5c4cecf059c4", "isFull": false, "type": "remote" }, "id": "1658666423610", "message": "export", "start": 1658666423610, "status": "failure", "tasks": [ { "id": "1658666423856", "message": "transfer", "start": 1658666423856, "status": "success", "end": 1658666670302, "result": { "size": 4736630272 } }, { "id": "1658666670925", "message": "clean-vm", "start": 1658666670925, "status": "failure", "tasks": [ { "id": "1658666676052", "message": "merge", "start": 1658666676052, "status": "failure", "end": 1658666676576, "result": { "generatedMessage": true, "code": "ERR_ASSERTION", "actual": "00000000-0000-0000-0000-000000000000", "expected": "c4f148fe-0077-492b-8c51-392d05a44663", "operator": "strictEqual", "message": "Expected values to be strictly equal:\n+ actual - expected\n\n+ '00000000-0000-0000-0000-000000000000'\n- 'c4f148fe-0077-492b-8c51-392d05a44663'", "name": "AssertionError", "stack": "AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:\n+ actual - expected\n\n+ '00000000-0000-0000-0000-000000000000'\n- 'c4f148fe-0077-492b-8c51-392d05a44663'\n at Function.<anonymous> (/opt/xo/xo-builds/xen-orchestra-202207212212/packages/vhd-lib/merge.js:123:14)\n at AsyncGenerator.next (<anonymous>)\n at wrapCall (/opt/xo/xo-builds/xen-orchestra-202207212212/node_modules/promise-toolbox/wrapCall.js:7:23)\n at loop (/opt/xo/xo-builds/xen-orchestra-202207212212/node_modules/promise-toolbox/Disposable.js:116:25)\n at onEvalDisposable (/opt/xo/xo-builds/xen-orchestra-202207212212/node_modules/promise-toolbox/Disposable.js:112:42)\n at runMicrotasks (<anonymous>)\n at processTicksAndRejections (node:internal/process/task_queues:96:5)" } } ], "end": 1658666676577, "result": { "generatedMessage": true, "code": "ERR_ASSERTION", "actual": "00000000-0000-0000-0000-000000000000", "expected": "c4f148fe-0077-492b-8c51-392d05a44663", "operator": "strictEqual", "message": "Expected values to be strictly equal:\n+ actual - expected\n\n+ '00000000-0000-0000-0000-000000000000'\n- 'c4f148fe-0077-492b-8c51-392d05a44663'", "name": "AssertionError", "stack": "AssertionError [ERR_ASSERTION]: Expected values to be strictly equal:\n+ actual - expected\n\n+ '00000000-0000-0000-0000-000000000000'\n- 'c4f148fe-0077-492b-8c51-392d05a44663'\n at Function.<anonymous> (/opt/xo/xo-builds/xen-orchestra-202207212212/packages/vhd-lib/merge.js:123:14)\n at AsyncGenerator.next (<anonymous>)\n at wrapCall (/opt/xo/xo-builds/xen-orchestra-202207212212/node_modules/promise-toolbox/wrapCall.js:7:23)\n at loop (/opt/xo/xo-builds/xen-orchestra-202207212212/node_modules/promise-toolbox/Disposable.js:116:25)\n at onEvalDisposable (/opt/xo/xo-builds/xen-orchestra-202207212212/node_modules/promise-toolbox/Disposable.js:112:42)\n at runMicrotasks (<anonymous>)\n at processTicksAndRejections (node:internal/process/task_queues:96:5)" } } ], "end": 1658666676625 } ], "end": 1658666676626 } ], "end": 1658666676626 } -
Pinging @florent
-
Have you got some logs like 'uuid is duplicated' in your jounalctl logs ? if yes, what is the following message ? ( should be either 'should delete xxx', or 'same ids but different content'
Regards
-
@florent No, but hours (days?) later XO still seems to be trying to work on the S3 backup for that VM.
Here is a few lines of data, but it keeps going...
Jul 25 08:19:03 xo1 xo-server[250695]: 2022-07-25T12:19:03.998Z xo:backups:MixinBackupWriter INFO merging children in progress { Jul 25 08:19:03 xo1 xo-server[250695]: children: [ Jul 25 08:19:03 xo1 xo-server[250695]: '/xo-vm-backups/ce202f0c-b270-d319-89ea-1cf103c51f45/vdis/f9405e51-da48-4eb1-980d-99da34359b3c/65ebc13f-2f2e-4765-bfda-2f300c8bd4a3/20220710T055447Z.alias.vhd' Jul 25 08:19:03 xo1 xo-server[250695]: ], Jul 25 08:19:03 xo1 xo-server[250695]: parent: '/xo-vm-backups/ce202f0c-b270-d319-89ea-1cf103c51f45/vdis/f9405e51-da48-4eb1-980d-99da34359b3c/65ebc13f-2f2e-4765-bfda-2f300c8bd4a3/20220709T060314Z.alias.vhd', Jul 25 08:19:03 xo1 xo-server[250695]: doneCount: 46, Jul 25 08:19:03 xo1 xo-server[250695]: totalCount: 1422 Jul 25 08:19:03 xo1 xo-server[250695]: } Jul 25 08:19:14 xo1 xo-server[250695]: 2022-07-25T12:19:14.007Z xo:backups:MixinBackupWriter INFO merging children in progress { Jul 25 08:19:14 xo1 xo-server[250695]: children: [ Jul 25 08:19:14 xo1 xo-server[250695]: '/xo-vm-backups/ce202f0c-b270-d319-89ea-1cf103c51f45/vdis/f9405e51-da48-4eb1-980d-99da34359b3c/65ebc13f-2f2e-4765-bfda-2f300c8bd4a3/20220710T055447Z.alias.vhd' Jul 25 08:19:14 xo1 xo-server[250695]: ], Jul 25 08:19:14 xo1 xo-server[250695]: parent: '/xo-vm-backups/ce202f0c-b270-d319-89ea-1cf103c51f45/vdis/f9405e51-da48-4eb1-980d-99da34359b3c/65ebc13f-2f2e-4765-bfda-2f300c8bd4a3/20220709T060314Z.alias.vhd', Jul 25 08:19:14 xo1 xo-server[250695]: doneCount: 46, Jul 25 08:19:14 xo1 xo-server[250695]: totalCount: 1422 Jul 25 08:19:14 xo1 xo-server[250695]: } Jul 25 08:19:24 xo1 xo-server[250695]: 2022-07-25T12:19:24.018Z xo:backups:MixinBackupWriter INFO merging children in progress { Jul 25 08:19:24 xo1 xo-server[250695]: children: [ Jul 25 08:19:24 xo1 xo-server[250695]: '/xo-vm-backups/ce202f0c-b270-d319-89ea-1cf103c51f45/vdis/f9405e51-da48-4eb1-980d-99da34359b3c/65ebc13f-2f2e-4765-bfda-2f300c8bd4a3/20220710T055447Z.alias.vhd' Jul 25 08:19:24 xo1 xo-server[250695]: ], Jul 25 08:19:24 xo1 xo-server[250695]: parent: '/xo-vm-backups/ce202f0c-b270-d319-89ea-1cf103c51f45/vdis/f9405e51-da48-4eb1-980d-99da34359b3c/65ebc13f-2f2e-4765-bfda-2f300c8bd4a3/20220709T060314Z.alias.vhd', Jul 25 08:19:24 xo1 xo-server[250695]: doneCount: 46, Jul 25 08:19:24 xo1 xo-server[250695]: totalCount: 1422 Jul 25 08:19:24 xo1 xo-server[250695]: } Jul 25 08:19:34 xo1 xo-server[250695]: 2022-07-25T12:19:34.028Z xo:backups:MixinBackupWriter INFO merging children in progress { Jul 25 08:19:34 xo1 xo-server[250695]: children: [ Jul 25 08:19:34 xo1 xo-server[250695]: '/xo-vm-backups/ce202f0c-b270-d319-89ea-1cf103c51f45/vdis/f9405e51-da48-4eb1-980d-99da34359b3c/65ebc13f-2f2e-4765-bfda-2f300c8bd4a3/20220710T055447Z.alias.vhd' Jul 25 08:19:34 xo1 xo-server[250695]: ], Jul 25 08:19:34 xo1 xo-server[250695]: parent: '/xo-vm-backups/ce202f0c-b270-d319-89ea-1cf103c51f45/vdis/f9405e51-da48-4eb1-980d-99da34359b3c/65ebc13f-2f2e-4765-bfda-2f300c8bd4a3/20220709T060314Z.alias.vhd', Jul 25 08:19:34 xo1 xo-server[250695]: doneCount: 46, Jul 25 08:19:34 xo1 xo-server[250695]: totalCount: 1422 Jul 25 08:19:34 xo1 xo-server[250695]: } Jul 25 08:19:44 xo1 xo-server[250695]: 2022-07-25T12:19:44.038Z xo:backups:MixinBackupWriter INFO merging children in progress { Jul 25 08:19:44 xo1 xo-server[250695]: children: [ Jul 25 08:19:44 xo1 xo-server[250695]: '/xo-vm-backups/ce202f0c-b270-d319-89ea-1cf103c51f45/vdis/f9405e51-da48-4eb1-980d-99da34359b3c/65ebc13f-2f2e-4765-bfda-2f300c8bd4a3/20220710T055447Z.alias.vhd' Jul 25 08:19:44 xo1 xo-server[250695]: ], Jul 25 08:19:44 xo1 xo-server[250695]: parent: '/xo-vm-backups/ce202f0c-b270-d319-89ea-1cf103c51f45/vdis/f9405e51-da48-4eb1-980d-99da34359b3c/65ebc13f-2f2e-4765-bfda-2f300c8bd4a3/20220709T060314Z.alias.vhd', Jul 25 08:19:44 xo1 xo-server[250695]: doneCount: 46, Jul 25 08:19:44 xo1 xo-server[250695]: totalCount: 1422 Jul 25 08:19:44 xo1 xo-server[250695]: } -
@Andrew it seems that the merge fails but the watcher still report progress ( which doesn't move)
Can you see if there is an error before ?
