Full FIle Backup

[ttyllc]

Im trying to do a full file backup of about 1Tb over the internet.
evrything works fine except 2 large files that keep failiing with the following error.

These files are all on a different drive/partition. Is it possible that DattoDB is not working for that drive?

I tried this twice and it took a week each time

This is the errors I get:

ERROR: Client calculated hash of “/urbackup/…/…/…/Archive.pst” differs from server calculated hash. This may be caused by a bug or by random bit flips on the client or server hard disk. Failing backup. (Hash: tree-sparse, client hash: cfL/7W03LWQg58owZqfjfjiRizGln9hGL3kyKGv2UAmw4r+5SdtMvxeByrbXojiauLyUwV2aIyiJwjSdph1n/Q==, server hash: DTawg7/mxC8MZn5yesNO41BRPo33MNFqj/GPHLCEx55Br9dMaEu0UlZmv6/Xrwd3P05ZFMArryWN/sTNLQFOFg==)
ERROR: Client calculated hash of “/urbackup/…/…/Arvhive2.pst” differs from server calculated hash. This may be caused by a bug or by random bit flips on the client or server hard disk. Failing backup. (Hash: tree-sparse, client hash: FgJ8+JhhjSlJnn05907QdwcoOWpp0vnd2qWqecX7ab4M4rTTyh82z09+IgAk5dtL8t+sheJWw1va/uYjxOhFfg==, server hash: 93EPfJs9lxdrjN80RHiwSpWDabnpRyhcWEqP7nq4/RtNl5nmagyBILJyJ5xl6W83A5Di8GpkEI1BBt/cTmmB6Q==)
WARNING: Not all folder metadata could be applied. Metadata was inconsistent.
ERROR: Fatal error during backup. Backup not completed
ERROR: FATAL: Backup failed because of disk problems (see previous messages)

[uroni]

You could look at the client side debug log file to see if it is backed up via snapshot?

If a file is backed up without snapshot while the server thinks it is backed up via snapshot and the file changes during backup you’ll see those errors, yes.

[ttyllc]

I turned on debug logging for this client, It still fails and it seems to me that the snapshot IS indeed working for taht partition

The files that fail are super large .pst (outlook files)

What do you think?
This is the relevant parts of the log file (The start of a new one and the end of failing previous one):

2021-09-11 10:13:20: rc=0 hasError=true state=0
2021-09-11 10:13:20: SERVICE_COMMANDS finished
2021-09-11 10:13:38: ClientService cmd: PONG
2021-09-11 10:13:38: rc=0 hasError=true state=3
2021-09-11 10:13:38: SERVICE_COMMANDS finished
2021-09-11 10:13:38: Started connection to SERVICE_COMMANDS
2021-09-11 10:13:38: ClientService cmd: #IY9LV1V6khXi4sQCkGEbb#1CHANNEL capa=196381&token=pZlMin97GzUM8i5jEWTf&restore_version=1&virtual_client=
2021-09-11 10:13:38: New channel: Number of Channels: 1
2021-09-11 10:13:44: Started connection to SERVICE_COMMANDS
2021-09-11 10:13:44: ClientService cmd: #IY9LV1V6khXi4sQCkGEbb#2PING RUNNING pc_done=&status_id=25&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=pZlMin97GzUM8i5jEWTf
2021-09-11 10:13:44: Started connection to SERVICE_COMMANDS
2021-09-11 10:13:44: ClientService cmd: #IY9LV1V6khXi4sQCkGEbb#3START FULL 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=25&async=1#token=pZlMin97GzUM8i5jEWTf
2021-09-11 10:13:44: Async index d0835e3ff690ea033d643349d4eefb37
2021-09-11 10:13:44: Removing VSS log data…
2021-09-11 10:13:44: Final path: /srv/dev-disk-by-label-DataA1RAID6
2021-09-11 10:13:44: rc=0 hasError=true state=0
2021-09-11 10:13:44: SERVICE_COMMANDS finished
2021-09-11 10:13:44: Script list at “/usr/local/etc/urbackup/scripts/list” does not exist. Skipping.
2021-09-11 10:13:44: Deleting files… doing full index…
2021-09-11 10:13:44: Started connection to SERVICE_COMMANDS
2021-09-11 10:13:44: ClientService cmd: #IY9LV1V6khXi4sQCkGEbb#WAIT FOR INDEX async_id=d0835e3ff690ea033d643349d4eefb37#token=pZlMin97GzUM8i5jEWTf
2021-09-11 10:13:44: Wait for async index d0835e3ff690ea033d643349d4eefb37
…
2021-09-11 10:16:38: Script “/usr/local/etc/urbackup/prefilebackup” does not exist
2021-09-11 10:16:38: Final path: /srv/dev-disk-by-label-DataA1RAID6
2021-09-11 10:16:38: Creating shadowcopy of “dev-disk-by-label-DataA1RAID6” in indexDirs()
…
2021-09-11 10:17:13: Snapshotting device /dev/sdb1 via dattobd…
2021-09-11 10:17:13: Using /dev/datto0…
2021-09-11 10:17:13: Mounting /dev/mapper/wsnap-e8b88f23e2df6e0e52e883736056150203878282dca08b50…
2021-09-11 10:17:13: Shadowcopy path: /mnt/urbackup_snaps/e8b88f23e2df6e0e52e883736056150203878282dca08b50
2021-09-11 10:17:13: done.
2021-09-11 10:17:13: Indexing “dev-disk-by-label-DataA1RAID6”…

