Delta backup footer1 !== footer2 error

Alexander 0

@olivierlambert I updated it Yesterday.

olivierlambert

Good. So you have a corrupted VHD in your backup (transfer interrupted at some point).

I think @badrAZ is working on something that would automatically deal with it. You can remove your VM snapshot so it will recreate a full.

Alexander 0

@olivierlambert I have remade backup when I saw the problem.
It went without problems.
I will monitor this further and report if it occurs on other VM's

Alexander 0

Two more VM's with error this night.

{
  "data": {
    "mode": "delta",
    "reportWhen": "always"
  },
  "id": "1618522200008",
  "jobId": "c7f542ad-07f2-45c9-9002-bf7169d90a14",
  "jobName": "discourse-BUp",
  "message": "backup",
  "scheduleId": "9dbda6ce-0118-41b6-b357-dcf080318ec1",
  "start": 1618522200008,
  "status": "failure",
  "infos": [
    {
      "data": {
        "vms": [
          "a1a3832c-b16a-a85e-2fdd-ae585087f629"
        ]
      },
      "message": "vms"
    }
  ],
  "tasks": [
    {
      "data": {
        "type": "VM",
        "id": "a1a3832c-b16a-a85e-2fdd-ae585087f629"
      },
      "id": "1618522200629",
      "message": "backup VM",
      "start": 1618522200629,
      "status": "failure",
      "tasks": [
        {
          "id": "1618522205326",
          "message": "snapshot",
          "start": 1618522205326,
          "status": "success",
          "end": 1618522210762,
          "result": "be5287a0-a956-81bc-87fa-e840be406cd4"
        },
        {
          "data": {
            "id": "df7361d2-509b-46fe-bf12-d63fc6d93524",
            "isFull": false,
            "type": "remote"
          },
          "id": "1618522210762:0",
          "message": "export",
          "start": 1618522210762,
          "status": "failure",
          "tasks": [
            {
              "id": "1618522210931",
              "message": "transfer",
              "start": 1618522210931,
              "status": "failure",
              "end": 1618522235395,
              "result": {
                "generatedMessage": false,
                "code": "ERR_ASSERTION",
                "actual": false,
                "expected": true,
                "operator": "==",
                "message": "footer1 !== footer2",
                "name": "AssertionError",
                "stack": "AssertionError [ERR_ASSERTION]: footer1 !== footer2\n    at Vhd.readHeaderAndFooter (/opt/xen-orchestra/packages/vhd-lib/dist/vhd.js:118:27)\n    at async checkVhd (/opt/xen-orchestra/@xen-orchestra/backups/_checkVhd.js:4:3)\n    at async RemoteAdapter.outputStream (/opt/xen-orchestra/@xen-orchestra/backups/RemoteAdapter.js:517:7)\n    at async /opt/xen-orchestra/@xen-orchestra/backups/_DeltaBackupWriter.js:196:11\n    at async Promise.all (index 0)\n    at async /opt/xen-orchestra/@xen-orchestra/backups/_DeltaBackupWriter.js:171:7"
              }
            }
          ],
          "end": 1618522235396,
          "result": {
            "generatedMessage": false,
            "code": "ERR_ASSERTION",
            "actual": false,
            "expected": true,
            "operator": "==",
            "message": "footer1 !== footer2",
            "name": "AssertionError",
            "stack": "AssertionError [ERR_ASSERTION]: footer1 !== footer2\n    at Vhd.readHeaderAndFooter (/opt/xen-orchestra/packages/vhd-lib/dist/vhd.js:118:27)\n    at async checkVhd (/opt/xen-orchestra/@xen-orchestra/backups/_checkVhd.js:4:3)\n    at async RemoteAdapter.outputStream (/opt/xen-orchestra/@xen-orchestra/backups/RemoteAdapter.js:517:7)\n    at async /opt/xen-orchestra/@xen-orchestra/backups/_DeltaBackupWriter.js:196:11\n    at async Promise.all (index 0)\n    at async /opt/xen-orchestra/@xen-orchestra/backups/_DeltaBackupWriter.js:171:7"
          }
        }
      ],
      "end": 1618522237312,
      "result": {
        "message": "task has already ended",
        "name": "Error",
        "stack": "Error: task has already ended\n    at Task.logAfterEnd (/opt/xen-orchestra/@xen-orchestra/backups/Task.js:5:9)\n    at Task.onLog (/opt/xen-orchestra/@xen-orchestra/backups/Task.js:59:37)\n    at Task.#log (/opt/xen-orchestra/@xen-orchestra/backups/Task.js:139:16)\n    at new Task (/opt/xen-orchestra/@xen-orchestra/backups/Task.js:75:14)\n    at Function.run (/opt/xen-orchestra/@xen-orchestra/backups/Task.js:33:12)\n    at DeltaBackupWriter._deleteOldEntries (/opt/xen-orchestra/@xen-orchestra/backups/_DeltaBackupWriter.js:115:17)\n    at DeltaBackupWriter.cleanup (/opt/xen-orchestra/@xen-orchestra/backups/_DeltaBackupWriter.js:110:18)\n    at /opt/xen-orchestra/@xen-orchestra/backups/Task.js:129:32\n    at /opt/xen-orchestra/@xen-orchestra/backups/Task.js:103:24\n    at Zone.run (/opt/xen-orchestra/node_modules/node-zone/index.js:80:23)"
      }
    }
  ],
  "end": 1618522237313
}

