Since upgrade to Server 2.5.30 the full backup always fails with error writing metadata

RL2022 · April 18, 2023, 5:31am

Since my upgrade to 2.5.30 on Linux the FULL backup always failes! Before the upgrade it never come up with that.

SERVER231: Loading file list…
Info
15.04.23 04:24
SERVER231: Started loading files…
Fehler
15.04.23 09:21
Error writing file metadata -1
Fehler
15.04.23 09:40
Error writing file metadata -1
Info
16.04.23 20:39
Waiting for file transfers…
Info
16.04.23 20:46
Waiting for file hashing and copying threads…
Warnungen
16.04.23 20:47
Not all folder metadata could be applied. Metadata was inconsistent.
Info
16.04.23 20:47
Writing new file list…
Info
16.04.23 20:48
All metadata was present
Info
16.04.23 20:48
Transferred 1.96597 TB - Average speed: 118.98 MBit/s
Fehler
16.04.23 20:48
FATAL: Backup failed because of disk problems (see previous messages)

The problem is it starts a FULL backup again next weekend and ends with the same message!

owenl · April 26, 2023, 8:55pm

I had the same problem. Could not find any problems with the disk, I reformatted several times to try Ext 3, 4 and BTRFS and swapped disk . My only solution was to revert back to the previous version of Urbackup. 2.4.15, no problems reported since. Of course doing this means the you need to clear out the current back up as they are not compatible.

uroni · April 26, 2023, 10:02pm

Sorry you are having issues. To solve the problem the server (debug) log would be useful.
If possible, could you post it or send it?

This post describes how to change the server to debug logging, where it is stored and where to send it to if posting is not possible: Having problems with UrBackup? Please read before posting

Thanks!

RL2022 · April 29, 2023, 5:56am

Hello from Asia!

I did change the config from warn to debug, now have to wait till next week for full backup because this weekend is already to short on time for a full one.

i see this in the debug log:

2023-04-29 07:40:54: Starting HTTP-Server on port 55414
2023-04-29 07:40:54: HTTP: Server started up successfully!
2023-04-29 07:40:56: SQLite: recovered 15137 frames from WAL file /var/urbackup/backup_server.db-wal code: 283
2023-04-29 07:41:11: SQLite: recovered 140731 frames from WAL file /var/urbackup/backup_server_files.db-wal code: 283
2023-04-29 07:41:11: SQLite: recovered 4880 frames from WAL file /var/urbackup/backup_server_link_journal.db-wal code: 283
2023-04-29 07:41:12: SQLite: recovered 26220 frames from WAL file /var/urbackup/backup_server_links.db-wal code: 283
2023-04-29 07:41:12: SQLite: recovered 3 frames from WAL file /var/urbackup/backup_server_settings.db-wal code: 283
2023-04-29 07:41:12: SQLite: recovered 15137 frames from WAL file /var/urbackup/backup_server.db-wal code: 283
2023-04-29 07:41:12: SQLite: recovered 3 frames from WAL file /var/urbackup/backup_server_settings.db-wal code: 283
2023-04-29 07:41:13: SQLite: recovered 140731 frames from WAL file /var/urbackup/backup_server_files.db-wal code: 283
2023-04-29 07:41:13: SQLite: recovered 26220 frames from WAL file /var/urbackup/backup_server_links.db-wal code: 283
2023-04-29 07:41:13: SQLite: recovered 4880 frames from WAL file /var/urbackup/backup_server_link_journal.db-wal code: 283
2023-04-29 07:41:13: Started UrBackup…
2023-04-29 07:41:13: Removing temporary files…
2023-04-29 07:41:13: Recreating temporary folder…
2023-04-29 07:41:14: Testing if backup destination can handle subvolumes and snapshots…
2023-04-29 07:41:14: InternetService: Server started up successfully!
2023-04-29 07:41:14: UrBackup Server start up complete.
2023-04-29 07:41:14: Looking for old Sessions… 0 sessions
2023-04-29 07:41:14: Server started up successfully!

Should i be concerned about the recovery things going on?

I did check the client versions, the servers with Client Version 2.4.11 not make problems, the server witch i did upgrade to 2.5.23 when i made the upgrade to server 2.5.30 are the one with problems. Maybe it is the Client? Deleting the Backups is no option!