2021-09-11 10:13:44: ClientService cmd: #IY9LV1V6khXi4sQCkGEbb#3START FULL BACKUP group=0&running_jobs=1&sha=528&with_permissions=1&with_scripts=1&with_orig_path=1&with_sequence=1&with_proper_symlin
ks=1&status_id=25&async=1#token=pZlMin97GzUM8i5jEWTf
2021-09-11 10:13:44: Async index d0835e3ff690ea033d643349d4eefb37
2021-09-11 10:13:44: Removing VSS log data…
2021-09-11 10:13:44: Final path: /srv/dev-disk-by-label-DataA1RAID6
2021-09-11 10:13:44: rc=0 hasError=true state=0
2021-09-11 10:13:44: SERVICE_COMMANDS finished
2021-09-11 10:13:44: Script list at “/usr/local/etc/urbackup/scripts/list” does not exist. Skipping.
2021-09-11 10:13:44: Deleting files… doing full index…
2021-09-11 10:13:44: Started connection to SERVICE_COMMANDS
2021-09-11 10:13:44: ClientService cmd: #IY9LV1V6khXi4sQCkGEbb#WAIT FOR INDEX async_id=d0835e3ff690ea033d643349d4eefb37#token=pZlMin97GzUM8i5jEWTf
2021-09-11 10:13:44: Wait for async index d0835e3ff690ea033d643349d4eefb37

2021-09-11 10:16:38: Script “/usr/local/etc/urbackup/prefilebackup” does not exist
2021-09-11 10:16:38: Final path: /srv/dev-disk-by-label-DataA1RAID6
2021-09-11 10:16:38: Creating shadowcopy of “dev-disk-by-label-DataA1RAID6” in indexDirs()

2021-09-11 10:17:13: Snapshotting device /dev/sdb1 via dattobd…
2021-09-11 10:17:13: Using /dev/datto0…
2021-09-11 10:17:13: Mounting /dev/mapper/wsnap-e8b88f23e2df6e0e52e883736056150203878282dca08b50…
2021-09-11 10:17:13: Shadowcopy path: /mnt/urbackup_snaps/e8b88f23e2df6e0e52e883736056150203878282dca08b50
2021-09-11 10:17:13: done.
2021-09-11 10:17:13: Indexing “dev-disk-by-label-DataA1RAID6”…

[BrainWaveCC]

Are those archive*.pst files open in anyone’s outlook application?

If they are open, they will be locked, and you will not get a good snapshot of them. Plus, Outlook will make changes to them.

[ttyllc]

Im not sure I understand.
Isnt that why I use datto (likle windows shadow copy)?

[BrainWaveCC]

PST files are a known problematic entity for backups, and have been for years (decades, really).

Check out this thread for just one example of the issues/complaints: Is Outlook compatible with Volume Shadow Copy Service? - Data Backup - Spiceworks

If the file is open in someone’s Outlook app, the timestamp on the PST will keep getting updated, which will make it seem like it is steadily changing.

Newer versions of Outlook (such as 2016 or 2019) should be able to backup a PST via VSS, but I haven’t seen an article from Microsoft to substantiate this as yet.

[uroni]

Can’t you upload/post a complete log, not just the start of one? Also, what client version are you using?

[ttyllc]

Sure, no problem. Just for testing I excluded those large pst files, but I still have large VHDs that fail the backup.

The debug log has all the hashing and filenames in it, can it be posted on the forum?

[uroni]

@ttyllc