{
  "data": {
    "mode": "delta",
    "reportWhen": "always"
  },
  "id": "1618502400009",
  "jobId": "2cdd42b8-8961-400d-9a6c-4c10b008c010",
  "jobName": "devart_jenkins",
  "message": "backup",
  "scheduleId": "18f81e07-5ed9-4b02-a707-bd3c5100861d",
  "start": 1618502400009,
  "status": "failure",
  "infos": [
    {
      "data": {
        "vms": [
          "3581d5ca-2c13-31f1-d552-7382aa343804"
        ]
      },
      "message": "vms"
    }
  ],
  "tasks": [
    {
      "data": {
        "type": "VM",
        "id": "3581d5ca-2c13-31f1-d552-7382aa343804"
      },
      "id": "1618502400600",
      "message": "backup VM",
      "start": 1618502400600,
      "status": "failure",
      "tasks": [
        {
          "id": "1618502401839",
          "message": "snapshot",
          "start": 1618502401839,
          "status": "success",
          "end": 1618502407288,
          "result": "8734319d-91da-88a0-c81b-5ce9a67edefb"
        },
        {
          "data": {
            "id": "df7361d2-509b-46fe-bf12-d63fc6d93524",
            "isFull": false,
            "type": "remote"
          },
          "id": "1618502407288:0",
          "message": "export",
          "start": 1618502407288,
          "status": "failure",
          "tasks": [
            {
              "id": "1618502407325",
              "message": "transfer",
              "start": 1618502407325,
              "status": "failure",
              "end": 1618502425566,
              "result": {
                "generatedMessage": false,
                "code": "ERR_ASSERTION",
                "actual": false,
                "expected": true,
                "operator": "==",
                "message": "footer1 !== footer2",
                "name": "AssertionError",
                "stack": "AssertionError [ERR_ASSERTION]: footer1 !== footer2\n    at Vhd.readHeaderAndFooter (/opt/xen-orchestra/packages/vhd-lib/dist/vhd.js:118:27)\n    at async checkVhd (/opt/xen-orchestra/@xen-orchestra/backups/_checkVhd.js:4:3)\n    at async RemoteAdapter.outputStream (/opt/xen-orchestra/@xen-orchestra/backups/RemoteAdapter.js:517:7)\n    at async /opt/xen-orchestra/@xen-orchestra/backups/_DeltaBackupWriter.js:196:11\n    at async Promise.all (index 0)\n    at async /opt/xen-orchestra/@xen-orchestra/backups/_DeltaBackupWriter.js:171:7"
              }
            }
          ],
          "end": 1618502425566,
          "result": {
            "generatedMessage": false,
            "code": "ERR_ASSERTION",
            "actual": false,
            "expected": true,
            "operator": "==",
            "message": "footer1 !== footer2",
            "name": "AssertionError",
            "stack": "AssertionError [ERR_ASSERTION]: footer1 !== footer2\n    at Vhd.readHeaderAndFooter (/opt/xen-orchestra/packages/vhd-lib/dist/vhd.js:118:27)\n    at async checkVhd (/opt/xen-orchestra/@xen-orchestra/backups/_checkVhd.js:4:3)\n    at async RemoteAdapter.outputStream (/opt/xen-orchestra/@xen-orchestra/backups/RemoteAdapter.js:517:7)\n    at async /opt/xen-orchestra/@xen-orchestra/backups/_DeltaBackupWriter.js:196:11\n    at async Promise.all (index 0)\n    at async /opt/xen-orchestra/@xen-orchestra/backups/_DeltaBackupWriter.js:171:7"
          }
        }
      ],
      "end": 1618502426837,
      "result": {
        "message": "task has already ended",
        "name": "Error",
        "stack": "Error: task has already ended\n    at Task.logAfterEnd (/opt/xen-orchestra/@xen-orchestra/backups/Task.js:5:9)\n    at Task.onLog (/opt/xen-orchestra/@xen-orchestra/backups/Task.js:59:37)\n    at Task.#log (/opt/xen-orchestra/@xen-orchestra/backups/Task.js:139:16)\n    at new Task (/opt/xen-orchestra/@xen-orchestra/backups/Task.js:75:14)\n    at Function.run (/opt/xen-orchestra/@xen-orchestra/backups/Task.js:33:12)\n    at DeltaBackupWriter._deleteOldEntries (/opt/xen-orchestra/@xen-orchestra/backups/_DeltaBackupWriter.js:115:17)\n    at DeltaBackupWriter.cleanup (/opt/xen-orchestra/@xen-orchestra/backups/_DeltaBackupWriter.js:110:18)\n    at /opt/xen-orchestra/@xen-orchestra/backups/Task.js:129:32\n    at /opt/xen-orchestra/@xen-orchestra/backups/Task.js:103:24\n    at Zone.run (/opt/xen-orchestra/node_modules/node-zone/index.js:80:23)"
      }
    }
  ],
  "end": 1618502426839
}

