Multiple volume image backup issue on Server 2.5.22

Dark_Angel · February 10, 2022, 11:53am

Description: I’m trying to backup 2 volumes via Linux image backup: both of them take part in boot process:
/dev/sda1 - partition that contains grub and /boot
/dev/sdb - device with main OS (Centos 7)

Steps to reproduce:

Setup Urbackup client with dattobd.
Setup Image Backup for client specifying volumes: /mountpoint/for/sda1;C (minor issue, if I specify “/” volume for backup - it tries to make snapshot from “/:” and fails, so I have to use capital “c”)
Run Full Image Backup.

Expected behavior:
Both partitions successfully backed up.

Actual behavior:

/dev/sda1 - backed up partially? Out of 12Gbs used - only around 500 Mbs backed up and during backup seems like CBT is used, however no full backup present. (ext4)
/dev/sdb fails to backup. (ext3)

Error logs:

Feb 10 12:19:16 URBACKUP_CLIENT urbackupclientbackend[32428]: Started connection to SERVICE_COMMANDS
Feb 10 12:19:16 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#FULL IMAGE letter=/mnt/for_swap&token=tMvcsnR8c4ReFTm6QnWI&bitmap=1&status_id=62&running_jobs=1&zero_skipped=1
Feb 10 12:19:16 URBACKUP_CLIENT su[3830]: (to zimbra) root on none
Feb 10 12:19:16 URBACKUP_CLIENT su[3830]: pam_unix(su-l:session): session opened for user zimbra by (uid=0)
Feb 10 12:19:19 URBACKUP_CLIENT kernel: EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
Feb 10 12:19:19 URBACKUP_CLIENT urbackupclientbackend[32428]: Snapshotting device /dev/sda1 via dattobd...
Feb 10 12:19:19 URBACKUP_CLIENT urbackupclientbackend[32428]: Using /dev/datto0...
Feb 10 12:19:19 URBACKUP_CLIENT urbackupclientbackend[32428]: Mounting /dev/mapper/wsnap-7f543c1dcc765251b4b0f1fd7a3a37acfdd21c719a519193...
Feb 10 12:19:19 URBACKUP_CLIENT urbackupclientbackend[32428]: Shadowcopy path: /mnt/urbackup_snaps/7f543c1dcc765251b4b0f1fd7a3a37acfdd21c719a519193
Feb 10 12:19:19 URBACKUP_CLIENT urbackupclientbackend[32428]: Resetting CBT information
Feb 10 12:19:19 URBACKUP_CLIENT urbackupclientbackend[32428]: done.
Feb 10 12:19:19 URBACKUP_CLIENT urbackupclientbackend[32428]: Detected fs type ext4
Feb 10 12:19:19 URBACKUP_CLIENT urbackupclientbackend[32428]: Partclone v0.3.18 http://partclone.org
Feb 10 12:19:19 URBACKUP_CLIENT urbackupclientbackend[32428]: Starting to clone device (/dev/datto0) to image (-)
Feb 10 12:19:19 URBACKUP_CLIENT urbackupclientbackend[32428]: Reading Super Block
Feb 10 12:19:19 URBACKUP_CLIENT urbackupclientbackend[32428]: Calculating bitmap... Please wait...
Feb 10 12:19:20 URBACKUP_CLIENT urbackupclientbackend[32428]: [198B blob data]
Feb 10 12:19:20 URBACKUP_CLIENT urbackupclientbackend[32428]: Total Time: 00:00:01, 100.00% completed!
Feb 10 12:19:20 URBACKUP_CLIENT urbackupclientbackend[32428]: done!
Feb 10 12:19:20 URBACKUP_CLIENT urbackupclientbackend[32428]: File system:  EXTFS
Feb 10 12:19:20 URBACKUP_CLIENT urbackupclientbackend[32428]: Device size:   41.0 GB = 10000123 Blocks
Feb 10 12:19:20 URBACKUP_CLIENT urbackupclientbackend[32428]: Space in use:  12.3 GB = 2998213 Blocks
Feb 10 12:19:20 URBACKUP_CLIENT urbackupclientbackend[32428]: Free Space:    28.7 GB = 7001910 Blocks
Feb 10 12:19:20 URBACKUP_CLIENT urbackupclientbackend[32428]: Block size:   4096 Byte
Feb 10 12:19:20 URBACKUP_CLIENT urbackupclientbackend[32428]: Elapsed: 00:00:01, Remaining: 00:01:39, Completed:   1.00%,   0.00byte/min,
Feb 10 12:19:20 URBACKUP_CLIENT urbackupclientbackend[32428]: [102B blob data]
Feb 10 12:19:22 URBACKUP_CLIENT urbackupclientbackend[32428]: Elapsed: 00:00:02, Remaining: 00:03:18, Completed:   1.00%,   0.00byte/min,
Feb 10 12:19:23 URBACKUP_CLIENT urbackupclientbackend[32428]: [126B blob data]
Feb 10 12:19:23 URBACKUP_CLIENT urbackupclientbackend[32428]: FSINFO: blocksize=4096 size=40960503808 has_error=false used_space=12277084160 type=ext4
Feb 10 12:19:23 URBACKUP_CLIENT urbackupclientbackend[32428]: Trying to exclude contents of file /mnt/urbackup_snaps/7f543c1dcc765251b4b0f1fd7a3a37acfdd21c719a519193//swapfile_for_tango from backup...
Feb 10 12:19:23 URBACKUP_CLIENT urbackupclientbackend[32428]: Trying to exclude contents of file /mnt/urbackup_snaps/7f543c1dcc765251b4b0f1fd7a3a37acfdd21c719a519193/.datto_3d41c58e-6724-4d47-8981-11c766a08a24_7f543c1dcc765251b4b0f1fd7a3a37acfdd21c719a519193 from backup...
Feb 10 12:19:26 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#2PING RUNNING pc_done=4&status_id=62&speed_bpms=0&total_bytes=1889574912&done_bytes=70119424&paused_fb=1#token=tMvcsnR8c4ReFTm6QnWI
Feb 10 12:19:36 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#2PING RUNNING pc_done=13&status_id=62&speed_bpms=0&total_bytes=1889574912&done_bytes=241750016&paused_fb=1#token=tMvcsnR8c4ReFTm6QnWI
Feb 10 12:19:40 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: PONG
Feb 10 12:19:40 URBACKUP_CLIENT urbackupclientbackend[32428]: rc=0 hasError=true state=3
Feb 10 12:19:40 URBACKUP_CLIENT urbackupclientbackend[32428]: SERVICE_COMMANDS finished
Feb 10 12:19:40 URBACKUP_CLIENT urbackupclientbackend[32428]: Started connection to SERVICE_COMMANDS
Feb 10 12:19:40 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#1CHANNEL capa=0&token=tMvcsnR8c4ReFTm6QnWI&restore_version=1&startup=1&virtual_client=
Feb 10 12:19:40 URBACKUP_CLIENT urbackupclientbackend[32428]: New channel: Number of Channels: 1
Feb 10 12:19:46 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#2PING RUNNING pc_done=22&status_id=62&speed_bpms=5136.49&total_bytes=1889574912&done_bytes=420061184&paused_fb=1#token=tMvcsnR8c4ReFTm6QnWI
Feb 10 12:19:56 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#2PING RUNNING pc_done=32&status_id=62&speed_bpms=4519.21&total_bytes=1889574912&done_bytes=607776768&paused_fb=1#token=tMvcsnR8c4ReFTm6QnWI
Feb 10 12:20:06 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#2PING RUNNING pc_done=42&status_id=62&speed_bpms=4987.73&total_bytes=1889574912&done_bytes=788434944&paused_fb=1#token=tMvcsnR8c4ReFTm6QnWI
Feb 10 12:20:16 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#2PING RUNNING pc_done=50&status_id=62&speed_bpms=5926.15&total_bytes=1889574912&done_bytes=949018624&paused_fb=1#token=tMvcsnR8c4ReFTm6QnWI
Feb 10 12:20:26 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#2PING RUNNING pc_done=58&status_id=62&speed_bpms=6459.6&total_bytes=1889574912&done_bytes=1097289728&paused_fb=1#token=tMvcsnR8c4ReFTm6QnWI
Feb 10 12:20:36 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#2PING RUNNING pc_done=72&status_id=62&speed_bpms=6406.49&total_bytes=1889574912&done_bytes=1361145856&paused_fb=1#token=tMvcsnR8c4ReFTm6QnWI
Feb 10 12:20:39 URBACKUP_CLIENT urbackupclientbackend[32428]: Sending full image done
Feb 10 12:20:39 URBACKUP_CLIENT urbackupclientbackend[32428]: Deleting shadowcopy for path "/mnt/urbackup_snaps/7f543c1dcc765251b4b0f1fd7a3a37acfdd21c719a519193" -2
Feb 10 12:20:39 URBACKUP_CLIENT urbackupclientbackend[32428]: Unmounting /dev/datto0 at /mnt/urbackup_snaps/7f543c1dcc765251b4b0f1fd7a3a37acfdd21c719a519193...
Feb 10 12:20:39 URBACKUP_CLIENT urbackupclientbackend[32428]: Removing devicemapper snapshot...
Feb 10 12:20:39 URBACKUP_CLIENT urbackupclientbackend[32428]: Transitioning dattobd snapshot /dev/datto0 to incremental...
Feb 10 12:20:39 URBACKUP_CLIENT urbackupclientbackend[32428]: Deleting Shadowcopy for dir "/mnt/for_swap"
Feb 10 12:20:39 URBACKUP_CLIENT urbackupclientbackend[32428]: Removing running process (1) id 7 server_id 62 token tMvcsnR8c4ReFTm6QnWI action 3
Feb 10 12:20:39 URBACKUP_CLIENT urbackupclientbackend[32428]: Service finished. Transferred 381.977 MB
Feb 10 12:20:39 URBACKUP_CLIENT urbackupclientbackend[32428]: SERVICE_COMMANDS finished
Feb 10 12:20:45 URBACKUP_CLIENT urbackupclientbackend[32428]: Done.
Feb 10 12:20:46 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#2PING RUNNING pc_done=90&status_id=62&speed_bpms=4768.84&total_bytes=1889574912&done_bytes=1701298176&paused_fb=1#token=tMvcsnR8c4ReFTm6QnWI
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: Starting zmconfigd...Started connection to SERVICE_COMMANDS
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#2LOGDATA 1644492089 0-1644491992-Starting unscheduled full image backup of volume "/mnt/for_swap"...
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: 0-1644491992-Basing image backup on last incremental or full image backup
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: 1-1644491992-Error retrieving last image backup. Doing full image backup instead.
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: 0-1644492089-Transferred 381.977 MB - Average speed: 33.424 MBit/s
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: 0-1644492089-(Before compression: 1.76435 GB ratio: 4.72984)
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: 0-1644492089-Time taken for backing up client Tango: 1m 36s
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: 0-1644492089-Backup succeeded
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: rc=0 hasError=true state=0
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: SERVICE_COMMANDS finished
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: Started connection to SERVICE_COMMANDS
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#MBR driveletter=SYSVOL&disk_path=SYSVOL&image_full=1&running_jobs=1&token=tMvcsnR8c4ReFTm6QnWI
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: rc=0 hasError=true state=0
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: SERVICE_COMMANDS finished
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: Started connection to SERVICE_COMMANDS
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#FULL IMAGE letter=SYSVOL&token=tMvcsnR8c4ReFTm6QnWI&bitmap=1&status_id=64&running_jobs=1&zero_skipped=1
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: Not found
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: rc=0 hasError=true state=0
Feb 10 12:20:53 URBACKUP_CLIENT urbackupclientbackend[32428]: SERVICE_COMMANDS finished
Feb 10 12:20:54 URBACKUP_CLIENT urbackupclientbackend[32428]: Started connection to SERVICE_COMMANDS
Feb 10 12:20:54 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#2PING RUNNING pc_done=0&status_id=64&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=tMvcsnR8c4ReFTm6QnWI
Feb 10 12:20:54 URBACKUP_CLIENT urbackupclientbackend[32428]: Started connection to SERVICE_COMMANDS
Feb 10 12:20:54 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#MBR driveletter=ESP&disk_path=ESP&image_full=1&running_jobs=1&token=tMvcsnR8c4ReFTm6QnWI
Feb 10 12:20:54 URBACKUP_CLIENT urbackupclientbackend[32428]: rc=0 hasError=true state=0
Feb 10 12:20:54 URBACKUP_CLIENT urbackupclientbackend[32428]: SERVICE_COMMANDS finished
Feb 10 12:20:54 URBACKUP_CLIENT urbackupclientbackend[32428]: Started connection to SERVICE_COMMANDS
Feb 10 12:20:54 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#FULL IMAGE letter=ESP&token=tMvcsnR8c4ReFTm6QnWI&bitmap=1&status_id=65&running_jobs=1&zero_skipped=1
Feb 10 12:20:54 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: Not found
Feb 10 12:20:54 URBACKUP_CLIENT urbackupclientbackend[32428]: rc=0 hasError=true state=0
Feb 10 12:20:54 URBACKUP_CLIENT urbackupclientbackend[32428]: SERVICE_COMMANDS finished
Feb 10 12:20:55 URBACKUP_CLIENT urbackupclientbackend[32428]: Started connection to SERVICE_COMMANDS
Feb 10 12:20:55 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#2PING RUNNING pc_done=0&status_id=65&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=tMvcsnR8c4ReFTm6QnWI
Feb 10 12:20:55 URBACKUP_CLIENT urbackupclientbackend[32428]: Started connection to SERVICE_COMMANDS
Feb 10 12:20:55 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#2PING RUNNING pc_done=0&status_id=63&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=tMvcsnR8c4ReFTm6QnWI
Feb 10 12:20:55 URBACKUP_CLIENT urbackupclientbackend[32428]: Started connection to SERVICE_COMMANDS
Feb 10 12:20:55 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#MBR driveletter=C&disk_path=C:&image_full=1&running_jobs=1&token=tMvcsnR8c4ReFTm6QnWI
Feb 10 12:20:55 URBACKUP_CLIENT urbackupclientbackend[32428]: dl_devnum=b
Feb 10 12:20:55 URBACKUP_CLIENT urbackupclientbackend[32428]: rc=0 hasError=true state=0
Feb 10 12:20:55 URBACKUP_CLIENT urbackupclientbackend[32428]: SERVICE_COMMANDS finished
Feb 10 12:20:56 URBACKUP_CLIENT urbackupclientbackend[32428]: Started connection to SERVICE_COMMANDS
Feb 10 12:20:56 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#FULL IMAGE letter=C:&token=tMvcsnR8c4ReFTm6QnWI&bitmap=1&status_id=63&running_jobs=1&zero_skipped=1
Feb 10 12:20:56 URBACKUP_CLIENT su[4827]: (to zimbra) root on none
Feb 10 12:20:56 URBACKUP_CLIENT su[4827]: pam_unix(su-l:session): session opened for user zimbra by (uid=0)
Feb 10 12:20:56 URBACKUP_CLIENT urbackupclientbackend[32428]: rc=0 hasError=true state=0
Feb 10 12:20:56 URBACKUP_CLIENT urbackupclientbackend[32428]: SERVICE_COMMANDS finished
Feb 10 12:21:04 URBACKUP_CLIENT urbackupclientbackend[32428]: rc=0 hasError=true state=0
Feb 10 12:21:04 URBACKUP_CLIENT urbackupclientbackend[32428]: SERVICE_COMMANDS finished
Feb 10 12:21:05 URBACKUP_CLIENT urbackupclientbackend[32428]: rc=0 hasError=true state=0
Feb 10 12:21:05 URBACKUP_CLIENT urbackupclientbackend[32428]: SERVICE_COMMANDS finished
Feb 10 12:21:05 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#2PING RUNNING pc_done=0&status_id=63&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=tMvcsnR8c4ReFTm6QnWI
Feb 10 12:21:07 URBACKUP_CLIENT urbackupclientbackend[32428]: WARNING: Could not open snapshot at "/mnt/urbackup_snaps/ed76ed75ed43f82a645287e7be01c04e71ac1671bbd0dfbf"
Feb 10 12:21:07 URBACKUP_CLIENT urbackupclientbackend[32428]: WARNING: Removing reference because shadowcopy could not be openend
Feb 10 12:21:07 URBACKUP_CLIENT urbackupclientbackend[32428]: WARNING: Restarting shadow copy of / because it was started by this server
Feb 10 12:21:07 URBACKUP_CLIENT urbackupclientbackend[32428]: Releasing /dev/sdb orig_target=/dev/sdb target=/mnt/urbackup_snaps/ed76ed75ed43f82a645287e7be01c04e71ac1671bbd0dfbf
Feb 10 12:21:07 URBACKUP_CLIENT urbackupclientbackend[32428]: Deleting shadowcopy for path "/mnt/urbackup_snaps/ed76ed75ed43f82a645287e7be01c04e71ac1671bbd0dfbf" -2
Feb 10 12:21:07 URBACKUP_CLIENT urbackupclientbackend[32428]: Snapshot at /mnt/urbackup_snaps/ed76ed75ed43f82a645287e7be01c04e71ac1671bbd0dfbf was already removed
Feb 10 12:21:07 URBACKUP_CLIENT urbackupclientbackend[32428]: Deleting Shadowcopy for dir "/"
Feb 10 12:21:07 URBACKUP_CLIENT kernel: datto: fallocate is not supported for '/.datto_3d41c58e-6724-4d47-8981-11c766a08a24_4c6ab9ef88739f9e85e12372f24ee57936f6cf1e41e07085', falling back on writing zeros
Feb 10 12:21:15 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#2PING RUNNING pc_done=0&status_id=63&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=tMvcsnR8c4ReFTm6QnWI
Feb 10 12:21:19 URBACKUP_CLIENT kernel: datto: '//.datto_3d41c58e-6724-4d47-8981-11c766a08a24_4c6ab9ef88739f9e85e12372f24ee57936f6cf1e41e07085' is not on 'sda1': -22
Feb 10 12:21:19 URBACKUP_CLIENT kernel: datto: error setting up cow manager: -22
Feb 10 12:21:19 URBACKUP_CLIENT kernel: datto: error transitioning tracer to snapshot mode: -22
Feb 10 12:21:19 URBACKUP_CLIENT kernel: datto: error during transition to snapshot ioctl handler: -22
Feb 10 12:21:21 URBACKUP_CLIENT kernel: datto: device specified already exists: -16
Feb 10 12:21:21 URBACKUP_CLIENT kernel: datto: error during setup ioctl handler: -16
Feb 10 12:21:21 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: Creating snapshot of "/dev/sdb" failed
Feb 10 12:21:21 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: Snapshotting device /dev/sdb via dattobd...
Feb 10 12:21:21 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: Trying to transition /dev/datto0 to snapshot...
Feb 10 12:21:21 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: dbdctl transition-to-snapshot '//.datto_3d41c58e-6724-4d47-8981-11c766a08a24_4c6ab9ef88739f9e85e12372f24ee57936f6cf1e41e07085' 0
Feb 10 12:21:21 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: driver returned an error performing specified action. check dmesg for more info: Invalid argument
Feb 10 12:21:21 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: Using /dev/datto0...
Feb 10 12:21:21 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: CBT=type=datto&reset=1
Feb 10 12:21:21 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: driver returned an error performing specified action. check dmesg for more info: Device or resource busy
Feb 10 12:21:21 URBACKUP_CLIENT urbackupclientbackend[32428]: Disabling CBT on volume "/dev/sdb"
Feb 10 12:21:21 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: Getting shadowcopy of "/dev/sdb" failed.
Feb 10 12:21:21 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: Creating shadow copy failed. See client log file for details.
Feb 10 12:21:21 URBACKUP_CLIENT urbackupclientbackend[32428]: Sending full image done
Feb 10 12:21:21 URBACKUP_CLIENT urbackupclientbackend[32428]: Removing running process (1) id 8 server_id 63 token tMvcsnR8c4ReFTm6QnWI action 3
Feb 10 12:21:21 URBACKUP_CLIENT urbackupclientbackend[32428]: SERVICE_COMMANDS finished
Feb 10 12:21:22 URBACKUP_CLIENT urbackupclientbackend[32428]: Started connection to SERVICE_COMMANDS
Feb 10 12:21:22 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: #I5vBaB3Q7U8e5PFSv2WI5#2LOGDATA 1644492118 0-1644492090-Starting unscheduled full image backup of volume "C:"...
Feb 10 12:21:22 URBACKUP_CLIENT urbackupclientbackend[32428]: 0-1644492092-Basing image backup on last incremental or full image backup
Feb 10 12:21:22 URBACKUP_CLIENT urbackupclientbackend[32428]: 1-1644492092-Error retrieving last image backup. Doing full image backup instead.
Feb 10 12:21:22 URBACKUP_CLIENT urbackupclientbackend[32428]: 2-1644492118-Request of image backup failed. Reason: Creating shadow copy failed. See client log file for details.
Feb 10 12:21:22 URBACKUP_CLIENT urbackupclientbackend[32428]: 0-1644492118-Transferred 858 bytes - Average speed: 264 Bit/s
Feb 10 12:21:22 URBACKUP_CLIENT urbackupclientbackend[32428]: 0-1644492118-Time taken for backing up client Tango: 27s
Feb 10 12:21:22 URBACKUP_CLIENT urbackupclientbackend[32428]: 2-1644492118-Backup failed
Feb 10 12:21:22 URBACKUP_CLIENT urbackupclientbackend[32428]: rc=0 hasError=true state=0
Feb 10 12:21:22 URBACKUP_CLIENT urbackupclientbackend[32428]: SERVICE_COMMANDS finished
Feb 10 12:21:25 URBACKUP_CLIENT urbackupclientbackend[32428]: rc=0 hasError=true state=0
Feb 10 12:21:25 URBACKUP_CLIENT urbackupclientbackend[32428]: SERVICE_COMMANDS finished
Feb 10 12:21:40 URBACKUP_CLIENT urbackupclientbackend[32428]: ClientService cmd: PONG
Feb 10 12:22:21 URBACKUP_CLIENT urbackupclientbackend[32428]: Done.