The debug log has all the hashing and filenames in it, can it be posted on the forum?

Depends on if you want everyone know your filenames and sizes Alternatives are described here:

Having problems with UrBackup? Please read before posting

First of all: Sorry your are having problems with UrBackup. We strive to keep UrBackup bug free, but as with every software project this is a difficult endeavour, which is dependant on the community reporting potential problems. Before you post for help or describe the problem you should check the following: Is there already an ongoing discussion about this problem? Use the forum search functionality. Check the manual and FAQ UrBackup is Open Source. You may be able to fix the problem and p…

[ttyllc]

Unless I can send it on private message for you to look at.

There is just so many files the backup is huge 1.2 TB of files and the debug log will be pretty large too of course

[ttyllc]

I finally run the failing backup and collected all the debug backup log. The total is 580MB of stuff. how can I share that?

[ttyllc]

I sent an email to bugreports@urbackup.org that has the log files. thank you so much for looking into this

[uroni]

Ok, so it uses the snapshot and the simplest transfer method (full file transfer).

Is there anything in dmesg w.r.t. dattobd after such a backup?

[ttyllc]

im not sure what w. r. t. is … but here is the dmesg output for that client:

Not sure about the relevant events (the USB plug and unplug is normal)
…

[21460.596986] loop: module loaded
[21460.664246] device-mapper: uevent: version 1.0.3
[21460.664428] device-mapper: ioctl: 4.39.0-ioctl (2018-04-03) initialised: dm-devel@redhat.com
[21462.497589] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[21929.227804] perf: interrupt took too long (2507 > 2500), lowering kernel.perf_event_max_sample_rate to 79750
[22333.697917] perf: interrupt took too long (3135 > 3133), lowering kernel.perf_event_max_sample_rate to 63750
[22507.821447] omv-engined[15835]: segfault at 7f0464856245 ip 0000559ca83d959f sp 00007fff3d5b5f70 error 4 in php7.0[559ca816c000+3aa000]
[22507.821457] Code: a7 00 00 00 e8 1a 91 e6 ff 66 90 48 83 c3 20 49 39 dc 0f 84 18 ff ff ff 48 8b 45 30 48 89 df ff d0 48 8b 7b 18 48 85 ff 74 e1 <0f> b6 57 05 f6 c2 02 75 d8 83 2f 01 75 d3 eb c1 90 48 83 c3 20 e8
[28197.492040] perf: interrupt took too long (4178 > 3918), lowering kernel.perf_event_max_sample_rate to 47750
[80109.426912] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[241190.711882] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[332960.923716] SUPR0GipMap: fGetGipCpu=0x3
[332961.230049] vboxdrv: 0000000063e44edc VMMR0.r0
[332961.659332] vboxdrv: 00000000b09e8e3c VBoxDDR0.r0
[332961.765813] VBoxNetFlt: attached to ‘eno1’ / 78:2b:cb:5d:3f:74
[332961.796262] device eno1 entered promiscuous mode
[332962.758119] VBoxNetFlt: attached to ‘eno2’ / 78:2b:cb:5d:3f:75
[332962.789415] device eno2 entered promiscuous mode
[347262.181497] perf: interrupt took too long (5257 > 5222), lowering kernel.perf_event_max_sample_rate to 38000
[448813.397208] omv-engined[12878]: segfault at 7f0464856245 ip 0000559ca83d959f sp 00007fff3d5b5f70 error 4 in php7.0[559ca816c000+3aa000]
[448813.397218] Code: a7 00 00 00 e8 1a 91 e6 ff 66 90 48 83 c3 20 49 39 dc 0f 84 18 ff ff ff 48 8b 45 30 48 89 df ff d0 48 8b 7b 18 48 85 ff 74 e1 <0f> b6 57 05 f6 c2 02 75 d8 83 2f 01 75 d3 eb c1 90 48 83 c3 20 e8
[595276.205429] usb 8-1: USB disconnect, device number 2
[595285.012065] usb 8-1: new high-speed USB device number 4 using ehci-pci
[595285.170692] usb 8-1: New USB device found, idVendor=1058, idProduct=25fb, bcdDevice=30.04
[595285.170695] usb 8-1: New USB device strings: Mfr=2, Product=3, SerialNumber=1
[595285.170697] usb 8-1: Product: easystore 25FB
[595285.170699] usb 8-1: Manufacturer: Western Digital
[595285.170701] usb 8-1: SerialNumber: 3753473644374D43
[595285.171116] usb-storage 8-1:1.0: USB Mass Storage device detected
[595285.171720] scsi host5: usb-storage 8-1:1.0
[595286.205439] scsi 5:0:0:0: Direct-Access WD easystore 25FB 3004 PQ: 0 ANSI: 6
[595286.206548] scsi 5:0:0:1: Enclosure WD SES Device 3004 PQ: 0 ANSI: 6
[595286.211249] sd 5:0:0:0: Attached scsi generic sg2 type 0
[595286.211375] ses 5:0:0:1: Attached Enclosure device
[595286.215342] sd 5:0:0:0: [sdc] Spinning up disk…
[595286.216388] ses 5:0:0:1: Wrong diagnostic page; asked for 1 got 8
[595286.216432] ses 5:0:0:1: Failed to get diagnostic page 0x1
[595286.216468] ses 5:0:0:1: Failed to bind enclosure -19
[595286.216693] ses 5:0:0:1: Attached scsi generic sg3 type 13
[595287.224037] …ready
[595302.585189] sd 5:0:0:0: [sdc] Very big device. Trying to use READ CAPACITY(16).
[595302.585944] sd 5:0:0:0: [sdc] 15628052480 512-byte logical blocks: (8.00 TB/7.28 TiB)
[595302.585946] sd 5:0:0:0: [sdc] 4096-byte physical blocks
[595302.587310] sd 5:0:0:0: [sdc] Write Protect is off
[595302.587312] sd 5:0:0:0: [sdc] Mode Sense: 47 00 10 08
[595302.588581] sd 5:0:0:0: [sdc] No Caching mode page found
[595302.588623] sd 5:0:0:0: [sdc] Assuming drive cache: write through
[595303.668699] sdc: sdc1
[595303.673639] sd 5:0:0:0: [sdc] Attached SCSI disk
[627859.800798] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[747978.197518] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[759168.914318] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[796267.642742] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[807873.890087] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[809313.716487] omv-engined[20417]: segfault at 7f0464856245 ip 0000559ca83d959f sp 00007fff3d5b5f70 error 4 in php7.0[559ca816c000+3aa000]
[809313.716497] Code: a7 00 00 00 e8 1a 91 e6 ff 66 90 48 83 c3 20 49 39 dc 0f 84 18 ff ff ff 48 8b 45 30 48 89 df ff d0 48 8b 7b 18 48 85 ff 74 e1 <0f> b6 57 05 f6 c2 02 75 d8 83 2f 01 75 d3 eb c1 90 48 83 c3 20 e8
[852584.223391] php-fpm7.0[15260]: segfault at 100000008 ip 0000560a9c4b9d10 sp 00007ffc59534aa8 error 4 in php-fpm7.0[560a9c27a000+3a8000]
[852584.223406] Code: 48 8d 05 8e 0b 0c 00 48 8d 0d 31 0d 11 00 48 8d 35 7d 78 10 00 bf 01 00 00 00 48 83 fa 01 48 0f 45 c8 31 c0 e8 ff 00 e9 ff 90 47 09 04 74 1e 48 8b 17 83 2a 01 74 22 80 7f 08 0a 74 34 f6 47
[852584.251908] php-fpm7.0[1844]: segfault at 100000007 ip 00007fda7db4daa8 sp 00007ffc59534aa0 error 4 in soap.so[7fda7db21000+49000]
[852584.251926] Code: 48 8b 43 40 48 85 c0 74 14 48 89 e7 48 89 04 24 c7 44 24 08 11 00 00 00 e8 45 d0 fd ff 48 8b 43 30 48 85 c0 0f 84 b4 00 00 00 <48> 8b 78 08 e8 47 d0 fd ff 48 8b 43 30 48 8b 78 10 e8 3a d0 fd ff
[891671.084752] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[1021379.657286] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[1450808.976175] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[1566713.141683] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[1567784.122727] internet client[31463]: segfault at 23f78f0 ip 00000000023f78f0 sp 00007fce875e56c8 error 15
[1567784.122733] Code: a0 e9 a0 de d5 f3 68 0c 3f ad 00 00 00 00 76 02 3c 26 53 bb c4 c5 d1 93 cd 90 e2 2c 19 91 0a 2e 65 81 40 74 aa a0 ce 7f 00 00 <00> 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[1568133.076083] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[1623369.908499] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[1625783.197138] traps: internet client[32175] general protection ip:46bc9d sp:7ff09ede46d0 error:0 in urbackupclientbackend[400000+2ce000]
[1628100.360134] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[1636768.605082] usb 8-1: USB disconnect, device number 4
[1636775.834405] usb 8-1: new high-speed USB device number 5 using ehci-pci
[1636775.992568] usb 8-1: New USB device found, idVendor=1058, idProduct=25fb, bcdDevice=30.04
[1636775.992571] usb 8-1: New USB device strings: Mfr=2, Product=3, SerialNumber=1
[1636775.992573] usb 8-1: Product: easystore 25FB
[1636775.992575] usb 8-1: Manufacturer: Western Digital
[1636775.992577] usb 8-1: SerialNumber: 3753475A4E504C43
[1636775.993008] usb-storage 8-1:1.0: USB Mass Storage device detected
[1636775.993581] scsi host5: usb-storage 8-1:1.0
[1636777.011737] scsi 5:0:0:0: Direct-Access WD easystore 25FB 3004 PQ: 0 ANSI: 6
[1636777.012825] scsi 5:0:0:1: Enclosure WD SES Device 3004 PQ: 0 ANSI: 6
[1636777.017467] sd 5:0:0:0: Attached scsi generic sg2 type 0
[1636777.017713] ses 5:0:0:1: Attached Enclosure device
[1636777.021763] sd 5:0:0:0: [sdc] Spinning up disk…
[1636777.022749] ses 5:0:0:1: Wrong diagnostic page; asked for 1 got 8
[1636777.022795] ses 5:0:0:1: Failed to get diagnostic page 0x1
[1636777.022831] ses 5:0:0:1: Failed to bind enclosure -19
[1636777.023057] ses 5:0:0:1: Attached scsi generic sg3 type 13
[1636778.034370] …ready
[1636793.395548] sd 5:0:0:0: [sdc] Very big device. Trying to use READ CAPACITY(16).
[1636793.396144] sd 5:0:0:0: [sdc] 15628052480 512-byte logical blocks: (8.00 TB/7.28 TiB)
[1636793.396147] sd 5:0:0:0: [sdc] 4096-byte physical blocks
[1636793.397277] sd 5:0:0:0: [sdc] Write Protect is off
[1636793.397279] sd 5:0:0:0: [sdc] Mode Sense: 47 00 10 08
[1636793.398472] sd 5:0:0:0: [sdc] No Caching mode page found
[1636793.398514] sd 5:0:0:0: [sdc] Assuming drive cache: write through
[1636794.757045] sdc: sdc1
[1636794.761321] sd 5:0:0:0: [sdc] Attached SCSI disk
[1721555.924001] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[1769525.555507] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[1796995.498833] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[1882773.238548] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[1887318.073578] traps: internet client[24477] general protection ip:46c0f7 sp:7f3eecdfc6d0 error:0 in urbackupclientbackend[400000+2ce000]
[2008585.336482] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[2050640.958389] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[2065963.702047] traps: internet client[25530] general protection ip:46bc9d sp:7f1a1effb6d0 error:0 in urbackupclientbackend[400000+2ce000]
[2068240.563233] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[2141922.175931] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[2154013.000751] traps: internet client[7231] general protection ip:46c0f7 sp:7f5d277fc6d0 error:0 in urbackupclientbackend[400000+2ce000]

