I always ends up with such errors from the server when doing complete files backup. Incremental backups are fine.
Client is Debian testing Trixie amd64 as of today with urbackupclient 2.5.25
Server is Armbian 24.8.3 (Debian bookworm) with urbackup client docker 2.5.33.
backups folder for urbackup is on an madm raid10 4 HDD with ext4 above LVM (without snapshot for lack of space or dm-integrity).
2024-10-05 01:26:21: WARNING: File "/backups/hermes/241005-0104/.hashes/applications-home/Programs/Unity/2019.3.2f1/Editor/Data/Documentation/Documentation/en/ScriptReference/AudioSettings.Mobile.StopAudioOutput.html" has wrong size. Should=8 is=116. Error writing metadata to file. -1
indeed the file is 116 bytes. sudo ls -l /srv/dev-disk-by-label-secure/backup/urbackup/hermes/241005-0104/.hashes/applications-home/Programs/Unity/2019.3.2f1/Editor/Data/Documentation/Documentation/en/ScriptReference/AudioSettings.Mobile.StopAudioOutput.html -rwxr-x--- 1 docker_u users 116 5 oct. 01:26 /srv/dev-disk-by-label-secure/backup/urbackup/hermes/241005-0104/.hashes/applications-home/Programs/Unity/2019.3.2f1/Editor/Data/Documentation/Documentation/en/ScriptReference/AudioSettings.Mobile.StopAudioOutput.html
Seems the file with the wrong size changes.
Should I conclude about a hardware issue?
This box had instability with the CPU but I was confident these were gone since I upped the voltage.
Could it be anything other than hardware?
urbackup is the only one having such issue and only with complete backups (incrementals always succeeds). But maybe also because it is the only one to check sanity of the written data…
Could the problem be on the server side? (I ran these commands on the client)
All my clients backuped files are on btrfs (with varying kernel versions).
on the client, is Linux 6.10.11-amd64 btrfs (Debian testing) except for the EFI partition
df -h ~/Applications/
Sys. de fichiers Taille Utilisé Dispo Uti% Monté sur
/dev/sdb5 794G 721G 72G 92% /home
mount |grep /dev/sdb5
/dev/sdb5 on /home type btrfs (rw,noatime,compress=lzo,space_cache,subvolid=5,subvol=/)
ST1000DM003-1SB102 CC63 W9AFAKSE sdb
sudo smartctl -a /dev/sdb
smartctl 7.4 2023-08-01 r5530 [x86_64-linux-6.10.11-amd64] (local build)
Copyright (C) 2002-23, Bruce Allen, Christian Franke, www.smartmontools.org
=== START OF INFORMATION SECTION ===
Model Family: Seagate Barracuda 7200.14 (AF)
Device Model: ST1000DM003-1SB102
Serial Number: W9AFAKSE
LU WWN Device Id: 5 000c50 0c052571b
Firmware Version: CC63
User Capacity: 1 000 204 886 016 bytes [1,00 TB]
Sector Sizes: 512 bytes logical, 4096 bytes physical
Rotation Rate: 7200 rpm
Form Factor: 3.5 inches
Device is: In smartctl database 7.3/5528
ATA Version is: ACS-2, ACS-3 T13/2161-D revision 3b
SATA Version is: SATA 3.1, 6.0 Gb/s (current: 6.0 Gb/s)
Local Time is: Tue Oct 15 18:59:13 2024 CEST
SMART support is: Available - device has SMART capability.
SMART support is: Enabled
=== START OF READ SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED
General SMART Values:
Offline data collection status: (0x82) Offline data collection activity
was completed without error.
Auto Offline Data Collection: Enabled.
Self-test execution status: ( 0) The previous self-test routine completed
without error or no self-test has ever
been run.
Total time to complete Offline
data collection: ( 0) seconds.
Offline data collection
capabilities: (0x7b) SMART execute Offline immediate.
Auto Offline data collection on/off support.
Suspend Offline collection upon new
command.
Offline surface scan supported.
Self-test supported.
Conveyance Self-test supported.
Selective Self-test supported.
SMART capabilities: (0x0003) Saves SMART data before entering
power-saving mode.
Supports SMART auto save timer.
Error logging capability: (0x01) Error logging supported.
General Purpose Logging supported.
Short self-test routine
recommended polling time: ( 1) minutes.
Extended self-test routine
recommended polling time: ( 104) minutes.
Conveyance self-test routine
recommended polling time: ( 2) minutes.
SCT capabilities: (0x1085) SCT Status supported.
SMART Attributes Data Structure revision number: 10
Vendor Specific SMART Attributes with Thresholds:
ID# ATTRIBUTE_NAME FLAG VALUE WORST THRESH TYPE UPDATED WHEN_FAILED RAW_VALUE
1 Raw_Read_Error_Rate 0x000f 074 063 006 Pre-fail Always - 25496152
3 Spin_Up_Time 0x0003 097 097 000 Pre-fail Always - 0
4 Start_Stop_Count 0x0032 100 100 020 Old_age Always - 941
5 Reallocated_Sector_Ct 0x0033 100 100 010 Pre-fail Always - 0
7 Seek_Error_Rate 0x000f 090 060 045 Pre-fail Always - 1291182760
9 Power_On_Hours 0x0032 062 062 000 Old_age Always - 34104
10 Spin_Retry_Count 0x0013 100 100 097 Pre-fail Always - 0
12 Power_Cycle_Count 0x0032 100 100 020 Old_age Always - 826
183 Runtime_Bad_Block 0x0032 100 100 000 Old_age Always - 0
184 End-to-End_Error 0x0032 100 100 099 Old_age Always - 0
187 Reported_Uncorrect 0x0032 100 100 000 Old_age Always - 0
188 Command_Timeout 0x0032 100 100 000 Old_age Always - 0 0 1
189 High_Fly_Writes 0x003a 100 100 000 Old_age Always - 0
190 Airflow_Temperature_Cel 0x0022 063 041 040 Old_age Always - 37 (Min/Max 34/42)
193 Load_Cycle_Count 0x0032 099 099 000 Old_age Always - 2210
194 Temperature_Celsius 0x0022 037 013 000 Old_age Always - 37 (0 13 0 0 0)
195 Hardware_ECC_Recovered 0x001a 004 001 000 Old_age Always - 25496152
197 Current_Pending_Sector 0x0012 100 100 000 Old_age Always - 0
198 Offline_Uncorrectable 0x0010 100 100 000 Old_age Offline - 0
199 UDMA_CRC_Error_Count 0x003e 200 200 000 Old_age Always - 0
240 Head_Flying_Hours 0x0000 100 253 000 Old_age Offline - 33959h+02m+25.436s
241 Total_LBAs_Written 0x0000 100 253 000 Old_age Offline - 155093990532
242 Total_LBAs_Read 0x0000 100 253 000 Old_age Offline - 120347240973
SMART Error Log Version: 1
No Errors Logged
SMART Self-test log structure revision number 1
Num Test_Description Status Remaining LifeTime(hours) LBA_of_first_error
# 1 Short offline Completed without error 00% 34104 -
# 2 Short offline Completed without error 00% 30186 -
# 3 Short offline Completed without error 00% 24957 -
# 4 Vendor (0x50) Aborted by host 90% 20630 -
# 5 Short offline Aborted by host 10% 20630 -
# 6 Extended offline Completed without error 00% 14298 -
# 7 Short offline Completed without error 00% 1590 -
# 8 Vendor (0x50) Completed without error 00% 39 -
# 9 Short offline Completed without error 00% 39 -
#10 Vendor (0x50) Completed without error 00% 1 -
SMART Selective self-test log data structure revision number 1
SPAN MIN_LBA MAX_LBA CURRENT_TEST_STATUS
1 0 0 Not_testing
2 0 0 Not_testing
3 0 0 Not_testing
4 0 0 Not_testing
5 0 0 Not_testing
Selective self-test flags (0x0):
After scanning selected spans, do NOT read-scan remainder of disk.
If Selective self-test is pending on power-up, resume after 0 minute delay.
The above only provides legacy SMART information - try 'smartctl -x' for more
that is sdb is an HDD.
There is also an SSD with the cache for one user session and the /var folder in a subvolume inside this same btrfs partition
SanDisk SD9SB8W128G1001 X6106001 190105804079 sda
All my clients are affected (though I had complete backup that succeeded at times but failed before and after. ANd all the clients fail with the same error. Likely the issue is on the server side.
For the uruk client, an Odroid U2 armhf (32bits) with an eMMC storage, Debian Bookworm with an 6.1.0-26-armmp kernel (also files on btrfs):
2024-10-15 20:30:35: Starting unscheduled full file backup...
2024-10-15 20:30:41: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:31:13: Create a readonly snapshot of '/' in '//.urbackup_snaps/aacd2071cbb14d58eef9c8fdd911ab47'
2024-10-15 20:31:13: Indexing of "uruk-etc" done. 592 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:31:13: Indexing of "dockerregistry-etc" done. 2 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:31:13: Indexing of "redmine-etc" done. 2 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:31:13: Indexing of "nginx-etc" done. 10 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:31:13: Indexing of "debops-accounts" done. 15682 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:31:13: Indexing of "redmine-code" done. 791 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:31:13: Indexing of "redmine-logs" done. 2 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:31:13: Create a readonly snapshot of '/var/archives' in '/var/archives/.urbackup_snaps/ac579c4b1078d224fbd831a7f2932118'
2024-10-15 20:31:13: Indexing of "archives" done. 2 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:31:13: Create a readonly snapshot of '/opt/redmine' in '/opt/redmine/.urbackup_snaps/2d05d9e60e08052e048fc1675a202628'
2024-10-15 20:31:13: Indexing of "redmine-account" done. 1014 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:31:13: Create a readonly snapshot of '/var/backups' in '/var/backups/.urbackup_snaps/aa7700f3509fccb4617b83df829f1488'
2024-10-15 20:31:13: Indexing of "backups" done. 3 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:31:13: Create a readonly snapshot of '/var/lib/autopostgresqlbackup' in '/var/lib/autopostgresqlbackup/.urbackup_snaps/52472e98c8a8d483d2976498cb568404'
2024-10-15 20:31:13: Indexing of "autopostgresqlbackup" done. 16 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:31:13: Create a readonly snapshot of '/opt/gitolite' in '/opt/gitolite/.urbackup_snaps/edbe72e2ae593e06bc6be5d94a5fb735'
2024-10-15 20:31:13: Indexing of "gitolite-data" done. 10764 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:31:13: Create a readonly snapshot of '/home/repositories' in '/home/repositories/.urbackup_snaps/626e2a613b3a140d34dd74509e5d5bf1'
2024-10-15 20:31:13: Indexing of "extern-repositories" done. 314 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:31:13: Indexing of "zim-account" done. 4 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:31:13: Indexing of "dockerregistry-data" done. 952 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:31:13: Indexing of "acserver" done. 5912 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:31:13: Indexing of "redminedefault-files" done. 1 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:31:13: uruk: Loading file list...
2024-10-15 20:31:14: uruk: Started loading files...
2024-10-15 20:31:32: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:32:22: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:33:13: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:33:42: WARNING: File "/backups/uruk/241015-2030/.hashes/debops-accounts/phn/redmine5/old1/ruby-rugged-1.5.0.1/debian/ruby-rugged/usr/lib/arm-linux-gnueabihf/rubygems-integration/3.0.0/gems/rugged-1.5.0.1/vendor/libgit2/build/deps/ntlmclient/CMakeFiles/ntlmclient.dir/crypt_openssl.c.o" has wrong size. Should=8 is=113. Error writing metadata to file. -1
2024-10-15 20:33:42: ERROR: Error writing file metadata -1
2024-10-15 20:33:55: Files WAL file urbackup/backup_server_files.db-wal greater than 1000 MB. Doing full WAL checkpoint...
2024-10-15 20:34:03: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:34:10: Full checkpoint of urbackup/backup_server_files.db-wal done.
2024-10-15 20:34:54: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:35:44: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:35:55: WARNING: File "/backups/uruk/241015-2030/.hashes/debops-accounts/phn/ruby/ruby/test/ruby/enc/test_cesu8.rb" has wrong size. Should=8 is=113. Error writing metadata to file. -1
2024-10-15 20:35:55: ERROR: Error writing file metadata -1
2024-10-15 20:35:55: WARNING: File "/backups/uruk/241015-2030/.hashes/debops-accounts/phn/ruby/ruby/test/ruby/enc/test_case_options.rb" has wrong size. Should=8 is=113. Error writing metadata to file. -1
2024-10-15 20:35:55: ERROR: Error writing file metadata -1
2024-10-15 20:35:55: WARNING: File "/backups/uruk/241015-2030/.hashes/debops-accounts/phn/ruby/ruby/test/ruby/enc/test_case_mapping.rb" has wrong size. Should=8 is=113. Error writing metadata to file. -1
2024-10-15 20:35:55: ERROR: Error writing file metadata -1
2024-10-15 20:35:55: WARNING: File "/backups/uruk/241015-2030/.hashes/debops-accounts/phn/ruby/ruby/test/ruby/enc/test_iso_8859.rb" has wrong size. Should=8 is=113. Error writing metadata to file. -1
2024-10-15 20:35:55: ERROR: Error writing file metadata -1
2024-10-15 20:35:55: WARNING: File "/backups/uruk/241015-2030/.hashes/debops-accounts/phn/ruby/ruby/test/ruby/enc/test_grapheme_breaks.rb" has wrong size. Should=8 is=113. Error writing metadata to file. -1
2024-10-15 20:35:55: ERROR: Error writing file metadata -1
2024-10-15 20:35:55: WARNING: File "/backups/uruk/241015-2030/.hashes/debops-accounts/phn/ruby/ruby/test/ruby/enc/test_regex_casefold.rb" has wrong size. Should=8 is=113. Error writing metadata to file. -1
2024-10-15 20:35:55: ERROR: Error writing file metadata -1
2024-10-15 20:35:55: WARNING: File "/backups/uruk/241015-2030/.hashes/debops-accounts/phn/ruby/ruby/test/ruby/enc/test_case_comprehensive.rb" has wrong size. Should=8 is=113. Error writing metadata to file. -1
2024-10-15 20:35:55: ERROR: Error writing file metadata -1
2024-10-15 20:36:35: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:36:57: WARNING: File "/backups/uruk/241015-2030/.hashes/debops-accounts/phn/u-boot/u-boot/arch/m68k/cpu/mcf52x2/start.S" has wrong size. Should=8 is=113. Error writing metadata to file. -1
2024-10-15 20:36:57: ERROR: Error writing file metadata -1
2024-10-15 20:36:58: WARNING: File "/backups/uruk/241015-2030/.hashes/debops-accounts/phn/u-boot/u-boot/arch/m68k/cpu/mcf52x2/speed.c" has wrong size. Should=8 is=113. Error writing metadata to file. -1
2024-10-15 20:36:58: ERROR: Error writing file metadata -1
2024-10-15 20:36:58: WARNING: File "/backups/uruk/241015-2030/.hashes/debops-accounts/phn/u-boot/u-boot/arch/m68k/cpu/mcf523x/start.S" has wrong size. Should=8 is=113. Error writing metadata to file. -1
2024-10-15 20:36:58: ERROR: Error writing file metadata -1
2024-10-15 20:37:25: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:38:08: WARNING: File "/backups/uruk/241015-2030/.hashes/redmine-code/plugins/redmine_git_hosting/app/models/concerns/gitolitable/config.rb" has wrong size. Should=8 is=113. Error writing metadata to file. -1
2024-10-15 20:38:08: ERROR: Error writing file metadata -1
2024-10-15 20:38:08: WARNING: File "/backups/uruk/241015-2030/.hashes/redmine-code/plugins/redmine_git_hosting/app/reports/repository_commits_stats.rb" has wrong size. Should=8 is=113. Error writing metadata to file. -1
2024-10-15 20:38:08: ERROR: Error writing file metadata -1
2024-10-15 20:38:08: WARNING: File "/backups/uruk/241015-2030/.hashes/redmine-code/plugins/redmine_git_hosting/app/reports/repository_contributors_stats.rb" has wrong size. Should=8 is=113. Error writing metadata to file. -1
2024-10-15 20:38:08: ERROR: Error writing file metadata -1
(...)
I indeed have non standard settings but I did not keep a journal of the changes.
obvious ones could be (I translated on my own from French locale urbackup web UI):
temporary files as buffer for file backups: unchecked
temporary files as buffer for system backups: unchecked
use symbolic links during incremental file backup : checked
periodically re-add incremental file hashes of internet clients to the database : checked
debug: verify all files backups: unchecked
debug: verify all all files backups using a fingerprint on the client side: unchecked
simultaneous work per client: 24
beta: number of parallel connexions to save the same file: 1 (should be default)
beta: number of parallel works to compute fingerprint by the server for each save saved file : 10
beta: number of parallel works to compute fingerprint on the server for the same saved file : 11
database size in cache memory during batch processing: 350MB
I now checked:
debug: verify all files backups
debug: verify all all files backups using a fingerprint on the client side
to help debug
I run urbackup server in the official docker container.
version: '2'
services:
urbackup:
image: uroni/urbackup-server:latest
container_name: urbackup
restart: unless-stopped
environment:
- PUID=1002 # Enter the UID of the user who should own the files here
- PGID=100 # Enter the GID of the user who should own the files here
- TZ=Europe/Paris # Enter your timezone
volumes:
- /srv/dev-disk-by-label-secure/appdata/docker/urbackup/etc_default_urbackupsrv:/etc/default/urbackupsrv
- /srv/dev-disk-by-label-secure/appdata/docker/urbackup/var_urbackup:/var/urbackup
- /srv/dev-disk-by-label-secure/appdata/docker/urbackup/var_log:/var/log
- /srv/dev-disk-by-label-secure/backup/urbackup:/backups
# Uncomment the next line if you want to bind-mount the www-folder
- /srv/dev-disk-by-label-non-mirrored-store/urbackup-www:/usr/share/urbackup
network_mode: "host"
# Activate the following two lines for BTRFS support
cap_add:
- SYS_ADMIN
note that my server has been known to have memory corruption issues which were reproducible with DVFS (Kobol Helios64, arm64). I thought this issue was gone since I upped the big cpu voltage to 1.2V at all frequencies and I did not have any issue with any other software since then. But I do not completely exclude it.
But I don’t know how to sort out if the hardware could still be at fault or if it is a urbackup bug.
Though I don’t know what could cause this metadata error (and why it always ends up with size 114 instead of size 8 for hermes (amd64), and size 113 instead of size 8 on uruk (armhf 32bits). My previous memory errors where pretty random. Here the issue is always the same even though on different files.
I was not sure I had been able to reproduce the metadata error on hermes since it succeed once, even though I told you otherwise so I did another run and was able to reproduce (still size 114 instead of 8):
2024-10-15 20:50:45: Starting unscheduled full file backup...
2024-10-15 20:50:54: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:51:44: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:51:50: Create a readonly snapshot of '/var' in '/var/.urbackup_snaps/56b7c8c22d89332756b8bf236b199b63741b0d7bff7d91bf'
2024-10-15 20:51:50: Indexing of "backups" done. 1 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:51:50: Create a readonly snapshot of '/' in '//.urbackup_snaps/fca36d56e6c5ebdce40c4c653af813ea1cc178ec9c173061'
2024-10-15 20:51:50: Indexing of "hermes-etc" done. 903 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:51:50: Backing up "efi-boot" without snapshot.
2024-10-15 20:51:50: Indexing of "efi-boot" done. 94 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:51:50: Create a readonly snapshot of '/home' in '/home/.urbackup_snaps/90cfd36afb74941554590b1e5f89acd6df43431b8fd56e89'
2024-10-15 20:51:50: Indexing of "applications-home" done. 18929 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:51:50: Indexing of "vimdir" done. 391 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:51:50: Indexing of "vimrc" done. 1 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:51:50: hermes: Loading file list...
2024-10-15 20:51:50: hermes: Started loading files...
2024-10-15 20:51:56: Referencing snapshot on "hermes" for path "efi-boot" failed: FAILED
2024-10-15 20:52:35: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:53:25: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:54:15: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:55:05: Starting scheduled incremental file backup...
2024-10-15 20:55:06: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:55:48: Create a readonly snapshot of '/' in '//.urbackup_snaps/60f9d130145c7a9dc3a369447f98d99a3dbff2c0e2b0f578'
2024-10-15 20:55:48: Scanning for changed hard links on volume of "/"...
2024-10-15 20:55:48: Indexing of "gitlab-repositories" done. 12 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:55:48: Indexing of "backups" done. 2 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:55:48: Indexing of "debops-accounts" done. 101206 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:55:48: Indexing of "archives" done. 1 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:55:48: Indexing of "hercule-etc" done. 550 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:55:48: Indexing of "autopostgresqlbackup" done. 15 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:55:48: Indexing of "gitlab-etc" done. 4 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:55:48: Indexing of "gitlab-backups" done. 1 filesystem lookups 0 db lookups and 0 db updates
2024-10-15 20:55:48: hercule: Loading file list...
2024-10-15 20:55:49: hercule: Calculating file tree differences...
2024-10-15 20:55:53: hercule: Calculating tree difference size...
2024-10-15 20:55:54: hercule: Linking unchanged and loading new files...
2024-10-15 20:55:56: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:56:47: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:56:48: Files WAL file urbackup/backup_server_files.db-wal greater than 1000 MB. Doing full WAL checkpoint...
2024-10-15 20:56:49: Full checkpoint of urbackup/backup_server_files.db-wal done.
2024-10-15 20:57:37: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:58:28: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 20:59:19: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:00:09: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:01:00: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:01:50: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:02:41: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:03:31: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:04:22: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:05:12: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:05:24: WARNING: File "/backups/hermes/241015-2050/.hashes/applications-home/Programs/Eclipse/eclipse_modelling/configuration/org.eclipse.osgi/140/0/.cp/javadoc/org/eclipse/emf/cdo/transaction/class-use/CDOTransactionFinishedEvent.html" has wrong size. Should=8 is=114. Error writing metadata to file. -1
2024-10-15 21:05:24: ERROR: Error writing file metadata -1
2024-10-15 21:06:02: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:06:53: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:07:43: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:08:34: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:08:58: Files WAL file urbackup/backup_server_files.db-wal greater than 1000 MB. Doing full WAL checkpoint...
2024-10-15 21:09:07: Full checkpoint of urbackup/backup_server_files.db-wal done.
2024-10-15 21:09:24: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:10:15: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:11:05: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:11:56: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:12:46: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:13:37: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:14:27: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:15:18: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:16:08: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:16:58: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:17:49: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:18:01: WARNING: File "/backups/hermes/241015-2050/.hashes/applications-home/Programs/Unity/2019.3.2f1/Editor/Data/Documentation/Documentation/en/ScriptReference/ParticleSystem.MinMaxGradient.html" has wrong size. Should=8 is=114. Error writing metadata to file. -1
2024-10-15 21:18:01: ERROR: Error writing file metadata -1
2024-10-15 21:18:02: WARNING: File "/backups/hermes/241015-2050/.hashes/applications-home/Programs/Unity/2019.3.2f1/Editor/Data/Documentation/Documentation/en/ScriptReference/ParticleSystem.NoiseModule-octaveCount.html" has wrong size. Should=8 is=114. Error writing metadata to file. -1
2024-10-15 21:18:02: ERROR: Error writing file metadata -1
2024-10-15 21:18:02: WARNING: File "/backups/hermes/241015-2050/.hashes/applications-home/Programs/Unity/2019.3.2f1/Editor/Data/Documentation/Documentation/en/ScriptReference/ParticleSystem.NoiseModule-remapYMultiplier.html" has wrong size. Should=8 is=114. Error writing metadata to file. -1
2024-10-15 21:18:02: ERROR: Error writing file metadata -1
2024-10-15 21:18:05: Looking for old Sessions... 1 sessions
2024-10-15 21:18:39: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:19:30: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:20:20: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:20:26: Files WAL file urbackup/backup_server_files.db-wal greater than 1000 MB. Doing full WAL checkpoint...
2024-10-15 21:20:30: Full checkpoint of urbackup/backup_server_files.db-wal done.
2024-10-15 21:21:11: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:22:01: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:22:52: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:23:42: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:24:33: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:24:42: WARNING: File "/backups/hermes/241015-2050/.hashes/applications-home/Programs/Unity/2019.3.2f1/Editor/Data/Resources/PackageManager/ProjectTemplates/libcache/com.unity.template.universal-7.1.8/Artifacts/f9/f90a37af5767ba174b70be6f519f9ccc" has wrong size. Should=8 is=114. Error writing metadata to file. -1
2024-10-15 21:24:42: ERROR: Error writing file metadata -1
2024-10-15 21:24:42: WARNING: File "/backups/hermes/241015-2050/.hashes/applications-home/Programs/Unity/2019.3.2f1/Editor/Data/Resources/PackageManager/ProjectTemplates/libcache/com.unity.template.universal-7.1.8/Artifacts/fb/fb026ea0797b02da321e93bc3393caf3" has wrong size. Should=8 is=114. Error writing metadata to file. -1
2024-10-15 21:24:42: ERROR: Error writing file metadata -1
2024-10-15 21:25:06: Waiting for file transfers...
2024-10-15 21:25:09: Waiting for file hashing and copying threads...
2024-10-15 21:25:23: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:26:13: WARNING: File "/backups/hermes/241015-2050/.hashes/vimdir/bundle/syntastic/syntax_checkers/c/cppcheck.vim" has wrong size. Should=8 is=114. Error writing metadata to file. -1
2024-10-15 21:26:13: ERROR: Error writing file metadata -1
2024-10-15 21:26:13: WARNING: File "/backups/hermes/241015-2050/.hashes/vimdir/bundle/syntastic/syntax_checkers/c/gcc.vim" has wrong size. Should=8 is=114. Error writing metadata to file. -1
2024-10-15 21:26:13: ERROR: Error writing file metadata -1
2024-10-15 21:26:13: WARNING: File "/backups/hermes/241015-2050/.hashes/vimdir/bundle/syntastic/syntax_checkers/c/clang_tidy.vim" has wrong size. Should=8 is=114. Error writing metadata to file. -1
2024-10-15 21:26:13: ERROR: Error writing file metadata -1
2024-10-15 21:26:14: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:27:05: ERROR: Sending broadcast failed! (ipv6)
2024-10-15 21:27:14: WARNING: Not all folder metadata could be applied. Metadata was inconsistent.
2024-10-15 21:27:14: Writing new file list...
2024-10-15 21:27:16: All metadata was present
2024-10-15 21:27:16: Transferred 24.5831 GB - Average speed: 105.628 MBit/s
2024-10-15 21:27:25: ERROR: FATAL: Backup failed because of disk problems (see previous messages)
* Trying fc00:10::1:25...
* Connected to mail.prahal.homelinux.net (fc00:10::1) port 25 (#0)
< 220 argos.prahal.homelinux.net ESMTP
> EHLO helios64
< 250-argos.prahal.homelinux.net
< 250-PIPELINING
< 250-SIZE 101000000
< 250-STARTTLS
< 250-ENHANCEDSTATUSCODES
< 250-8BITMIME
< 250-SMTPUTF8
< 250 CHUNKING
> STARTTLS
< 220 2.0.0 Ready to start TLS
* found 387 certificates in /etc/ssl/certs
* SSL connection using TLS1.2 / ECDHE_RSA_AES_256_GCM_SHA384
* server certificate verification SKIPPED
* server certificate status verification SKIPPED
* common name: prahal.homelinux.net (matched)
* server certificate expiration date OK
* server certificate activation date OK
* certificate public key: RSA
* certificate version: #3
* subject: CN=prahal.homelinux.net
* start date: Fri, 09 Jun 2023 20:38:20 GMT
* expire date: Mon, 08 Jun 2026 20:38:20 GMT
* issuer: O=Prahal,OU=Domain CA
> EHLO helios64
< 250-argos.prahal.homelinux.net
< 250-PIPELINING
< 250-SIZE 101000000
< 250-AUTH PLAIN LOGIN
< 250-AUTH=PLAIN LOGIN
< 250-ENHANCEDSTATUSCODES
< 250-8BITMIME
< 250-SMTPUTF8
< 250 CHUNKING
> MAIL FROM:<root@helios64.prahal.homelinux.net>
< 250 2.1.0 Ok
> RCPT TO:<root@argos.prahal.homelinux.net>
< 250 2.1.5 Ok
> DATA
< 354 End data with <CR><LF>.<CR><LF>
< 250 2.0.0 Ok: queued as 4XSkdC6ynLz9rpfh
* Connection #0 to host mail.prahal.homelinux.net left intact
2024-10-15 21:27:28: Time taken for backing up client hermes: 36m 42s
2024-10-15 21:27:28: ERROR: Backup failed
2024-10-15 21:27:28: Updating statistics...
2024-10-15 21:27:28: Updating image stats...
2024-10-15 21:27:28: Updating file statistics...
2024-10-15 21:27:29: WARNING: Exponential backoff: Waiting at least 40m before next file backup
2024-10-15 21:27:29: server_prepare_hash Thread finished (exit)
2024-10-15 21:27:29: server_hash Thread finished - normal
2024-10-15 21:27:29: server_prepare_hash Thread finished (exit)
2024-10-15 21:27:29: server_prepare_hash Thread finished (exit)
2024-10-15 21:27:29: server_prepare_hash Thread finished (exit)
2024-10-15 21:27:29: server_prepare_hash Thread finished (exit)
2024-10-15 21:27:29: server_hash Thread finished - normal
2024-10-15 21:27:29: server_prepare_hash Thread finished (exit)
2024-10-15 21:27:29: server_hash Thread finished - normal
2024-10-15 21:27:29: server_hash Thread finished - normal
2024-10-15 21:27:29: server_prepare_hash Thread finished (exit)
2024-10-15 21:27:29: server_hash Thread finished - normal
2024-10-15 21:27:29: server_hash Thread finished - normal
2024-10-15 21:27:29: server_hash Thread finished - normal
2024-10-15 21:27:29: server_hash Thread finished - normal
2024-10-15 21:27:29: server_prepare_hash Thread finished (exit)
2024-10-15 21:27:29: server_hash Thread finished - normal
2024-10-15 21:27:29: server_prepare_hash Thread finished (exit)
2024-10-15 21:27:29: server_prepare_hash Thread finished (exit)
2024-10-15 21:27:29: server_hash Thread finished - normal
I have in the server settings for Local/passive clients:
Encrypt local/passive transfers: checked
Compress local/passive transfers: checked
And now that I think about it, as I use docker bind mount volumes for storage, the docker version might matter:
apt policy docker-ce
docker-ce:
Installé : 5:26.1.4-1~debian.12~bookworm
Candidat : 5:26.1.4-1~debian.12~bookworm
Table de version :
*** 5:26.1.4-1~debian.12~bookworm 100
100 /var/lib/dpkg/status
apt policy docker-compose-plugin
docker-compose-plugin:
Installé : 2.27.1-1~debian.12~bookworm
Candidat : 2.27.1-1~debian.12~bookworm
Table de version :
*** 2.27.1-1~debian.12~bookworm 100
100 /var/lib/dpkg/status
Mind that docker was supposed to be managed by OpenMediaVault (my belief is it was before) but it seems the docker-ce apt repository is not enabled anymore. Could be that I missed something while migrating from OMV6 to bookworm/OMV7.
I now check Docker-repo checkbox in omv-extras OMV web UI and apply.
Issue is still there after a reboot (in case docker bind mount volumes required a restart to get docker upgrade potential fixups). Kernel after reboot was 6.11.3-edge-rockchip64.
2024-10-16 02:52:37: Starting unscheduled full file backup...
2024-10-16 02:52:42: Create a readonly snapshot of '/var' in '/var/.urbackup_snaps/977d57ea485537fd6b04fbc192373d5d08546ffcfa261063'
2024-10-16 02:52:42: Indexing of "backups" done. 1 filesystem lookups 0 db lookups and 0 db updates
2024-10-16 02:52:42: Create a readonly snapshot of '/' in '//.urbackup_snaps/7d535094227c71fe92f54def57d52a0a85529306fcf116ec'
2024-10-16 02:52:42: Indexing of "hermes-etc" done. 903 filesystem lookups 0 db lookups and 0 db updates
2024-10-16 02:52:42: Backing up "efi-boot" without snapshot.
2024-10-16 02:52:42: Indexing of "efi-boot" done. 94 filesystem lookups 0 db lookups and 0 db updates
2024-10-16 02:52:42: Create a readonly snapshot of '/home' in '/home/.urbackup_snaps/23098cdd518c9fb570a0a2fca0185b71780122414dcac3ae'
2024-10-16 02:52:42: Indexing of "applications-home" done. 18929 filesystem lookups 0 db lookups and 0 db updates
2024-10-16 02:52:42: Indexing of "vimdir" done. 391 filesystem lookups 0 db lookups and 0 db updates
2024-10-16 02:52:42: Indexing of "vimrc" done. 1 filesystem lookups 0 db lookups and 0 db updates
2024-10-16 02:52:42: hermes: Loading file list...
2024-10-16 02:52:42: hermes: Started loading files...
2024-10-16 02:52:45: Referencing snapshot on "hermes" for path "efi-boot" failed: FAILED
2024-10-16 03:02:26: Files WAL file urbackup/backup_server_files.db-wal greater than 1000 MB. Doing full WAL checkpoint...
2024-10-16 03:02:27: Full checkpoint of urbackup/backup_server_files.db-wal done.
2024-10-16 03:07:54: WARNING: File "/backups/hermes/241016-0252/.hashes/applications-home/Programs/Unity/2018.4.17f1/Editor/Data/Documentation/Documentation/en/ScriptReference/Experimental.UIElements.TemplateContainer.UxmlTraits-uxmlChildElementsDescription.html" has wrong size. Should=8 is=114. Error writing metadata to file. -1
2024-10-16 03:07:54: ERROR: Error writing file metadata -1
2024-10-16 03:11:36: Looking for old Sessions... 1 sessions
2024-10-16 03:11:41: Files WAL file urbackup/backup_server_files.db-wal greater than 1000 MB. Doing full WAL checkpoint...
2024-10-16 03:11:46: Full checkpoint of urbackup/backup_server_files.db-wal done.
2024-10-16 03:17:08: Starting scheduled incremental file backup...
2024-10-16 03:17:20: Create a readonly snapshot of '/' in '//.urbackup_snaps/f55f05b37edc9f984d7b45997ac1cf65712945e54f6b8840'
2024-10-16 03:17:20: Scanning for changed hard links on volume of "/"...
2024-10-16 03:17:20: Indexing of "cyclope-etc" done. 1161 filesystem lookups 0 db lookups and 0 db updates
2024-10-16 03:17:20: Create a readonly snapshot of '/home' in '/home/.urbackup_snaps/70118dab3e608af45425a7a0e84ff0ca009a0cbfb9c0e58e'
2024-10-16 03:17:20: Scanning for changed hard links on volume of "/home"...
2024-10-16 03:17:20: Indexing of "applications-home" done. 8896 filesystem lookups 0 db lookups and 0 db updates
2024-10-16 03:17:20: Indexing of "backups" done. 3 filesystem lookups 0 db lookups and 0 db updates
2024-10-16 03:17:20: Indexing of "calibre_plugins" done. 13 filesystem lookups 0 db lookups and 0 db updates
2024-10-16 03:17:20: Indexing of "tokenfiles" done. 1 filesystem lookups 0 db lookups and 0 db updates
2024-10-16 03:17:20: Indexing of "vimrc" done. 1 filesystem lookups 0 db lookups and 0 db updates
2024-10-16 03:17:20: Indexing of "vimdir" done. 612 filesystem lookups 0 db lookups and 0 db updates
2024-10-16 03:17:20: Indexing of "cyclope-nixnote2-evernote-backup" done. 17 filesystem lookups 0 db lookups and 0 db updates
2024-10-16 03:17:20: Indexing of "kodi-userdata" done. 77 filesystem lookups 0 db lookups and 0 db updates
2024-10-16 03:17:20: Indexing of "usr-local-grub-images" done. 1 filesystem lookups 0 db lookups and 0 db updates
2024-10-16 03:17:20: cyclope: Loading file list...
2024-10-16 03:17:20: cyclope: Calculating file tree differences...
2024-10-16 03:17:21: Waiting for file transfers...
2024-10-16 03:17:21: cyclope: Calculating tree difference size...
2024-10-16 03:17:22: cyclope: Linking unchanged and loading new files...
2024-10-16 03:17:23: Waiting for file hashing and copying threads...
2024-10-16 03:17:35: Files WAL file urbackup/backup_server_files.db-wal greater than 1000 MB. Doing full WAL checkpoint...
2024-10-16 03:17:36: Full checkpoint of urbackup/backup_server_files.db-wal done.
2024-10-16 03:17:49: Waiting for file transfers...
2024-10-16 03:17:49: Waiting for file hashing and copying threads...
2024-10-16 03:18:24: WARNING: Not all folder metadata could be applied. Metadata was inconsistent.
2024-10-16 03:18:24: Writing new file list...
2024-10-16 03:18:26: All metadata was present
2024-10-16 03:18:26: Transferred 24.5831 GB - Average speed: 142.536 MBit/s
2024-10-16 03:18:27: ERROR: FATAL: Backup failed because of disk problems (see previous messages)
I am trying to grep filelist.ub for a file that failed just after the backup failed. I hope to have the results soon.
ABout the debug logllve, I had it set for server but indeed not client. I have an issue for the server that the urbackup.log does not have the DEBUG logs inside even though debug log seems to have been properly set, this as I have debug logs in the “show journals” urbackup server web UI. Is this a bug?
My server /etc/default/urbackup (from insde the urbackup docker container) is a bind mount to /srv/dev-disk-by-label-secure/appdata/docker/urbackup/etc_default_urbackupsrv and have LOGLEVEL=“debug” and LOGFILE=“/var/log/urbackup.log” in it.
I have check from inside the urbackup docker container taht the file is at its proper location inside the container and is readable by the user the urbackup server is running as:
phn@helios64:~$ docker exec -u urbackup -ti urbackup bash
urbackup@helios64:/$ cat /etc/default/urbackupsrv
# Defaults for urbackupsrv initscript
# sourced by /etc/init.d/urbackupsrv and /lib/systemd/system/urbackup-server.service
# installed at /etc/default/urbackupsrv by the maintainer scripts
#
# This is parsed as a key=value file
#
#Port for FastCGI requests
FASTCGI_PORT=55413
#Enable internal HTTP server
# Required for serving web interface without FastCGI
# and for websocket connections from client
HTTP_SERVER="true"
#Port for the web interface
#(if internal HTTP server is enabled)
HTTP_PORT=55414
#Bind HTTP server to localhost only
HTTP_LOCALHOST_ONLY=false
#Bind Internet port to localhost only
INTERNET_LOCALHOST_ONLY=false
#log file name
LOGFILE="/var/log/urbackup.log"
#Either debug,warn,info or error
LOGLEVEL="debug"
#Temporary file directory
# -- this may get very large depending on the advanced settings
DAEMON_TMPDIR="/tmp"
#Tmp file directory for sqlite temporary tables.
#You might want to put the databases on another filesystem than the other temporary files.
#Default is the same as DAEMON_TMPDIR
SQLITE_TMPDIR=""
#Interfaces from which to send broadcasts. (Default: all).
#Comma separated -- e.g. "eth0,eth1"
BROADCAST_INTERFACES="bond0"
#User the urbackupsrv process runs as
USER="urbackup"
But I have other weird things, even though I have BROADCAST_INTERFACES=“bond0”, I see broadcast for all interfaces in the urbackup.log
2024-10-16 18:16:28: Broadcasting on ipv4 interface bond0 addr 192.168.10.172
2024-10-16 18:16:28: Broadcasting on ipv4 interface cni-podman0 addr 10.88.0.1
2024-10-16 18:16:28: Broadcasting on ipv4 interface docker0 addr 172.17.0.1
2024-10-16 18:16:28: Broadcasting on ipv4 interface br-bf3522ece73d addr 172.18.0.1
2024-10-16 18:16:28: Broadcasting on ipv4 interface br-c887f93ed62c addr 172.21.0.1
2024-10-16 18:16:28: Broadcasting on ipv4 interface br-d76d002ac358 addr 172.22.0.1
2024-10-16 18:16:28: Broadcasting on ipv6 interface bond0 addr fc00:10::3cd0:5dff:fec2:36e4
2024-10-16 18:16:28: Broadcasting on ipv6 interface bond0 addr fe80::3cd0:5dff:fec2:36e4
2024-10-16 18:16:28: Broadcasting on ipv6 interface veth2b650f7b addr fe80::e862:2aff:fe9c:eef1
2024-10-16 18:16:28: Broadcasting on ipv6 interface br-bf3522ece73d addr fe80::42:a0ff:fea3:b1ed
2024-10-16 18:16:28: Broadcasting on ipv6 interface br-c887f93ed62c addr fe80::42:3bff:fe9c:25cc
2024-10-16 18:16:28: Broadcasting on ipv6 interface br-d76d002ac358 addr fe80::42:51ff:fe04:cd6c
2024-10-16 18:16:28: Broadcasting on ipv6 interface veth4341945 addr fe80::80ea:3bff:fe0d:40ac
2024-10-16 18:16:28: Broadcasting on ipv6 interface vethd739ba7 addr fe80::6834:69ff:fe4e:8d30
2024-10-16 18:16:28: Broadcasting on ipv6 interface veth8f5daf6 addr fe80::8c80:cff:fe53:6013
2024-10-16 18:16:28: Broadcasting on ipv6 interface vethf273e1e addr fe80::9c8f:12ff:fef2:24ed
But I indeed have debug logs in the client logs when I also set the loglevel to debug in /etc/default/urbackupclient on the client (not a docker container, raw service).
I think I will be able to provide client debug logs, but I might not for server debug logs.
I confirm that with beta number of parallel works to compute by the server for each saved file set to 1 and beta number of parallel works to compute on the server for the same saved file set to 1 the issue is gone.
I was close as I had seen a comment stating a fix like this one in Server 2.5.22/Client 2.5.16 - #12 by BleoFile backups are failing when Beta: Number of parallel file* are set to anything more than 1, |WARNING |Not all folder metadata could be applied. Metadata was inconsistent.| but the error message pasted was only the last error, he asked for help, and there were no followups to this clue. Though I only found it a few weeks ago. Hard to tell if I had been able to nail this issue with just my previous finding (and it was a short hint in a lot of notes). In fact, checking, I found this hint the day I opened this thread!
Thanks a lot. I only have one client left to test, but all other four succeeded reproducibly a few times already.