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

[Backup NG] vhdimount can't mount source file in file restore #3739

Closed PieterWaegeman closed 5 years ago

PieterWaegeman commented 5 years ago

Context

Expected behavior

I expect that the vhdi from a delta backup is mounted so I can restore a file from a backup.

Current behavior

When I go to the web menu to Backup NG > File restore and select an image, to restore a file I get the dialog to select the backup. This works. After this I select the disk, but when I do this I get the error "Error while scanning disk".

If I check the logs I see following error:

backupNg.listPartitions { "remote": "e224e718-1245-4676-89af-a25e73b99730", "disk": "xo-vm-backups/93dc6115-b77f-42b4-0b31-fcd24b26ee94/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/5befd5a9-3147-431a-8e4d-a787682b83cc/20181130T001454Z.vhd" } { "message": "Command failed: vhdimount /mnt/backupxo-vm-backups/93dc6115-b77f-42b4-0b31-fcd24b26ee94/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/5befd5a9-3147-431a-8e4d-a787682b83cc/20181130T001454Z.vhd /tmp/tmp-407fMiGPTmFEflO Unable to open source file. libcfile_file_open_with_error_code: no such file: /mnt/backupxo-vm-backups/93dc6115-b77f-42b4-0b31-fcd24b26ee94/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/5befd5a9-3147-431a-8e4d-a787682b83cc/20181130T001454Z.vhd. libcfile_file_open: unable to open file. libbfio_file_open: unable to open file: /mnt/backupxo-vm-backups/93dc6115-b77f-42b4-0b31-fcd24b26ee94/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/5befd5a9-3147-431a-8e4d-a787682b83cc/20181130T001454Z.vhd. libcfile_file_get_size: invalid file - missing descriptor. libbfio_file_get_size: unable to retrieve size of file: /mnt/backupxo-vm-backups/93dc6115-b77f-42b4-0b31-fcd24b26ee94/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/5befd5a9-3147-431a-8e4d-a787682b83cc/20181130T001454Z.vhd. libbfio_handle_get_size: unable to retrieve size. libvhdi_file_open_read: unable to retrieve file size. libvhdi_file_open_file_io_handle: unable to read from file handle. libvhdi_file_open: unable to open file: /mnt/backupxo-vm-backups/93dc6115-b77f-42b4-0b31-fcd24b26ee94/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/5befd5a9-3147-431a-8e4d-a787682b83cc/20181130T001454Z.vhd. mount_handle_open_input: unable to open input file.

vhdimount 20160424

", "stack": "Error: Command failed: vhdimount /mnt/backupxo-vm-backups/93dc6115-b77f-42b4-0b31-fcd24b26ee94/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/5befd5a9-3147-431a-8e4d-a787682b83cc/20181130T001454Z.vhd /tmp/tmp-407fMiGPTmFEflO Unable to open source file. libcfile_file_open_with_error_code: no such file: /mnt/backupxo-vm-backups/93dc6115-b77f-42b4-0b31-fcd24b26ee94/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/5befd5a9-3147-431a-8e4d-a787682b83cc/20181130T001454Z.vhd. libcfile_file_open: unable to open file. libbfio_file_open: unable to open file: /mnt/backupxo-vm-backups/93dc6115-b77f-42b4-0b31-fcd24b26ee94/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/5befd5a9-3147-431a-8e4d-a787682b83cc/20181130T001454Z.vhd. libcfile_file_get_size: invalid file - missing descriptor. libbfio_file_get_size: unable to retrieve size of file: /mnt/backupxo-vm-backups/93dc6115-b77f-42b4-0b31-fcd24b26ee94/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/5befd5a9-3147-431a-8e4d-a787682b83cc/20181130T001454Z.vhd. libbfio_handle_get_size: unable to retrieve size. libvhdi_file_open_read: unable to retrieve file size. libvhdi_file_open_file_io_handle: unable to read from file handle. libvhdi_file_open: unable to open file: /mnt/backupxo-vm-backups/93dc6115-b77f-42b4-0b31-fcd24b26ee94/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/5befd5a9-3147-431a-8e4d-a787682b83cc/20181130T001454Z.vhd. mount_handle_open_input: unable to open input file.

vhdimount 20160424

at makeError (/opt/xen-orchestra/node_modules/execa/index.js:174:9)
at Promise.all.then.arr (/opt/xen-orchestra/node_modules/execa/index.js:278:16)
at tryCatcher (/opt/xen-orchestra/node_modules/bluebird/js/release/util.js:16:23)
at Promise._settlePromiseFromHandler (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:512:31)
at Promise._settlePromise (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:569:18)
at Promise._settlePromise0 (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:614:10)
at Promise._settlePromises (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:694:18)
at Promise._fulfill (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:638:18)
at PromiseArray._resolve (/opt/xen-orchestra/node_modules/bluebird/js/release/promise_array.js:126:19)
at PromiseArray._promiseFulfilled (/opt/xen-orchestra/node_modules/bluebird/js/release/promise_array.js:144:14)
at Promise._settlePromise (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:574:26)
at Promise._settlePromise0 (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:614:10)
at Promise._settlePromises (/opt/xen-orchestra/node_modules/bluebird/js/release/promise.js:694:18)
at _drainQueueStep (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:138:12)
at _drainQueue (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:131:9)
at Async._drainQueues (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:147:5)
at Immediate.Async.drainQueues (/opt/xen-orchestra/node_modules/bluebird/js/release/async.js:17:14)
at runCallback (timers.js:810:20)
at tryOnImmediate (timers.js:768:5)
at processImmediate [as _immediateCallback] (timers.js:745:5)",

"code": 1, "stdout": "vhdimount 20160424

", "stderr": "Unable to open source file. libcfile_file_open_with_error_code: no such file: /mnt/backupxo-vm-backups/93dc6115-b77f-42b4-0b31-fcd24b26ee94/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/5befd5a9-3147-431a-8e4d-a787682b83cc/20181130T001454Z.vhd. libcfile_file_open: unable to open file. libbfio_file_open: unable to open file: /mnt/backupxo-vm-backups/93dc6115-b77f-42b4-0b31-fcd24b26ee94/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/5befd5a9-3147-431a-8e4d-a787682b83cc/20181130T001454Z.vhd. libcfile_file_get_size: invalid file - missing descriptor. libbfio_file_get_size: unable to retrieve size of file: /mnt/backupxo-vm-backups/93dc6115-b77f-42b4-0b31-fcd24b26ee94/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/5befd5a9-3147-431a-8e4d-a787682b83cc/20181130T001454Z.vhd. libbfio_handle_get_size: unable to retrieve size. libvhdi_file_open_read: unable to retrieve file size. libvhdi_file_open_file_io_handle: unable to read from file handle. libvhdi_file_open: unable to open file: /mnt/backupxo-vm-backups/93dc6115-b77f-42b4-0b31-fcd24b26ee94/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/5befd5a9-3147-431a-8e4d-a787682b83cc/20181130T001454Z.vhd. mount_handle_open_input: unable to open input file. ", "failed": true, "signal": null, "cmd": "vhdimount /mnt/backupxo-vm-backups/93dc6115-b77f-42b4-0b31-fcd24b26ee94/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/5befd5a9-3147-431a-8e4d-a787682b83cc/20181130T001454Z.vhd /tmp/tmp-407fMiGPTmFEflO", "timedOut": false, "killed": false }

I've made a local remote on the server on /mnt/backup. But when the vhdimount tries to select the file, it just uses "/mnt/backup" and not "/mnt/backup/". The web interface also does not allow for the input of "/mnt/backup/".

Kind regards,

Pieter

PieterWaegeman commented 5 years ago

This is still not fixed with this patch. When I apply the changes I still get the same error.

julien-f commented 5 years ago

Thanks, I'll take a look.

PieterWaegeman commented 5 years ago

Logs now only show this when it occurs:

Command failed: vhdimount /mnt/backupxo-vm-backups/1809d606-be1e-1b9a-fe68-044ac52b8d37/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/ab188dce-7813-451f-a714-911427f1f81c/20181203T001338Z.vhd /tmp/tmp-8770ymcrtzcfpyk1 Unable to open source file. libcfile_file_open_with_error_code: no such file: /mnt/backupxo-vm-backups/1809d606-be1e-1b9a-fe68-044ac52b8d37/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/ab188dce-7813-451f-a714-911427f1f81c/20181203T001338Z.vhd. libcfile_file_open: unable to open file. libbfio_file_open: unable to open file: /mnt/backupxo-vm-backups/1809d606-be1e-1b9a-fe68-044ac52b8d37/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/ab188dce-7813-451f-a714-911427f1f81c/20181203T001338Z.vhd. libcfile_file_get_size: invalid file - missing descriptor. libbfio_file_get_size: unable to retrieve size of file: /mnt/backupxo-vm-backups/1809d606-be1e-1b9a-fe68-044ac52b8d37/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/ab188dce-7813-451f-a714-911427f1f81c/20181203T001338Z.vhd. libbfio_handle_get_size: unable to retrieve size. libvhdi_file_open_read: unable to retrieve file size. libvhdi_file_open_file_io_handle: unable to read from file handle. libvhdi_file_open: unable to open file: /mnt/backupxo-vm-backups/1809d606-be1e-1b9a-fe68-044ac52b8d37/vdis/05baeea1-1151-4f7a-b7a9-bda9caf92303/ab188dce-7813-451f-a714-911427f1f81c/20181203T001338Z.vhd. mount_handle_open_input: unable to open input file.

vhdimount 20160424

dsgagi commented 5 years ago

Experiencing the same behavior after updating to the latest version yesterday.

We are using 7 days delta backups. I can use file restore on delta backups from 3rd December and before, but get same errors on the backups made today at 1am.

Our logs are below.

Dec 04 12:02:38 xoce.netcast.rs xo-server[876]: Unable to open source file.
Dec 04 12:02:38 xoce.netcast.rs xo-server[876]: libcfile_file_open_with_error_code: no such file: /xo-vm-backups/a52f0de6-98b9-61b7-c581-9bd48ed859ff/vdis/8aefbee2-3243-46dc-b520-71cd25857a51/e68625d0-0575-491b-9963-db5907eed28d/20181203T000755Z.vhd.
Dec 04 12:02:38 xoce.netcast.rs xo-server[876]: libcfile_file_open: unable to open file.
Dec 04 12:02:38 xoce.netcast.rs xo-server[876]: libbfio_file_open: unable to open file: /xo-vm-backups/a52f0de6-98b9-61b7-c581-9bd48ed859ff/vdis/8aefbee2-3243-46dc-b520-71cd25857a51/e68625d0-0575-491b-9963-db5907eed28d/20181203T000755Z.vhd.
Dec 04 12:02:38 xoce.netcast.rs xo-server[876]: libbfio_handle_open: unable to open handle.
Dec 04 12:02:38 xoce.netcast.rs xo-server[876]: libvhdi_file_open_file_io_handle: unable to open file IO handle.
Dec 04 12:02:38 xoce.netcast.rs xo-server[876]: libvhdi_file_open: unable to open file: /run/xo-server/mounts/43815fe3-0741-4f8a-9def-768d6f741eb9/xo-vm-backups/a52f0de6-98b9-61b7-c581-9bd48ed859ff/vdis/8aefbee2-3243-46dc-b520-71cd25857a51/e68625d0-0575-491b-9963-db5907eed28d/../../../../../../../../../xo-vm-backups/a52f0de6-98b9-61b7-c581-9bd48ed859ff/vdis/8aefbee2-3243-46dc-b520-71cd25857a51/e68625d0-0575-491b-9963-db5907eed28d/20181203T000755Z.vhd.
Dec 04 12:02:38 xoce.netcast.rs xo-server[876]: mount_handle_open_input_parent_file: unable to open parent input file: /run/xo-server/mounts/43815fe3-0741-4f8a-9def-768d6f741eb9/xo-vm-backups/a52f0de6-98b9-61b7-c581-9bd48ed859ff/vdis/8aefbee2-3243-46dc-b520-71cd25857a51/e68625d0-0575-491b-9963-db5907eed28d/../../../../../../../../../xo-vm-backups/a52f0de6-98b9-61b7-c581-9bd48ed859ff/vdis/8aefbee2-3243-46dc-b520-71cd25857a51/e68625d0-0575-491b-9963-db5907eed28d/20181203T000755Z.vhd.
Dec 04 12:02:38 xoce.netcast.rs xo-server[876]: mount_handle_open_input: unable to open parent input file.
Dec 04 12:02:38 xoce.netcast.rs xo-server[876]: vhdimount 20170223

Update: Just saw that file restore is working on the first delta backup (which is the initial full backup; added some new VMs to backup schedule yesterday). It seems it's not working on delta vhd files created after the update.

julien-f commented 5 years ago

After first look it appears the parent name in the delta file is incorrect due to the leading slash returned by handler.list.

jcharaoui commented 5 years ago

I also got hit by this problem. All the base VHDs of our delta backups got nuked when it got past the retention period. This happened completely silently, I only found out because I happened to manually test our backups. It's possible all users of delta backup may be impacted by this...

jcharaoui commented 5 years ago

By the way, I tested the latest master (cc26e378e5e06b2ef47da9c1c89c569a94478be8) and the problem still exists. Reproducing is simple: create new delta backup job with retention 1, trigger first run for full backup, then trigger a second run. The resulting backup is unusable, only the differencing VHD is kept.

I can confirm, reverting to 2946eaa15682e7b101577903645a5ee9361d1aad fixes the problem.

julien-f commented 5 years ago

Thanks for your tests, I intend to get this fixed tomorrow :slightly_smiling_face:

dsgagi commented 5 years ago

Any updates maybe? :)

