search

vatesfr / xen-orchestra

The global orchestration solution to manage and backup XCP-ng and XenServer.
https://xen-orchestra.com
Other
750 stars 261 forks source link

[Bug] footer1 !== footer2 #3899

Closed Zuko closed 5 years ago

Zuko commented 5 years ago

Context

Expected behavior

Successful backup ;)

Current behavior

prod_xXx

    UUID: c3c1f69f-64d5-42c9-8b2b-2bfaba6ab93e
    Start time: Thursday, January 24th 2019, 12:30:12 am
    End time: Thursday, January 24th 2019, 12:32:53 am
    Duration: 3 minutes

    Snapshot ✔
        Start time: Thursday, January 24th 2019, 12:30:12 am
        End time: Thursday, January 24th 2019, 12:30:52 am
        Duration: a few seconds

    Remotes

        NAS (9988c77d-9dbc-40ee-829f-dd4970d1bbd1) 🚨
            Start time: Thursday, January 24th 2019, 12:30:54 am
            End time: Thursday, January 24th 2019, 12:32:41 am

            Duration: 2 minutes

            Error: footer1 !== footer2
            transfer 🚨
                Start time: Thursday, January 24th 2019, 12:30:54 am
                End time: Thursday, January 24th 2019, 12:32:41 am
                Duration: 2 minutes
                Error: footer1 !== footer2
julien-f commented 5 years ago

This indicates that a VHD file has been corrupted, either because the previous run was interrupted or for other reasons.

I suspect you are using legacy backups, please migrate to Backup NG which handles much better this kind of issues.

Zuko commented 5 years ago

I use "Backup NG", and next backup (from schedule) was successful.

julien-f commented 5 years ago

Ok, can you please copy paste the full error from the details modal?

Zuko commented 5 years ago

Sure, I just changed VM names.