In some cases dattobd reports:

Feb 10 12:50:30 URBACKUP_CLIENT kernel: datto: device specified already exists: -16
Feb 10 12:50:30 URBACKUP_CLIENT kernel: datto: error during setup ioctl handler: -16
Feb 10 12:50:30 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: Creating snapshot of "/dev/sdb" failed
Feb 10 12:50:30 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: Snapshotting device /dev/sdb via dattobd...
Feb 10 12:50:30 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: Using /dev/datto0...
Feb 10 12:50:30 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: CBT=type=datto&reset=1
Feb 10 12:50:30 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: driver returned an error performing specified action. check dmesg for more info: Device or resource busy
Feb 10 12:50:30 URBACKUP_CLIENT urbackupclientbackend[32428]: Disabling CBT on volume "/dev/sdb"
Feb 10 12:50:30 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: Getting shadowcopy of "/dev/sdb" failed.
Feb 10 12:50:30 URBACKUP_CLIENT urbackupclientbackend[32428]: ERROR: Creating shadow copy failed. See client log file for details.

With single volume in the list - issue is not present.

uroni · February 12, 2022, 9:46am

Could be compression or the exclusion of swap file. If you want to verify image contents, there is a testing procedure described at Server 2.5.23/Client 2.5.17 ( Testing (image backup + file backup with CBT))