Our backups got nuked on Sunday too. Thx @jcharaoui for reporting, otherwise we wouldn't even catch it.

I restarted all delta backups from scratch after that. Just wondering now if I should revert back to 5.30.1 or wait a little longer, in case that the fix will come out soon.

julien-f commented 5 years ago

@dsgagi Your backups are not broken, you don't need to delete them, file restore is just not working with them, I'll push a fix very soon :slightly_smiling_face:

dsgagi commented 5 years ago

Actually, same thing happened to us as @jcharaoui explained before.

We have a smart delta job for all running VM's with 7 files retention. Yesterday I noticed that base VHD files were deleted, only 7 differential files were in the folder.

After that, I moved all backups to another folder and started the job manually (only differentials that were left that is). XO started all full backup jobs, but I'm afraid the same thing will happen again when we reach the retention limit.

jcharaoui commented 5 years ago

@julien-f I think this bug report is mixing two issues, one with file restore, as reported by OP, and another, with delta backups, where the base VHD files are really getting lost, as in completely lost, deleted from the filesystem.

Perhaps it would be less confusing for all if a new issue was opened for this.

julien-f commented 5 years ago

The error message Unable to open source file only appears in case of file restore and it's the issue I'm talking about here.

julien-f commented 5 years ago

Yes please, open a new issue for the full being deleted when reaching the retention limit :+1:

dsgagi commented 5 years ago

I think it's maybe related.

File restore needs to link all vhd files to work, but it failed to open the parent file/files. I suppose the merge process failed for the same reason, and base VHD got deleted in the end.

What logic is used for deleting files at retention limit? File name or modification time?

jcharaoui commented 5 years ago

Alright I opened #3784.

@dsgagi, @julien-f According to my tests the original issue with file restore path issue is fixed in the latest master.

julien-f commented 5 years ago

I don't think so, I haven't pushed the fix yet…

I'll do some tests on my side.

PieterWaegeman commented 5 years ago

Any update on this issue @julien-f ?

julien-f commented 5 years ago

Yep, I'm working on it, I'll push in the next few hours :slightly_smiling_face:

julien-f commented 5 years ago

I just pushed a fix for this, it will work for new VHD chains (all the deltas in chain need to have been created after this commit).