Log ```json { "data": { "mode": "delta", "reportWhen": "failure" }, "id": "1548286200004", "jobId": "c2711a5b-3fc0-45ae-ae6f-bb24c57c0d6e", "jobName": "Delta_6h", "scheduleId": "6a7582e7-76af-477a-a104-d6a1bee2cdc7", "start": 1548286200004, "status": "failure", "infos": [ { "data": { "vms": [ "40cc98fe-adc8-da99-19d6-bec4e92dbc87", "454b99a1-2daf-e911-694b-83e8a15723ff", "12ebab59-10a5-fc7f-811f-0ffb7bf860c6", "c3c1f69f-64d5-42c9-8b2b-2bfaba6ab93e", "8c16242e-efe2-6a9a-557f-0f932a8d1820", "0c89d8fd-e1b6-3180-cf8b-8f44730d7377", "e9319a4a-d9a5-3918-c839-5cff9f5ce7f9", "d678903f-6cab-ecfe-e681-e8728ae0340b", "9d7b955d-39ac-e226-cf41-34e7152db8b2", "fd40a7e3-bb18-22a0-8c13-51bd74582f72", "badb23dd-e783-3bf8-814d-0d9823cea8e3", "a100de1c-fe36-4284-560f-e380c21fa98b" ] }, "message": "vms" } ], "tasks": [ { "data": { "type": "VM", "id": "40cc98fe-adc8-da99-19d6-bec4e92dbc87" }, "id": "1548286212868:0", "message": "Starting backup of prod_123. (c2711a5b-3fc0-45ae-ae6f-bb24c57c0d6e)", "start": 1548286212868, "status": "success", "tasks": [ { "id": "1548286212871", "message": "snapshot", "start": 1548286212871, "status": "success", "end": 1548286223307, "result": "d8c98208-74dd-f540-68cb-123b99c41920" }, { "id": "1548286223314", "message": "add metadata to snapshot", "start": 1548286223314, "status": "success", "end": 1548286223363 }, { "id": "1548286223538", "message": "waiting for uptodate snapshot record", "start": 1548286223538, "status": "success", "end": 1548286223757 }, { "id": "1548286224042", "message": "start snapshot export", "start": 1548286224042, "status": "success", "end": 1548286224042 }, { "data": { "id": "9988c77d-9dbc-40ee-829f-dd4970d1bbd1", "isFull": false, "type": "remote" }, "id": "1548286224043", "message": "export", "start": 1548286224043, "status": "success", "tasks": [ { "id": "1548286224105", "message": "transfer", "start": 1548286224105, "status": "success", "end": 1548286261916, "result": { "size": 327258624 } }, { "id": "1548286261925", "message": "merge", "start": 1548286261925, "status": "success", "end": 1548286285088, "result": { "size": 182452224 } } ], "end": 1548286285088 }, { "id": "1548286285091", "message": "set snapshot.other_config[xo:backup:exported]", "start": 1548286285091, "status": "success", "end": 1548286285243 } ], "end": 1548286327301 }, { "data": { "type": "VM", "id": "454b99a1-2daf-e911-694b-83e8a15723ff" }, "id": "1548286212871:0", "message": "Starting backup of prod_234. (c2711a5b-3fc0-45ae-ae6f-bb24c57c0d6e)", "start": 1548286212871, "status": "success", "tasks": [ { "id": "1548286212872", "message": "snapshot", "start": 1548286212872, "status": "success", "end": 1548286285382, "result": "de47e840-a1f7-89a0-262f-10e81cca3330" }, { "id": "1548286285390", "message": "add metadata to snapshot", "start": 1548286285390, "status": "success", "end": 1548286286112 }, { "id": "1548286286323", "message": "waiting for uptodate snapshot record", "start": 1548286286323, "status": "success", "end": 1548286286542 }, { "id": "1548286286972", "message": "start snapshot export", "start": 1548286286972, "status": "success", "end": 1548286286972 }, { "data": { "id": "9988c77d-9dbc-40ee-829f-dd4970d1bbd1", "isFull": false, "type": "remote" }, "id": "1548286286978", "message": "export", "start": 1548286286978, "status": "success", "tasks": [ { "id": "1548286287305", "message": "transfer", "start": 1548286287305, "status": "success", "end": 1548286323854, "result": { "size": 239197696 } }, { "id": "1548286323862", "message": "merge", "start": 1548286323862, "status": "success", "end": 1548286573156, "result": { "size": 870318080 } } ], "end": 1548286573157 }, { "id": "1548286573159", "message": "set snapshot.other_config[xo:backup:exported]", "start": 1548286573159, "status": "success", "end": 1548286573184 } ], "end": 1548286574746 }, { "data": { "type": "VM", "id": "12ebab59-10a5-fc7f-811f-0ffb7bf860c6" }, "id": "1548286212872:0", "message": "Starting backup of prod_345. (c2711a5b-3fc0-45ae-ae6f-bb24c57c0d6e)", "start": 1548286212872, "status": "failure", "tasks": [ { "id": "1548286212873", "message": "snapshot", "start": 1548286212873, "status": "success", "end": 1548286233287, "result": "3d01f5ac-5d09-2f31-ead7-4a3485a8838e" }, { "id": "1548286233291", "message": "add metadata to snapshot", "start": 1548286233291, "status": "success", "end": 1548286233335 }, { "id": "1548286233512", "message": "waiting for uptodate snapshot record", "start": 1548286233512, "status": "success", "end": 1548286233736 }, { "id": "1548286233920", "message": "start snapshot export", "start": 1548286233920, "status": "success", "end": 1548286233921 }, { "data": { "id": "9988c77d-9dbc-40ee-829f-dd4970d1bbd1", "isFull": false, "type": "remote" }, "id": "1548286233921:0", "message": "export", "start": 1548286233921, "status": "failure", "tasks": [ { "id": "1548286234001", "message": "transfer", "start": 1548286234001, "status": "failure", "end": 1548286275992, "result": { "message": "footer1 !== footer2", "stack": "AssertionError [ERR_ASSERTION]: footer1 !== footer2\n at /opt/xen-orchestra/packages/vhd-lib/src/vhd.js:167:8\n at Generator.next ()\n at asyncGeneratorStep (/opt/xen-orchestra/packages/vhd-lib/dist/vhd.js:22:103)\n at _next (/opt/xen-orchestra/packages/vhd-lib/dist/vhd.js:24:194)\n at tryCatcher (/opt/xen-orchestra/node_modules/bluebird/js/release/util.js:16:23)\n at Promise._settlePromiseFromHandler (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:512:31)\n at Promise._settlePromise (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:569:18)\n at Promise._settlePromise0 (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:614:10)\n at Promise._settlePromises (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:694:18)\n at _drainQueueStep (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:138:12)\n at _drainQueue (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:131:9)\n at Async._drainQueues (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:147:5)\n at Immediate.Async.drainQueues (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:17:14)\n at runCallback (timers.js:810:20)\n at tryOnImmediate (timers.js:768:5)\n at processImmediate [as _immediateCallback] (timers.js:745:5)", "generatedMessage": false, "name": "AssertionError [ERR_ASSERTION]", "code": "ERR_ASSERTION", "actual": false, "expected": true, "operator": "==" } } ], "end": 1548286275993, "result": { "message": "footer1 !== footer2", "stack": "AssertionError [ERR_ASSERTION]: footer1 !== footer2\n at /opt/xen-orchestra/packages/vhd-lib/src/vhd.js:167:8\n at Generator.next ()\n at asyncGeneratorStep (/opt/xen-orchestra/packages/vhd-lib/dist/vhd.js:22:103)\n at _next (/opt/xen-orchestra/packages/vhd-lib/dist/vhd.js:24:194)\n at tryCatcher (/opt/xen-orchestra/node_modules/bluebird/js/release/util.js:16:23)\n at Promise._settlePromiseFromHandler (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:512:31)\n at Promise._settlePromise (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:569:18)\n at Promise._settlePromise0 (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:614:10)\n at Promise._settlePromises (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:694:18)\n at _drainQueueStep (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:138:12)\n at _drainQueue (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:131:9)\n at Async._drainQueues (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:147:5)\n at Immediate.Async.drainQueues (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:17:14)\n at runCallback (timers.js:810:20)\n at tryOnImmediate (timers.js:768:5)\n at processImmediate [as _immediateCallback] (timers.js:745:5)", "generatedMessage": false, "name": "AssertionError [ERR_ASSERTION]", "code": "ERR_ASSERTION", "actual": false, "expected": true, "operator": "==" } }, { "id": "1548286275995", "message": "set snapshot.other_config[xo:backup:exported]", "start": 1548286275995, "status": "success", "end": 1548286276045 } ], "end": 1548286286839 }, { "data": { "type": "VM", "id": "c3c1f69f-64d5-42c9-8b2b-2bfaba6ab93e" }, "id": "1548286212873:0", "message": "Starting backup of prod_456. (c2711a5b-3fc0-45ae-ae6f-bb24c57c0d6e)", "start": 1548286212873, "status": "failure", "tasks": [ { "id": "1548286212873:1", "message": "snapshot", "start": 1548286212873, "status": "success", "end": 1548286252779, "result": "ab472127-8dd2-f197-fded-4f14134d01b6" }, { "id": "1548286252783", "message": "add metadata to snapshot", "start": 1548286252783, "status": "success", "end": 1548286252835 }, { "id": "1548286253007", "message": "waiting for uptodate snapshot record", "start": 1548286253007, "status": "success", "end": 1548286253228 }, { "id": "1548286254210", "message": "start snapshot export", "start": 1548286254210, "status": "success", "end": 1548286254210 }, { "data": { "id": "9988c77d-9dbc-40ee-829f-dd4970d1bbd1", "isFull": false, "type": "remote" }, "id": "1548286254211", "message": "export", "start": 1548286254211, "status": "failure", "tasks": [ { "id": "1548286254382", "message": "transfer", "start": 1548286254382, "status": "failure", "end": 1548286361490, "result": { "message": "footer1 !== footer2", "stack": "AssertionError [ERR_ASSERTION]: footer1 !== footer2\n at /opt/xen-orchestra/packages/vhd-lib/src/vhd.js:167:8\n at Generator.next ()\n at asyncGeneratorStep (/opt/xen-orchestra/packages/vhd-lib/dist/vhd.js:22:103)\n at _next (/opt/xen-orchestra/packages/vhd-lib/dist/vhd.js:24:194)\n at tryCatcher (/opt/xen-orchestra/node_modules/bluebird/js/release/util.js:16:23)\n at Promise._settlePromiseFromHandler (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:512:31)\n at Promise._settlePromise (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:569:18)\n at Promise._settlePromise0 (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:614:10)\n at Promise._settlePromises (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:694:18)\n at _drainQueueStep (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:138:12)\n at _drainQueue (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:131:9)\n at Async._drainQueues (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:147:5)\n at Immediate.Async.drainQueues (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:17:14)\n at runCallback (timers.js:810:20)\n at tryOnImmediate (timers.js:768:5)\n at processImmediate [as _immediateCallback] (timers.js:745:5)", "generatedMessage": false, "name": "AssertionError [ERR_ASSERTION]", "code": "ERR_ASSERTION", "actual": false, "expected": true, "operator": "==" } } ], "end": 1548286361491, "result": { "message": "footer1 !== footer2", "stack": "AssertionError [ERR_ASSERTION]: footer1 !== footer2\n at /opt/xen-orchestra/packages/vhd-lib/src/vhd.js:167:8\n at Generator.next ()\n at asyncGeneratorStep (/opt/xen-orchestra/packages/vhd-lib/dist/vhd.js:22:103)\n at _next (/opt/xen-orchestra/packages/vhd-lib/dist/vhd.js:24:194)\n at tryCatcher (/opt/xen-orchestra/node_modules/bluebird/js/release/util.js:16:23)\n at Promise._settlePromiseFromHandler (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:512:31)\n at Promise._settlePromise (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:569:18)\n at Promise._settlePromise0 (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:614:10)\n at Promise._settlePromises (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:694:18)\n at _drainQueueStep (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:138:12)\n at _drainQueue (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:131:9)\n at Async._drainQueues (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:147:5)\n at Immediate.Async.drainQueues (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:17:14)\n at runCallback (timers.js:810:20)\n at tryOnImmediate (timers.js:768:5)\n at processImmediate [as _immediateCallback] (timers.js:745:5)", "generatedMessage": false, "name": "AssertionError [ERR_ASSERTION]", "code": "ERR_ASSERTION", "actual": false, "expected": true, "operator": "==" } }, { "id": "1548286361492", "message": "set snapshot.other_config[xo:backup:exported]", "start": 1548286361492, "status": "success", "end": 1548286361516 } ], "end": 1548286373331 }, { "data": { "type": "VM", "id": "8c16242e-efe2-6a9a-557f-0f932a8d1820" }, "id": "1548286212874", "message": "Starting backup of prod_567. (c2711a5b-3fc0-45ae-ae6f-bb24c57c0d6e)", "start": 1548286212874, "status": "success", "tasks": [ { "id": "1548286212874:0", "message": "snapshot", "start": 1548286212874, "status": "success", "end": 1548286261124, "result": "c666200e-3728-5d8b-ae9a-e92e0e232184" }, { "id": "1548286261127", "message": "add metadata to snapshot", "start": 1548286261127, "status": "success", "end": 1548286261159 }, { "id": "1548286261348", "message": "waiting for uptodate snapshot record", "start": 1548286261348, "status": "success", "end": 1548286261570 }, { "id": "1548286261955", "message": "start snapshot export", "start": 1548286261955, "status": "success", "end": 1548286261955 }, { "data": { "id": "9988c77d-9dbc-40ee-829f-dd4970d1bbd1", "isFull": false, "type": "remote" }, "id": "1548286261956", "message": "export", "start": 1548286261956, "status": "success", "tasks": [ { "id": "1548286262021", "message": "transfer", "start": 1548286262021, "status": "success", "end": 1548286286114, "result": { "size": 94499840 } }, { "id": "1548286286123", "message": "merge", "start": 1548286286123, "status": "success", "end": 1548286304967, "result": { "size": 148897792 } } ], "end": 1548286304967 }, { "id": "1548286304969", "message": "set snapshot.other_config[xo:backup:exported]", "start": 1548286304969, "status": "success", "end": 1548286304987 } ], "end": 1548286306756 }, { "data": { "type": "VM", "id": "0c89d8fd-e1b6-3180-cf8b-8f44730d7377" }, "id": "1548286286839:0", "message": "Starting backup of prod_678. (c2711a5b-3fc0-45ae-ae6f-bb24c57c0d6e)", "start": 1548286286839, "status": "success", "tasks": [ { "id": "1548286286842", "message": "snapshot", "start": 1548286286842, "status": "success", "end": 1548286294848, "result": "ae623c69-b31a-7936-e8dd-4c2f84b59dc5" }, { "id": "1548286294852", "message": "add metadata to snapshot", "start": 1548286294852, "status": "success", "end": 1548286294883 }, { "id": "1548286295071", "message": "waiting for uptodate snapshot record", "start": 1548286295071, "status": "success", "end": 1548286295291 }, { "id": "1548286297614", "message": "start snapshot export", "start": 1548286297614, "status": "success", "end": 1548286297614 }, { "data": { "id": "9988c77d-9dbc-40ee-829f-dd4970d1bbd1", "isFull": false, "type": "remote" }, "id": "1548286297615", "message": "export", "start": 1548286297615, "status": "success", "tasks": [ { "id": "1548286300551", "message": "transfer", "start": 1548286300551, "status": "success", "end": 1548286361364, "result": { "size": 339844608 } }, { "id": "1548286361395", "message": "merge", "start": 1548286361395, "status": "success", "end": 1548286388923, "result": { "size": 117440512 } } ], "end": 1548286388923 }, { "id": "1548286388925", "message": "set snapshot.other_config[xo:backup:exported]", "start": 1548286388925, "status": "success", "end": 1548286388945 } ], "end": 1548286407455 }, { "data": { "type": "VM", "id": "e9319a4a-d9a5-3918-c839-5cff9f5ce7f9" }, "id": "1548286306756:0", "message": "Starting backup of prod_789. (c2711a5b-3fc0-45ae-ae6f-bb24c57c0d6e)", "start": 1548286306756, "status": "success", "tasks": [ { "id": "1548286306759", "message": "snapshot", "start": 1548286306759, "status": "success", "end": 1548286314191, "result": "aaa13c38-e91e-4e4f-7197-486c900a5fa4" }, { "id": "1548286314194", "message": "add metadata to snapshot", "start": 1548286314194, "status": "success", "end": 1548286314256 }, { "id": "1548286314422", "message": "waiting for uptodate snapshot record", "start": 1548286314422, "status": "success", "end": 1548286314645 }, { "id": "1548286323689", "message": "start snapshot export", "start": 1548286323689, "status": "success", "end": 1548286323689 }, { "data": { "id": "9988c77d-9dbc-40ee-829f-dd4970d1bbd1", "isFull": false, "type": "remote" }, "id": "1548286323690", "message": "export", "start": 1548286323690, "status": "success", "tasks": [ { "id": "1548286323808", "message": "transfer", "start": 1548286323808, "status": "success", "end": 1548286386086, "result": { "size": 333633536 } }, { "id": "1548286386097", "message": "merge", "start": 1548286386097, "status": "success", "end": 1548286518014, "result": { "size": 459276288 } } ], "end": 1548286518014 }, { "id": "1548286518017", "message": "set snapshot.other_config[xo:backup:exported]", "start": 1548286518017, "status": "success", "end": 1548286518038 } ], "end": 1548286520028 }, { "data": { "type": "VM", "id": "d678903f-6cab-ecfe-e681-e8728ae0340b" }, "id": "1548286327301:0", "message": "Starting backup of int_PAL-DNS Local #2. (c2711a5b-3fc0-45ae-ae6f-bb24c57c0d6e)", "start": 1548286327301, "status": "success", "tasks": [ { "id": "1548286327304", "message": "snapshot", "start": 1548286327304, "status": "success", "end": 1548286337587, "result": "e68207ae-b5e8-cc76-cdca-62eba761ddd2" }, { "id": "1548286337591", "message": "add metadata to snapshot", "start": 1548286337591, "status": "success", "end": 1548286337625 }, { "id": "1548286337812", "message": "waiting for uptodate snapshot record", "start": 1548286337812, "status": "success", "end": 1548286338036 }, { "id": "1548286348876", "message": "start snapshot export", "start": 1548286348876, "status": "success", "end": 1548286348876 }, { "data": { "id": "9988c77d-9dbc-40ee-829f-dd4970d1bbd1", "isFull": false, "type": "remote" }, "id": "1548286348876:1", "message": "export", "start": 1548286348876, "status": "success", "tasks": [ { "id": "1548286352671", "message": "transfer", "start": 1548286352671, "status": "success", "end": 1548286402989, "result": { "size": 356625920 } }, { "id": "1548286404186", "message": "merge", "start": 1548286404186, "status": "success", "end": 1548286454238, "result": { "size": 178257920 } } ], "end": 1548286454239 }, { "id": "1548286454240", "message": "set snapshot.other_config[xo:backup:exported]", "start": 1548286454240, "status": "success", "end": 1548286454266 } ], "end": 1548286456228 }, { "data": { "type": "VM", "id": "9d7b955d-39ac-e226-cf41-34e7152db8b2" }, "id": "1548286373332", "message": "Starting backup of prod_890. (c2711a5b-3fc0-45ae-ae6f-bb24c57c0d6e)", "start": 1548286373332, "status": "success", "tasks": [ { "id": "1548286373334", "message": "snapshot", "start": 1548286373334, "status": "success", "end": 1548286391851, "result": "4d7e79db-a307-aa9c-4f80-4fdae85b3600" }, { "id": "1548286391855", "message": "add metadata to snapshot", "start": 1548286391855, "status": "success", "end": 1548286391888 }, { "id": "1548286392074", "message": "waiting for uptodate snapshot record", "start": 1548286392074, "status": "success", "end": 1548286392293 }, { "id": "1548286393740", "message": "start snapshot export", "start": 1548286393740, "status": "success", "end": 1548286393740 }, { "data": { "id": "9988c77d-9dbc-40ee-829f-dd4970d1bbd1", "isFull": false, "type": "remote" }, "id": "1548286393741", "message": "export", "start": 1548286393741, "status": "success", "tasks": [ { "id": "1548286399184", "message": "transfer", "start": 1548286399184, "status": "success", "end": 1548286791972, "result": { "size": 4375375360 } }, { "id": "1548286791980", "message": "merge", "start": 1548286791980, "status": "success", "end": 1548287163208, "result": { "size": 5203034112 } } ], "end": 1548287163208 }, { "id": "1548287163210", "message": "set snapshot.other_config[xo:backup:exported]", "start": 1548287163210, "status": "success", "end": 1548287163235 } ], "end": 1548287176753 }, { "data": { "type": "VM", "id": "fd40a7e3-bb18-22a0-8c13-51bd74582f72" }, "id": "1548286407455:0", "message": "Starting backup of prod_901. (c2711a5b-3fc0-45ae-ae6f-bb24c57c0d6e)", "start": 1548286407455, "status": "success", "tasks": [ { "id": "1548286407457", "message": "snapshot", "start": 1548286407457, "status": "success", "end": 1548286417358, "result": "995315dd-75de-ebe1-4dbf-5646e1a659dc" }, { "id": "1548286417361", "message": "add metadata to snapshot", "start": 1548286417361, "status": "success", "end": 1548286417394 }, { "id": "1548286417581", "message": "waiting for uptodate snapshot record", "start": 1548286417581, "status": "success", "end": 1548286417800 }, { "id": "1548286422419", "message": "start snapshot export", "start": 1548286422419, "status": "success", "end": 1548286422419 }, { "data": { "id": "9988c77d-9dbc-40ee-829f-dd4970d1bbd1", "isFull": false, "type": "remote" }, "id": "1548286422420", "message": "export", "start": 1548286422420, "status": "success", "tasks": [ { "id": "1548286424441", "message": "transfer", "start": 1548286424441, "status": "success", "end": 1548286516718, "result": { "size": 337828864 } }, { "id": "1548286516758", "message": "merge", "start": 1548286516758, "status": "success", "end": 1548286606570, "result": { "size": 299892736 } } ], "end": 1548286606570 }, { "id": "1548286606573", "message": "set snapshot.other_config[xo:backup:exported]", "start": 1548286606573, "status": "success", "end": 1548286606594 } ], "end": 1548286614513 }, { "data": { "type": "VM", "id": "badb23dd-e783-3bf8-814d-0d9823cea8e3" }, "id": "1548286456228:0", "message": "Starting backup of int_PAL-DNS-Local #1. (c2711a5b-3fc0-45ae-ae6f-bb24c57c0d6e)", "start": 1548286456228, "status": "success", "tasks": [ { "id": "1548286456230", "message": "snapshot", "start": 1548286456230, "status": "success", "end": 1548286463758, "result": "28beb0f6-7325-67d9-e985-c1f674afbc86" }, { "id": "1548286463762", "message": "add metadata to snapshot", "start": 1548286463762, "status": "success", "end": 1548286463792 }, { "id": "1548286463984", "message": "waiting for uptodate snapshot record", "start": 1548286463984, "status": "success", "end": 1548286464202 }, { "id": "1548286469779", "message": "start snapshot export", "start": 1548286469779, "status": "success", "end": 1548286469779 }, { "data": { "id": "9988c77d-9dbc-40ee-829f-dd4970d1bbd1", "isFull": false, "type": "remote" }, "id": "1548286469779:1", "message": "export", "start": 1548286469779, "status": "success", "tasks": [ { "id": "1548286472972", "message": "transfer", "start": 1548286472972, "status": "success", "end": 1548286547006, "result": { "size": 404872192 } }, { "id": "1548286547014", "message": "merge", "start": 1548286547014, "status": "success", "end": 1548286606241, "result": { "size": 140509184 } } ], "end": 1548286606241 }, { "id": "1548286606243", "message": "set snapshot.other_config[xo:backup:exported]", "start": 1548286606243, "status": "success", "end": 1548286606263 } ], "end": 1548286608673 }, { "data": { "type": "VM", "id": "a100de1c-fe36-4284-560f-e380c21fa98b" }, "id": "1548286520029", "message": "Starting backup of prod_012. (c2711a5b-3fc0-45ae-ae6f-bb24c57c0d6e)", "start": 1548286520029, "status": "success", "tasks": [ { "id": "1548286520031", "message": "snapshot", "start": 1548286520031, "status": "success", "end": 1548286530945, "result": "faf2bcc2-d66a-d988-219d-6407f8da8eb5" }, { "id": "1548286530949", "message": "add metadata to snapshot", "start": 1548286530949, "status": "success", "end": 1548286530990 }, { "id": "1548286531169", "message": "waiting for uptodate snapshot record", "start": 1548286531169, "status": "success", "end": 1548286531388 }, { "id": "1548286535778", "message": "start snapshot export", "start": 1548286535778, "status": "success", "end": 1548286535778 }, { "data": { "id": "9988c77d-9dbc-40ee-829f-dd4970d1bbd1", "isFull": false, "type": "remote" }, "id": "1548286535779", "message": "export", "start": 1548286535779, "status": "success", "tasks": [ { "id": "1548286538738", "message": "transfer", "start": 1548286538738, "status": "success", "end": 1548286604126, "result": { "size": 367196160 } }, { "id": "1548286604522", "message": "merge", "start": 1548286604522, "status": "success", "end": 1548286697859, "result": { "size": 822083584 } } ], "end": 1548286697860 }, { "id": "1548286697862", "message": "set snapshot.other_config[xo:backup:exported]", "start": 1548286697862, "status": "success", "end": 1548286697881 } ], "end": 1548286700310 } ], "end": 1548287176754 } ```
Zuko commented 5 years ago

