Server:
UrBackup Server v2.5.28.0
FreeBSD 13.1-RELEASE-p2 running in a TrueNAS jail
Client:
UrBackup Client Backend v2.5.22.0
Ubuntu 22.04.1 LTS
The client contains approximately 6 million files, for 13TB of data, and yesterday when I had it run a full file backup it took 284 minutes to index everything before starting the transfer. The transfer was quick, because only around 24GB had to be sent.
Today it is running an incremental file backup and while it only hashed changed files in the rootfs directory, it appears to be hashing every single file, changed or not, in the /mnt/storage directory where the bulk of the files are. I had previously turned parallel file hashing off to troubleshoot a different issue, which I think was resolved by running the full file backup
Hashes for all the files larger than 2047 bytes do appear to be in the filelist.ub file, but it appears to be building a filelist_new_0.ub file with all the same files and hashes now, re-hashing everything it did yesterday. That’s not the expected behavior, is it? It doesn’t seem to be happening on my other urbackup server and clients. (This server is dedicated to this one system.)
Client log file:
2023-02-18 07:59:25: Looking for old Sessions... 0 sessions
2023-02-18 08:00:17: ClientService cmd: PONG
2023-02-18 08:01:17: ClientService cmd: PONG
2023-02-18 08:02:17: ClientService cmd: PONG
2023-02-18 08:03:17: ClientService cmd: PONG
2023-02-18 08:04:17: ClientService cmd: PONG
2023-02-18 08:05:17: ClientService cmd: PONG
2023-02-18 08:06:17: ClientService cmd: PONG
2023-02-18 08:07:17: ClientService cmd: PONG
2023-02-18 08:07:42: Started connection to SERVICE_COMMANDS
2023-02-18 08:07:42: ClientService cmd: #IEuXoVpSu4Wwbk0OFXfqN#2PING RUNNING pc_done=&status_id=8&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=Fg9gchFToF0Xgg8V55Wz
2023-02-18 08:07:42: Internet server auth failed. Error: Token not found
2023-02-18 08:07:42: InternetClient: Had an auth error
2023-02-18 08:07:42: Started connection to SERVICE_COMMANDS
2023-02-18 08:07:42: ClientService cmd: #IEuXoVpSu4Wwbk0OFXfqN#3START BACKUP group=0&running_jobs=1&sha=528&with_permissions=1&with_scripts=1&with_orig_path=1&with_sequence=1&with_proper_symlinks=1&status_id=8&async=1#token=Fg9gchFToF0Xgg8V55Wz
2023-02-18 08:07:42: Removing VSS log data...
2023-02-18 08:07:42: Final path: /
2023-02-18 08:07:42: Final path: /mnt/storage
2023-02-18 08:07:42: Final path: /boot
2023-02-18 08:07:42: rc=0 hasError=true state=0
2023-02-18 08:07:42: SERVICE_COMMANDS finished
2023-02-18 08:07:42: Script list at "/usr/local/etc/urbackup/scripts/list" does not exist. Skipping.
2023-02-18 08:07:42: Script "/usr/local/etc/urbackup/prefilebackup" does not exist
2023-02-18 08:07:42: Final path: /
2023-02-18 08:07:42: Final path: /mnt/storage
2023-02-18 08:07:42: Final path: /boot
2023-02-18 08:07:42: Creating shadowcopy of "rootfs" in indexDirs()
2023-02-18 08:07:42: Started connection to SERVICE_COMMANDS
2023-02-18 08:07:42: ClientService cmd: #IEuXoVpSu4Wwbk0OFXfqN#WAIT FOR INDEX async_id=35d2c9f7e6f64431cd7c3b7005f416c8#token=Fg9gchFToF0Xgg8V55Wz
2023-02-18 08:07:42: Wait for async index 35d2c9f7e6f64431cd7c3b7005f416c8
2023-02-18 08:07:42: Reducing COW size <172.04 GiB down to maximum usable size 100.39 GiB.
2023-02-18 08:07:42: Logical volume "urbackup_snap_23c58514a33c8e8170130eff538eb040e1f4455f5c8185c2" created.
2023-02-18 08:07:42: Shadowcopy path: /mnt/urbackup_snaps/23c58514a33c8e8170130eff538eb040e1f4455f5c8185c2
2023-02-18 08:07:42: done.
2023-02-18 08:07:42: Removing deleted directories from index for "/"...
2023-02-18 08:07:42: Scanning for changed hard links on volume of "/"...
2023-02-18 08:07:42: Disabling CBT on volume ""
2023-02-18 08:07:42: Indexing "rootfs"...
2023-02-18 08:07:42: Not following symlink "/etc/mtab" because symlink target at "/proc/5489/mounts" is excluded
2023-02-18 08:07:42: Not following symlink "/etc/resolv.conf" because symlink target at "/run/systemd/resolve/stub-resolv.conf" is excluded
2023-02-18 08:07:42: Hashing file "/mnt/urbackup_snaps/23c58514a33c8e8170130eff538eb040e1f4455f5c8185c2/etc/ld.so.cache"
2023-02-18 08:07:42: Hashing file "/mnt/urbackup_snaps/23c58514a33c8e8170130eff538eb040e1f4455f5c8185c2/etc/lvm/archive/hdd-raid10_00030-1447771065.vg"
2023-02-18 08:07:42: Hashing file "/mnt/urbackup_snaps/23c58514a33c8e8170130eff538eb040e1f4455f5c8185c2/etc/lvm/archive/ubuntu-vg_00030-473214264.vg"
2023-02-18 08:07:43: Not following symlink "/etc/systemd/system/sudo.service" because symlink target at "/dev/null" is excluded
2023-02-18 08:07:50: Hashing file "/mnt/urbackup_snaps/23c58514a33c8e8170130eff538eb040e1f4455f5c8185c2/opt/sqlbackup/BABY.sql.gz"
[... a bunch of files which did change since the last backup omitted here ...]
2023-02-18 08:08:22: Hashing file "/mnt/urbackup_snaps/23c58514a33c8e8170130eff538eb040e1f4455f5c8185c2/var/log/unattended-upgrades/unattended-upgrades.log"
2023-02-18 08:08:22: Indexing of "rootfs" done. 16323 filesystem lookups 0 db lookups and 109 db updates
2023-02-18 08:08:22: Creating shadowcopy of "storage" in indexDirs()
2023-02-18 08:08:23: Logical volume "urbackup_snap_83a995474e906b1dc33503ed38632836b5e0a8e5d415fb0a" created.
2023-02-18 08:08:23: Shadowcopy path: /mnt/urbackup_snaps/83a995474e906b1dc33503ed38632836b5e0a8e5d415fb0a
2023-02-18 08:08:23: done.
2023-02-18 08:08:23: Removing deleted directories from index for "/mnt/storage"...
2023-02-18 08:08:23: Scanning for changed hard links on volume of "/mnt/storage"...
2023-02-18 08:08:23: Disabling CBT on volume "/mnt/storage"
2023-02-18 08:08:23: Indexing "storage"...
2023-02-18 08:08:23: Hashing file "/mnt/urbackup_snaps/83a995474e906b1dc33503ed38632836b5e0a8e5d415fb0a/ImageCollection/burkeFooter.php"
2023-02-18 08:08:23: Hashing file "/mnt/urbackup_snaps/83a995474e906b1dc33503ed38632836b5e0a8e5d415fb0a/ImageCollection/burkeMainNav.php"
2023-02-18 08:08:23: Hashing file "/mnt/urbackup_snaps/83a995474e906b1dc33503ed38632836b5e0a8e5d415fb0a/ImageCollection/burkeSubNav.php"
2023-02-18 08:08:23: Hashing file "/mnt/urbackup_snaps/83a995474e906b1dc33503ed38632836b5e0a8e5d415fb0a/ImageCollection/checklist.php"
[... none of those files has changed since the last backup, for example:
File: /mnt/urbackup_snaps/83a995474e906b1dc33503ed38632836b5e0a8e5d415fb0a/ImageCollection/checklist.php
Size: 2349 Blocks: 8 IO Block: 4096 regular file
Device: fd07h/64775d Inode: 172228927 Links: 1
Access: (0664/-rw-rw-r--) Uid: ( 1001/ pnwhweb) Gid: ( 1001/ pnwhweb)
Access: 2023-01-09 14:40:06.339666654 -0800
Modify: 2018-11-05 15:15:30.801522100 -0800
Change: 2023-01-27 10:40:25.460367155 -0800
Birth: 2023-01-09 14:40:06.339666654 -0800
...]
2023-02-18 08:08:42: Hashing file "/mnt/urbackup_snaps/83a995474e906b1dc33503ed38632836b5e0a8e5d415fb0a/ImageCollection/imagecollection/wtu0/tb/wtu000874.jpg"
2023-02-18 08:08:42: ClientService cmd: #IEuXoVpSu4Wwbk0OFXfqN#2PING RUNNING pc_done=&eta_ms=415215629&status_id=8&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=Fg9gchFToF0Xgg8V55Wz
2023-02-18 08:08:42: Hashing file "/mnt/urbackup_snaps/83a995474e906b1dc33503ed38632836b5e0a8e5d415fb0a/ImageCollection/imagecollection/wtu0/tb/wtu000875.jpg"
[... etc ...]
Thanks for any insight you might offer, and please let me know if there’s other information I can provide which would help.