What happen if i go back to client 2.4.11?

Regards

RL2022 · May 13, 2023, 7:31am

Sorry but i forget to set a reminder! So no full backup this weekend again.
I set a reminder now! …
Fri 19.05.23 backup 231 full ← SET

All a good weekend!

RL2022 · May 23, 2023, 8:00am

This weekend full backup was successful! But i have to mention i updated the urbackup software to version

UrBackup Server v2.5.31.0

before the backup.

So at the moment i am happy with the new version and will stop the debug option. (if i remeber where the config is)

KD.Gundermann · July 8, 2023, 10:46am

I have also update to v2.5.31.0 but now all backups are failing with lots of error.

Seeing the same message:

2023-07-08 12:38:34: WARNING: Metadata file and "/mnt/urbackup01/UG/230708-1201/C/Program Files/WindowsApps/Microsoft.WebpImageExtension_1.0.22753.0_x64__8wekyb3d8bbwe/Assets/contrast-black/AppList.targetsize-96_altform-unplated_contrast-black.png" (id=16930) do not exist. Skipping applying metdata for this file.
2023-07-08 12:38:34: WARNING: Metadata file and "/mnt/urbackup01/UG/230708-1201/C/Program Files/WindowsApps/Microsoft.WebpImageExtension_1.0.22753.0_x64__8wekyb3d8bbwe/Assets/contrast-black/AppList.targetsize-96_contrast-black.png" (id=16931) do not exist. Skipping applying metdata for this file.
2023-07-08 12:38:34: WARNING: Metadata file and "/mnt/urbackup01/UG/230708-1201/C/Program Files/WindowsApps/Microsoft.WebpImageExtension_1.0.22753.0_x64__8wekyb3d8bbwe/Assets/contrast-black/BadgeLogo.scale-100_contrast-black.png" (id=16932) do not exist. Skipping applying metdata for this file.
2023-07-08 12:38:34: WARNING: Metadata file and "/mnt/urbackup01/UG/230708-1201/C/Program Files/WindowsApps/Microsoft.WebpImageExtension_1.0.22753.0_x64__8wekyb3d8bbwe/Assets/contrast-black/BadgeLogo.scale-125_contrast-black.png" (id=16933) do not exist. Skipping applying metdata for this file.
2023-07-08 12:39:36: WARNING: Not all folder metadata could be applied. Metadata was inconsistent.
2023-07-08 12:39:36: WARNING: Error removing temporary directory "/mnt/urbackup01/MON2/230708-1203/.b68xO+K9SCOF35cLk4Bf9Q". Directory not empty (code: 39)
2023-07-08 12:39:39: ERROR: Fatal error during backup. Backup not completed
2023-07-08 12:39:40: ERROR: FATAL: Backup failed because of disk problems (see previous messages)
2023-07-08 12:39:41: ERROR: Backup failed
2023-07-08 12:39:43: WARNING: Exponential backoff: Waiting at least 40m before next file backup

KD.Gundermann · July 8, 2023, 10:48am

and getting an email about the failed backup, starts with:

WARNING: Restarting shadow copy of C:\ because it was started by this server
WARNING: Restarting shadow copy of D:\ because it was started by this server
ERROR: Error opening file "/mnt/urbackup01/CB2/230708-1203/.b68xO+K9SCOF35cLk4Bf9Q/5915" for reading file. File: temp_fn. Input/output error (code: 5) Target path: "/mnt/urbackup01/CB2/230708-1203/C/Program Files (x86)/Microsoft Office/root/Office16/OutlookExplorerTellMeZeroTermCommandModel.bin"
WARNING: Error opening temporary file. Retrying...
ERROR: Error opening file "/mnt/urbackup01/CB2/230708-1203/.b68xO+K9SCOF35cLk4Bf9Q/3094" from pipe for reading ec=5
ERROR: Error opening file "/mnt/urbackup01/CB2/230708-1203/.b68xO+K9SCOF35cLk4Bf9Q/3095" from pipe for reading ec=5
ERROR: Error opening file "/mnt/urbackup01/CB2/230708-1203/.b68xO+K9SCOF35cLk4Bf9Q/3096" from pipe for reading ec=5
....