Corrected VHD-Parent to incorrect image filename, cannot delete old backups

Server
1

Hi,
Recently one of the machines I am backing up has stopped backing up one of the disks with the error:

2024-11-07 02:44:59: Starting scheduled incremental image backup of volume "D:"...
2024-11-07 02:44:59: Basing image backup on last incremental or full image backup
2024-11-07 02:45:10: VHD-Parent: "/backups/PC/241029-1808_Image_C/Image_C_241029-1808.vhdz"
2024-11-07 02:45:10: Corrected VHD-Parent to: "/backups/PC/241104-1803_Image_D/Image_C_241029-1808.vhdz"
2024-11-07 02:45:10: ERROR: Error opening VHD file
2024-11-07 02:45:10: ERROR: Error opening Parentvhdfile "/backups/PC/241104-1803_Image_D/Image_C_241029-1808.vhdz"
2024-11-07 02:45:10: ERROR: Error opening parent VHD
2024-11-07 02:45:10: ERROR: Error opening VHD file "/backups/PC/241107-0244_Image_D/Image_D_241107-0244.vhdz"
2024-11-07 02:45:10: Transferred 360.402 KB - Average speed: 276.936 KBit/s
2024-11-07 02:45:10: Time taken for backing up client PC: 10s
2024-11-07 02:45:10: ERROR: Backup failed

Obviously it’s not going to find the image for D: in the directory of C: :slight_smile:

Also when I try to remove all the D: backups so that it can start that chain again I get the error from the web UI:

Error deleting backup: Incremental image backup based on this backup is currently running

But no backups are running and I have tried restarting the docker container but it still thinks a backup is running.

Can I just delete the Image_D directories from the filesystem and let urbackup figure it out?

2

It seems to have fixed itself, maybe because I restarted the docker container?

2024-11-07 18:03:18(info): Basing image backup on last incremental or full image backup
2024-11-07 18:03:18(warning): Error retrieving last image backup. Doing full image backup instead.
3

I’m a bit worried about this still. The most likely explanation is that it based the D image off a C image, which would not be great.

You don’t happen to have logs of when the 241104-1803_Image_D backup was done?

4

The docker container still has logs back to August, but grep doesn’t show any 241104-1803_Image_D until the error on the 5th which is when it first started giving the bad Corrected VHD-Parent (exactly the same as the error posted above).

Here are the logs for 2024-11-04 18:03:

2024-11-04 18:03:30: Starting scheduled incremental image backup of volume "D:"...
2024-11-04 18:03:30: Basing image backup on last incremental or full image backup
2024-11-04 18:03:30: Authentication failed in InternetServiceConnector::ReceivePackets: Token not found (token authentication)
2024-11-04 18:04:18: VHD-Parent: "/backups/PC/241021-1834_Image_D/Image_D_241021-1834.vhdz"
2024-11-04 18:04:18: VHD-Parent: "/backups/PC/241020-0500_Image_D/Image_D_241020-0500.vhdz"
2024-11-04 18:05:34: Encryption overhead: 948 bytes
2024-11-04 18:05:34: Trim beyond drivesize (drivesize: 20722482688 trim to 20722483200). Trimming less...
2024-11-04 18:05:34: Transferred 1.58988 MB - Average speed: 107.952 KBit/s
2024-11-04 18:05:34: (Before compression: 10.7676 MB ratio: 6.77256)
2024-11-04 18:05:34: Time taken for backing up client PC: 2m 4s
2024-11-04 18:05:34: Backup succeeded

Also, this client is using an unsupported version of urbackup 2.4.11 since that is the latest which works on windows 2008r2. I should have mentioned that before, but when I made the post I was just thinking about how to reset the backup chain rather than why it went wrong :slight_smile:

5

Thanks. Do you find anything if you search for 241029-1808_Image_C ?

6

It seems like 241029-1808_Image_C was deleted at 2024-11-02 16:55:42, a few days before the failed backup referenced it.
There was also a second attempt to delete it again at 2024-11-02 16:55:43, which failed because it had already gone.