Alexander 0

@olivierlambert Yesterday I deleted snapshots of delta backups and it made full backups successful. Today I see errors again with incremental.

olivierlambert

Please rebuild everything on master and try again. It's hard to investigate when we do not control entirely the environment.

Alexander 0

@olivierlambert I have rebuild xen orchestra with last master.
Now I recreating backup job. Will see if there will be same issues.

Alexander 0

@olivierlambert and today I have first failed backup with same error.

olivierlambert

To rule out an XO problem (but something specific on your setup), please try with an XOA on latest If you need another trial round for that, let me know I'll unlock it!

Alexander 0

@olivierlambert I see today's commit with changes to merge process.
May this help?

olivierlambert

Feel free to try and report then thanks!

Alexander 0

@olivierlambert I've set up XOA trial. Will see if problem appear.

Alexander 0

@olivierlambert
I got the same error on XOA appliance.

{
  "data": {
    "mode": "delta",
    "reportWhen": "always"
  },
  "id": "1620250200011",
  "jobId": "f44dc556-32ba-4bbc-8568-06d5d26b6835",
  "jobName": "discourse-BUp",
  "message": "backup",
  "scheduleId": "bb7b53e4-ca32-48f8-afbb-1ce36ddc84f2",
  "start": 1620250200011,
  "status": "failure",
  "infos": [
    {
      "data": {
        "vms": [
          "a1a3832c-b16a-a85e-2fdd-ae585087f629"
        ]
      },
      "message": "vms"
    }
  ],
  "tasks": [
    {
      "data": {
        "type": "VM",
        "id": "a1a3832c-b16a-a85e-2fdd-ae585087f629"
      },
      "id": "1620250200710",
      "message": "backup VM",
      "start": 1620250200710,
      "status": "failure",
      "tasks": [
        {
          "id": "1620250205577",
          "message": "snapshot",
          "start": 1620250205577,
          "status": "success",
          "end": 1620250210934,
          "result": "569701f3-2665-32c1-ef1c-2b8b1377d88b"
        },
        {
          "data": {
            "id": "84dd7240-14e8-4233-befa-f95e7d62e74e",
            "isFull": false,
            "type": "remote"
          },
          "id": "1620250210935",
          "message": "export",
          "start": 1620250210935,
          "status": "failure",
          "tasks": [
            {
              "id": "1620250211055",
              "message": "transfer",
              "start": 1620250211055,
              "status": "failure",
              "end": 1620250232442,
              "result": {
                "generatedMessage": false,
                "code": "ERR_ASSERTION",
                "actual": false,
                "expected": true,
                "operator": "==",
                "message": "footer1 !== footer2",
                "name": "AssertionError",
                "stack": "AssertionError [ERR_ASSERTION]: footer1 !== footer2\n    at Vhd.readHeaderAndFooter (/usr/local/lib/node_modules/xo-server/node_modules/vhd-lib/dist/vhd.js:118:27)\n    at async checkVhd (/usr/local/lib/node_modules/xo-server/node_modules/@xen-orchestra/backups/_checkVhd.js:4:3)\n    at async RemoteAdapter.outputStream (/usr/local/lib/node_modules/xo-server/node_modules/@xen-orchestra/backups/RemoteAdapter.js:517:7)\n    at async /usr/local/lib/node_modules/xo-server/node_modules/@xen-orchestra/backups/_DeltaBackupWriter.js:196:11\n    at async Promise.all (index 0)\n    at async /usr/local/lib/node_modules/xo-server/node_modules/@xen-orchestra/backups/_DeltaBackupWriter.js:171:7"
              }
            }
          ],
          "end": 1620250232442,
          "result": {
            "generatedMessage": false,
            "code": "ERR_ASSERTION",
            "actual": false,
            "expected": true,
            "operator": "==",
            "message": "footer1 !== footer2",
            "name": "AssertionError",
            "stack": "AssertionError [ERR_ASSERTION]: footer1 !== footer2\n    at Vhd.readHeaderAndFooter (/usr/local/lib/node_modules/xo-server/node_modules/vhd-lib/dist/vhd.js:118:27)\n    at async checkVhd (/usr/local/lib/node_modules/xo-server/node_modules/@xen-orchestra/backups/_checkVhd.js:4:3)\n    at async RemoteAdapter.outputStream (/usr/local/lib/node_modules/xo-server/node_modules/@xen-orchestra/backups/RemoteAdapter.js:517:7)\n    at async /usr/local/lib/node_modules/xo-server/node_modules/@xen-orchestra/backups/_DeltaBackupWriter.js:196:11\n    at async Promise.all (index 0)\n    at async /usr/local/lib/node_modules/xo-server/node_modules/@xen-orchestra/backups/_DeltaBackupWriter.js:171:7"
          }
        }
      ],
      "end": 1620250233919,
      "result": {
        "message": "task has already ended",
        "name": "Error",
        "stack": "Error: task has already ended\n    at Task.logAfterEnd (/usr/local/lib/node_modules/xo-server/node_modules/@xen-orchestra/backups/Task.js:5:9)\n    at Task.onLog (/usr/local/lib/node_modules/xo-server/node_modules/@xen-orchestra/backups/Task.js:59:37)\n    at Task.#log (/usr/local/lib/node_modules/xo-server/node_modules/@xen-orchestra/backups/Task.js:139:16)\n    at new Task (/usr/local/lib/node_modules/xo-server/node_modules/@xen-orchestra/backups/Task.js:75:14)\n    at Function.run (/usr/local/lib/node_modules/xo-server/node_modules/@xen-orchestra/backups/Task.js:33:12)\n    at DeltaBackupWriter._deleteOldEntries (/usr/local/lib/node_modules/xo-server/node_modules/@xen-orchestra/backups/_DeltaBackupWriter.js:115:17)\n    at DeltaBackupWriter.cleanup (/usr/local/lib/node_modules/xo-server/node_modules/@xen-orchestra/backups/_DeltaBackupWriter.js:110:18)\n    at /usr/local/lib/node_modules/xo-server/node_modules/@xen-orchestra/backups/Task.js:129:32\n    at /usr/local/lib/node_modules/xo-server/node_modules/@xen-orchestra/backups/Task.js:103:24\n    at Zone.run (/usr/local/lib/node_modules/xo-server/node_modules/node-zone/index.js:80:23)"
      }
    }
  ],
  "end": 1620250233919
}

I have created a bug ticket with a link to this topic.

Alexander 0

@olivierlambert problem was fixed. Thank you for help.

MrNaz

@alexander-0
I am having this exact same issue. Can you tell me what you did to fix it? Or was it fixed when you updated to the latest version?

Alexander 0

@mrnaz the fixed it in version 5.58.1. So update helped.