Another occurrence. And like last one, next scheduled backup was successful.

Log fragment ``` "message": "footer1 !== footer2", "stack": "AssertionError [ERR_ASSERTION]: footer1 !== footer2\n at /opt/xen-orchestra/packages/vhd-lib/src/vhd.js:167:8\n at Generator.next ()\n at asyncGeneratorStep (/opt/xen-orchestra/packages/vhd-lib/dist/vhd.js:22:103)\n at _next (/opt/xen-orchestra/packages/vhd-lib/dist/vhd.js:24:194)\n at tryCatcher (/opt/xen-orchestra/node_modules/bluebird/js/release/util.js:16:23)\n at Promise._settlePromiseFromHandler (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:512:31)\n at Promise._settlePromise (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:569:18)\n at Promise._settlePromise0 (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:614:10)\n at Promise._settlePromises (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:694:18)\n at _drainQueueStep (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:138:12)\n at _drainQueue (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:131:9)\n at Async._drainQueues (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:147:5)\n at Immediate.Async.drainQueues (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:17:14)\n at runCallback (timers.js:810:20)\n at tryOnImmediate (timers.js:768:5)\n at processImmediate [as _immediateCallback] (timers.js:745:5)", "generatedMessage": false, "name": "AssertionError [ERR_ASSERTION]", "code": "ERR_ASSERTION", "actual": false, "expected": true, "operator": "==" ```
julien-f commented 5 years ago

By any chance, do you have multiple jobs working at the same time on the same VM?

Zuko commented 5 years ago

Let me check. Edit. Nope, all my vm's have only one "backup" tag.

image

Zuko commented 5 years ago

Another failed backup ;( I'm the only one with this bug?

julien-f commented 5 years ago

Always on the same backup job, remote or VM?

Zuko commented 5 years ago

Same remote, different VM's and backup jobs _(Delta_6h and DeltaDay)

Zuko commented 5 years ago

I changed storage (different NFS share, on different hardware) and the problem disappeared (for now).

julien-f commented 5 years ago

Ok, let's close this for now, please report if it reappear :-)