2024-11-02 16:55:42: Downloading version file...
2024-11-02 16:55:42: Downloading version file...
2024-11-02 16:55:42: Downloading server version info...
2024-11-02 16:55:42: Downloading dataplan database...
2024-11-02 16:55:42: Deleting incremental image backup ( id=1228, backuptime=2024-10-28 18:05:33, path=/backups/PC/241028-1805_Image_C/Image_C_241028-1805.vhdz, letter=C: ) from client "PC" ( id=4 ) ...
2024-11-02 16:55:42: Cannot delete image because incremental image backups referencing this image are not allowed to be deleted
2024-11-02 16:55:42: ERROR: Cannot delete image because incremental image backup referencing this image cannot be deleted
2024-11-02 16:55:42: ERROR: Cannot delete image because incremental image backup referencing this image cannot be deleted
2024-11-02 16:55:42: ERROR: Cannot delete image because incremental image backup referencing this image cannot be deleted
2024-11-02 16:55:42: Deleting incremental image backup ( id=1239, backuptime=2024-10-29 18:08:47, path=/backups/PC/241029-1808_Image_C/Image_C_241029-1808.vhdz, letter=C: ) from client "PC" ( id=4 ) ...
2024-11-02 16:55:42: Deleting image backup ( id=1272, path=/backups/PC/241102-0500_Image_SYSVOL/Image_SYSVOL_241102-0500.vhdz ) ...
2024-11-02 16:55:42: WARNING: Deleting /backups/PC/241102-0500_Image_SYSVOL/Image_SYSVOL_241102-0500.vhdz.bitmap failed. No such file or directory (code: 2)
2024-11-02 16:55:42: Deleting image backup ( id=1273, path=/backups/PC/241102-0501_Image_C/Image_C_241102-0501.vhdz ) ...
2024-11-02 16:55:42: WARNING: Deleting /backups/PC/241102-0501_Image_C/Image_C_241102-0501.vhdz.bitmap failed. No such file or directory (code: 2)
2024-11-02 16:55:42: Deleting image backup ( id=1260, path=/backups/PC/241101-0203_Image_SYSVOL/Image_SYSVOL_241101-0203.vhdz ) ...
2024-11-02 16:55:42: WARNING: Deleting /backups/PC/241101-0203_Image_SYSVOL/Image_SYSVOL_241101-0203.vhdz.bitmap failed. No such file or directory (code: 2)
2024-11-02 16:55:42: Deleting image backup ( id=1261, path=/backups/PC/241101-0203_Image_C/Image_C_241101-0203.vhdz ) ...
2024-11-02 16:55:42: WARNING: Deleting /backups/PC/241101-0203_Image_C/Image_C_241101-0203.vhdz.bitmap failed. No such file or directory (code: 2)
2024-11-02 16:55:42: Deleting image backup ( id=1247, path=/backups/PC/241031-0200_Image_SYSVOL/Image_SYSVOL_241031-0200.vhdz ) ...
2024-11-02 16:55:43: WARNING: Deleting /backups/PC/241031-0200_Image_SYSVOL/Image_SYSVOL_241031-0200.vhdz.bitmap failed. No such file or directory (code: 2)
2024-11-02 16:55:43: Deleting image backup ( id=1248, path=/backups/PC/241031-0200_Image_C/Image_C_241031-0200.vhdz ) ...
2024-11-02 16:55:43: WARNING: Deleting /backups/PC/241031-0200_Image_C/Image_C_241031-0200.vhdz.bitmap failed. No such file or directory (code: 2)
2024-11-02 16:55:43: Deleting image backup ( id=1238, path=/backups/PC/241029-1808_Image_SYSVOL/Image_SYSVOL_241029-1808.vhdz ) ...
2024-11-02 16:55:43: WARNING: Deleting /backups/PC/241029-1808_Image_SYSVOL/Image_SYSVOL_241029-1808.vhdz.bitmap failed. No such file or directory (code: 2)
2024-11-02 16:55:43: Deleting image backup ( id=1239, path=/backups/PC/241029-1808_Image_C/Image_C_241029-1808.vhdz ) ...
2024-11-02 16:55:43: WARNING: Deleting /backups/PC/241029-1808_Image_C/Image_C_241029-1808.vhdz.bitmap failed. No such file or directory (code: 2)

I have uploaded the full log in case it is useful since it doesn’t seem to contain any personal information after changing the server names. There are 2 other clients and sometimes the log messages from 2 backups get merged together in the log.

urbackup.log.gz (196.4 KB)

7

Don’t have enough information to track this down at this point. If it re-occurs could you look if the problem is in the database or in the vhdz files?

Additionally other details about your system would be appreciated. E.g. what kind of Linux version you are using, file systems, ECC RAM…

8

I do actually have a few days of backups of the urbackup directory containing the databases, but not as far back as 241029. Looking at the backup_images table in backup_server.db the incremental_ref for all the D: backups is correct.
I can’t find 241029 anywhere in the whole backup_server.db file (using grep) though on the 3rd or 4th November when the errors occurred so maybe I am not looking in the right place :slight_smile: .

The machine running urbackup is Slackware64-15.0 on an AMD Ryzen 3 3200G with non-ECC RAM.
32GB of RAM and the highest memory use over the last 3 months has been 77%.
The backups are stored on an ext4 formatted 8TB disk which has 5TB free space so nowhere near full.
urbackup is running in docker 27.2.0 using image uroni/urbackup-server:latest and up to date.