[uroni]

@ttyllc

[2154013.000751] traps: internet client[7231] general protection ip:46c0f7 sp:7f5d277fc6d0 error:0 in urbackupclientbackend[400000+2ce000]

So it crashes? Maybe debug this? (See link above for how to)

[ttyllc]

@ttyllc

013.000751] t

WOW Thanks, I will

I wish I didnt have to bother you. Than k you so much, Ill look into it and I’ll post the finfings

…I see I have to compile the client … ill see how far I get with it. I used to run gentoo in the past, so I used to have to compile everything, so we’ll see if that will help.

Thank you for your help

[uroni]

I think the version with debug symbols should also work (page should be updated, I guess): https://hndl.urbackup.org/Client/2.4.11/UrBackup%20Client%20Linux%202.4.11-dbg.sh

[ttyllc]

Awsome

[ttyllc]

I was able to run the backup following these instructions.

https://urbackup.atlassian.net/wiki/spaces/US/pages/8323075/Debugging+with+gdb+on+Linux

bt command at the end showed nothing

I’ll send the logs link to the same email, they are too large to be posted.

I’m adding the following log files:
-Client log
-Server Log
-Server UI
-gdb output

[uroni]

Thanks! How are you running the server? On OMV in a docker container? (W.r.t. having you run a patched server…)