Maybe because it’s not a partition. Will have to run some tests…

uroni · February 12, 2022, 11:50am

It might be reusing the datto device used for the other volume, i.e., this bit doesn’t work: https://github.com/uroni/urbackup_backend/blob/dev/linux_snapshot/dattobd_create_snapshot#L58

Edit: I think removing the double quotes might fix it, so:

has_num ()
{
	exists "/mnt/urbackup_snaps/cbt_info/*-snapdev" && grep "$1" /mnt/urbackup_snaps/cbt_info/*-snapdev > /dev/null
}

Could you change this and check?

Dark_Angel · May 5, 2022, 1:18pm

Making this fix seems to have resolved some strange issues I was hunting for on other Linux systems.

Unfortunately original system based on which this report has been created got migrated and no longer contain 2 volumes, so I cannot verify on 100%, but as mentioned above - I have Linux image backups running more reliably now due to the fix.

And I see that fix already applied for 2.5 branch. Thank you.

Reason for long validation is that I still have datto cow files left on systems that are backed up. I cannot understand sequence of steps which leads to abandoned files. So I thought that this is somehow related. Example on one of the systems:

----------    1 root root 144M Apr 13 04:30 .datto_3d41c58e-6724-4d47-8981-11c766a08a24_1d7e63ca3ab8b56d54ba09d6046d8b8b81961a283dfb6252
----------    1 root root 144M Feb 24 01:48 .datto_3d41c58e-6724-4d47-8981-11c766a08a24_a51a72ebbd546ff91731f249a567ebecc0b7967543d802b3
----------    1 root root 144M May  3 08:56 .datto_3d41c58e-6724-4d47-8981-11c766a08a24_cddca5ba7f7dc69d20f29cd68ca196b7c7b280b9df74dd9b

On this example files are small, but on some other examples they might be 12-20G, which leads to exhausted space on the root drives. Issue is not 100% reproducable. File might not appear for weeks and then I check - they are there.

Will report separately once found. I believe this issue could be closed.

DrRSatzteil · October 19, 2022, 12:41pm

Have you found the reason for the remaining datto cow files? I had one client with a full disk a couple of days ago due to this issue. Right now I’m manually removing the files every now and again. I thought about automating the removal in the postfilebackup script but I‘m not sure whether they can be safely removed at the time the script is called.

Dark_Angel · October 19, 2022, 3:59pm

Unfortunately the issue is still there. Haven’t found steps to reproduce it.

DrRSatzteil · November 7, 2022, 2:28pm

Just discovered this in the logs:

Info
07.11.22 11:28
Snapshotting device /dev/sda2 via dattobd...
Info
07.11.22 11:28
Trying to transition /dev/datto0 to snapshot...
Info
07.11.22 11:28
dbdctl transition-to-snapshot '//.datto_3d41c58e-6724-4d47-8981-11c766a08a24_25f9e4c9615e3887b55db86bfb68db6dc26f63c1d39a219b' 0
Info
07.11.22 11:28
driver returned an error performing specified action. check dmesg for more info: No such file or directory

This error does not occur when deleting the snapshot but when transitioning to snapshot. It seems that there is an additional leading ‘/’ in the file name. By looking at the scripts in /usr/local/share/urbackup/dattobd_create_snapshot I get the impression that the script might break when the $SNAP_MOUNTPOINT variable is not set. Where would be the right place to change this variable?

DrRSatzteil · December 6, 2022, 11:12am

Just discovered something else that might cause this. When I examine the client logs I can see that the dattobd_create_snapshot script is executed as these log entries are present:

0-1670312488-Snapshotting device /dev/sdc1 via dattobd...
0-1670312488-Using /dev/datto0...
0-1670312488-Mounting /dev/mapper/wsnap-f6e54eb65355a873e9931a88e6984f026c30917582f7599c...

However I don’t see any of the echo/log statements from the dattobd_remove_snapshot script. The script is executable and has the same permissions as the create script but does not seem to called at all. Are you experiencing the same behaviour?

Dark_Angel · December 6, 2022, 12:27pm

I can confirm, that I do not have messages from dattodb_remove_snapshot script in my logs as well, while from dattodb_create_snapshot - they exist.

Interesting. @uroni Is it how it should be?

DrRSatzteil · December 7, 2022, 7:53pm

It seems that the remove snapshot script is called even though we cannot see the log output since block devices are successfully transitioned to incremental mode after the backup operation. However I found some time to go through the code in more detail and stumbled upon this line in the create script which is problematic at least when you use virtual clients, I don’t know if this is related to your issue as well:

while [ -e "/dev/datto$NUM" ] && has_num $NUM

This is not correct in my opinion as it should actually be:

while [ -e "/dev/datto$NUM" ] || has_num $NUM

The reason is that when you use a virtual subclient on the same machine, depending on the current client there is a different subset of datto devices that have to be transitioned to snapshot mode. This however means that there is no /dev/datto0 device present when my second virtual sub client runs and this loop ends with $NUM being 0 which is however already used for a different mountpoint for the first client. When changed to ‘OR’ the script will always find the next free $NUM.

Example:
First client creates snapshot of two devices:
/dev/datto0
/dev/datto1
After the backup is done both datto devices are transitioned to incremental and the corresponding /dev/dattoX devices disappear.

An hour later when the backup for my virtual subclient runs it will determine 0 as the next free device number and thus tries to reuse the /dev/datto0 device which fails my backup…
With my proposed change the code will determine $NUM = 2 (via the has_num part of the expression) as the next free device number and the backup runs smoothly with device /dev/datto2

Moreover I added a new variable to the create script (and similar in the remove script):

SNAP_MOUNTPOINT_PATH_PREFIX="$2"
if [ $SNAP_MOUNTPOINT_PATH_PREFIX = "/" ]; then
    SNAP_MOUNTPOINT_PATH_PREFIX=""
fi

I use this variable as a replacement for all occurrences of SNAP_MOUNTPOINT when it is used to create a path in the filesystem. This way I no longer have incorrect paths like //.datto_3d41…
I’m pretty sure theres a more elegant solution but it should get the job done… I’ll know if this fixes my problems after the next few backups I guess…

DrRSatzteil · December 9, 2022, 8:26pm

So far everything runs very smooth, I’m very happy with my adjustments

In addition to that I just wanted to share a small script I will run at startup to clean up the files after a reboot (I haven’t setup datto to reload the snapshots before mounting the drives yet). This should get rid of any obsolete .datto, .overlay or cbt_info files at startup:

#!/bin/sh

for FILE in /mnt/urbackup_snaps/cbt_info/*-cowfile
do
    SNAP_COWFILE_PATH=$(cat $FILE)
    SNAP_COWFILE_NAME=".$(cat $FILE | cut -d '.' -f2-)"
    if [ ! -e /proc/datto-info ] || ! grep -q "$SNAP_COWFILE_NAME" /proc/datto-info; then
        echo "COW-File is not loaded by kernel module"
        if [ -e $SNAP_COWFILE_PATH ]; then
            echo "Deleting $SNAP_COWFILE_PATH"
            rm -f $SNAP_COWFILE_PATH
        fi
        DEVNUM_PATH=$(echo "$FILE" | sed s/-cowfile$/-snapdev/)
        if [ -e $DEVNUM_PATH ]; then
            echo "Deleting $DEVNUM_PATH"
            rm -f $DEVNUM_PATH
        fi
        OVERLAY_PATH=$(echo "$SNAP_COWFILE_PATH" | sed s/.datto_3d41c58e-6724-4d47-8981-11c766a08a24/.overlay_2fefd007-3e48-4162-b2c6-45ccdda22f37/)
        if [ -e $OVERLAY_PATH ]; then
            echo "Deleting $OVERLAY_PATH"
            rm -f $OVERLAY_PATH
        fi
        echo "Deleting $FILE"
        rm -f $FILE
    fi
done

Dark_Angel · December 11, 2022, 8:17pm

Thank you for sharing @DrRSatzteil. I believe it would make sense to include this as PR to the repo.

Described issues seems to be relevant to mine, specially with “&&” and “||” replacement. I will give it a try on client with multiple volumes.

DrRSatzteil · December 11, 2022, 9:07pm

Just created a PR for the &&-|| part. The double slashes are still a problem when backing up the root volume but I don’t think that my solution is particularly beautiful. If I find some time I might create another PR for this issue.

Oops… just realised that the PR is not there yet I will do that later…

DrRSatzteil · January 16, 2023, 4:05pm

Thanks for merging the first PR! I just created another one to address the cases where SNAP_MOUNTPOINT is root which led to wrong paths with starting double slashes.

uroni · January 16, 2023, 7:12pm

Thx you as well.

W.r.t. the slash, I’m wondering if perhaps it would be better to do that on the C++ side… what do you think?

DrRSatzteil · January 16, 2023, 7:39pm

Sorry I’m not really familiar with the whole architecture of Urbackup: You mean that you would call the script with an empty string as SNAP_MOUNTPOINT? This would however require to change the code to generate the file names in cbt_info as the slashes are currently replaced by underscores there.

uroni · January 16, 2023, 7:41pm

Hmm, ok an empty string would perhaps not be good. Will merge your PR.

DrRSatzteil · January 16, 2023, 11:07pm

I think it does not make sense to pass something else to the script only because it is the filesystem root. So I think it’s better to handle it in the script, it also makes it more robust for different inputs. Thanks for merging, I will create another similar PR for the remove snapshot script soon.