Hi! I’ll check it and write. Thank you!
I think I forgot to commit something. urbackup-client-2.4.12.0(1).tar.gz (4.5 MB) has it. Sorry for the inconvenience!
I already checked previous file and begun write report. It had same error, snapshot didn’t delete.
I’ll check this file and write.
I hope we can beat this issue!))
I made a few tests with urbackup-client-2.4.12.0(1).tar.gz.
Full client and server logs attached:
full_logs_urbackup-client-2.4.12.0(1).zip (304.9 KB)
2 tests:
-
Part1. Reset server then wait 10 hours (snapshot still exists)
-
Part2. Reset server (snapshot still exists), then start new backup - result error, 2 minutes later - old snapshot deleted, start new backup - same error.
Reproduce1. Reset server then wait 10 hours (snapshot still exists). Step by step.
Before start backup:
root@snap-leftover-nas-original:~# date
Sat 03 Apr 2021 01:29:42 AM MSK
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~# lvs
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
lv7zbackups vg7zbackups -wi-ao---- 1.76g
data1 vgdata -wi-ao---- 500.02g
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~# df -h
Filesystem Size Used Avail Use% Mounted on
udev 977M 0 977M 0% /dev
tmpfs 200M 4.5M 196M 3% /run
/dev/sda1 19G 4.6G 14G 26% /
tmpfs 998M 0 998M 0% /dev/shm
tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs 998M 0 998M 0% /sys/fs/cgroup
tmpfs 998M 4.0K 998M 1% /tmp
/dev/mapper/vg7zbackups-lv7zbackups 1.7G 17M 1.6G 1% /backups/nas7zbackups
/dev/mapper/vgdata-data1 493G 3.6G 489G 1% /srv/dev-disk-by-id-dm-name-vgdata-data1
Start backup:
root@snap-leftover-nas-original:~# date
Sat 03 Apr 2021 01:30:54 AM MSK
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~# lvs
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
lv7zbackups vg7zbackups -wi-ao---- 1.76g
data1 vgdata owi-aos--- 500.02g
urbackup_snap_5efede7f29b91cee714974dc1ee8dabdcac45aca265b56af vgdata swi-aos--- 99.99g data1 0.01
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~# df -h
Filesystem Size Used Avail Use% Mounted on
udev 977M 0 977M 0% /dev
tmpfs 200M 4.5M 195M 3% /run
/dev/sda1 19G 4.6G 14G 26% /
tmpfs 998M 0 998M 0% /dev/shm
tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs 998M 0 998M 0% /sys/fs/cgroup
tmpfs 998M 4.0K 998M 1% /tmp
/dev/mapper/vg7zbackups-lv7zbackups 1.7G 17M 1.6G 1% /backups/nas7zbackups
/dev/mapper/vgdata-data1 493G 3.6G 489G 1% /srv/dev-disk-by-id-dm-name-vgdata-data1
/dev/dm-4 493G 3.6G 489G 1% /mnt/urbackup_snaps/5efede7f29b91cee714974dc1ee8dabdcac45aca265b56af
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~# urbackupclientctl status
{
"capability_bits": 257823,
"finished_processes": [],
"internet_connected": false,
"internet_status": "connected_local",
"last_backup_time": 1617401140,
"running_processes": [{
"action": "FULL",
"done_bytes": 309206112,
"eta_ms": 159543,
"percent_done": 8,
"process_id": 1,
"server_status_id": 1,
"speed_bpms": 0,
"total_bytes": 3752245248
}
],
"servers": [{
"internet_connection": false,
"name": "30.30.30.233"
}
],
"time_since_last_lan_connection": 7786
}
Reset urbackup server. Snapshot still exists
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~# date
Sat 03 Apr 2021 01:32:06 AM MSK
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~# lvs
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
lv7zbackups vg7zbackups -wi-ao---- 1.76g
data1 vgdata owi-aos--- 500.02g
urbackup_snap_5efede7f29b91cee714974dc1ee8dabdcac45aca265b56af vgdata swi-aos--- 99.99g data1 0.01
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~# df -h
Filesystem Size Used Avail Use% Mounted on
udev 977M 0 977M 0% /dev
tmpfs 200M 4.5M 195M 3% /run
/dev/sda1 19G 4.6G 14G 26% /
tmpfs 998M 0 998M 0% /dev/shm
tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs 998M 0 998M 0% /sys/fs/cgroup
tmpfs 998M 4.0K 998M 1% /tmp
/dev/mapper/vg7zbackups-lv7zbackups 1.7G 17M 1.6G 1% /backups/nas7zbackups
/dev/mapper/vgdata-data1 493G 3.6G 489G 1% /srv/dev-disk-by-id-dm-name-vgdata-data1
/dev/dm-4 493G 3.6G 489G 1% /mnt/urbackup_snaps/5efede7f29b91cee714974dc1ee8dabdcac45aca265b56af
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~# urbackupclientctl status
{
"capability_bits": 257823,
"finished_processes": [],
"internet_connected": false,
"internet_status": "connected_local",
"last_backup_time": 1617401140,
"running_processes": [{
"action": "FULL",
"done_bytes": 928527840,
"eta_ms": 139542,
"percent_done": 25,
"process_id": 1,
"server_status_id": 1,
"speed_bpms": 30942.7,
"total_bytes": 3752245248
}
],
"servers": [{
"internet_connection": false,
"name": "30.30.30.233"
}
,{
"internet_connection": false,
"name": "30.30.30.233"
}
],
"time_since_last_lan_connection": 9856
}
2 minutes later. urbackupclientctl status shows that backup not running, but urbackupclientbackend process still use files at snapshot
And snapshot still exists
root@snap-leftover-nas-original:~# date
Sat 03 Apr 2021 01:34:56 AM MSK
root@snap-leftover-nas-original:~# urbackupclientctl status
{
"capability_bits": 257823,
"finished_processes": [],
"internet_connected": false,
"internet_status": "connected_local",
"last_backup_time": 1617401140,
"running_processes": [],
"servers": [{
"internet_connection": false,
"name": "30.30.30.233"
}
],
"time_since_last_lan_connection": 1009
}
root@snap-leftover-nas-original:~# fuser -m /dev/dm-4
/dev/dm-4: 508
root@snap-leftover-nas-original:~# lsof +D /mnt/urbackup_snaps/5efede7f29b91cee714974dc1ee8dabdcac45aca265b56af
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
urbackupc 508 root 24r REG 253,4 1199468544 35 /mnt/urbackup_snaps/5efede7f29b91cee714974dc1ee8dabdcac45aca265b56af/cloud1/Обмен/f18
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~# urbackupclientctl status
{
"capability_bits": 257823,
"finished_processes": [],
"internet_connected": false,
"internet_status": "connected_local",
"last_backup_time": 1617401140,
"running_processes": [],
"servers": [{
"internet_connection": false,
"name": "30.30.30.233"
}
],
"time_since_last_lan_connection": 1009
}
Wait a few hours…
10 hours later. Snapshot still exists.
root@snap-leftover-nas-original:~# date
Sat 03 Apr 2021 02:15:47 PM MSK
root@snap-leftover-nas-original:~# lvs
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
lv7zbackups vg7zbackups -wi-ao---- 1.76g
data1 vgdata owi-aos--- 500.02g
urbackup_snap_5efede7f29b91cee714974dc1ee8dabdcac45aca265b56af vgdata swi-aos--- 99.99g data1 0.01
root@snap-leftover-nas-original:~# df -h
Filesystem Size Used Avail Use% Mounted on
udev 977M 0 977M 0% /dev
tmpfs 200M 22M 178M 11% /run
/dev/sda1 19G 4.6G 14G 26% /
tmpfs 998M 0 998M 0% /dev/shm
tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs 998M 0 998M 0% /sys/fs/cgroup
tmpfs 998M 4.0K 998M 1% /tmp
/dev/mapper/vg7zbackups-lv7zbackups 1.7G 17M 1.6G 1% /backups/nas7zbackups
/dev/mapper/vgdata-data1 493G 3.6G 489G 1% /srv/dev-disk-by-id-dm-name-vgdata-data1
/dev/dm-4 493G 3.6G 489G 1% /mnt/urbackup_snaps/5efede7f29b91cee714974dc1ee8dabdcac45aca265b56af
As we see noone process use it, but snapshot still exists.
root@snap-leftover-nas-original:~# fuser -m /dev/dm-4
root@snap-leftover-nas-original:~# lsof +D /mnt/urbackup_snaps/5efede7f29b91cee714974dc1ee8dabdcac45aca265b56afPart 2. First part at previous post.
Reproduce2. Reset server (snapshot still exists), then start new backup - result error, 2 minutes later - old snapshot deleted, start new backup - same error. Step by step.
Before start backup:
root@snap-leftover-nas-original:~# date
Sat 03 Apr 2021 02:51:24 PM MSK
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~# lvs
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
lv7zbackups vg7zbackups -wi-ao---- 1.76g
data1 vgdata -wi-ao---- 500.02g
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~# df -h
Filesystem Size Used Avail Use% Mounted on
udev 977M 0 977M 0% /dev
tmpfs 200M 4.5M 196M 3% /run
/dev/sda1 19G 4.6G 14G 26% /
tmpfs 998M 0 998M 0% /dev/shm
tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs 998M 0 998M 0% /sys/fs/cgroup
tmpfs 998M 4.0K 998M 1% /tmp
/dev/mapper/vg7zbackups-lv7zbackups 1.7G 17M 1.6G 1% /backups/nas7zbackups
/dev/mapper/vgdata-data1 493G 3.6G 489G 1% /srv/dev-disk-by-id-dm-name-vgdata-data1
root@snap-leftover-nas-original:~#
Start backup:
root@snap-leftover-nas-original:~# date
Sat 03 Apr 2021 02:52:25 PM MSK
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~# lvs
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
lv7zbackups vg7zbackups -wi-ao---- 1.76g
data1 vgdata owi-aos--- 500.02g
urbackup_snap_b3cf5c9e5d5a2608ebe1213058b9a6b258189da492bb3dd6 vgdata swi-aos--- 99.99g data1 0.01
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~# df -h
Filesystem Size Used Avail Use% Mounted on
udev 977M 0 977M 0% /dev
tmpfs 200M 4.5M 195M 3% /run
/dev/sda1 19G 4.6G 14G 26% /
tmpfs 998M 0 998M 0% /dev/shm
tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs 998M 0 998M 0% /sys/fs/cgroup
tmpfs 998M 4.0K 998M 1% /tmp
/dev/mapper/vg7zbackups-lv7zbackups 1.7G 17M 1.6G 1% /backups/nas7zbackups
/dev/mapper/vgdata-data1 493G 3.6G 489G 1% /srv/dev-disk-by-id-dm-name-vgdata-data1
/dev/dm-3 493G 3.6G 489G 1% /mnt/urbackup_snaps/b3cf5c9e5d5a2608ebe1213058b9a6b258189da492bb3dd6
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~# urbackupclientctl status
{
"capability_bits": 257823,
"finished_processes": [],
"internet_connected": false,
"internet_status": "connected_local",
"last_backup_time": 1617401140,
"running_processes": [{
"action": "FULL",
"done_bytes": 628101776,
"eta_ms": 149551,
"percent_done": 17,
"process_id": 1,
"server_status_id": 1,
"speed_bpms": 0,
"total_bytes": 3752245248
}
],
"servers": [{
"internet_connection": false,
"name": "30.30.30.233"
}
],
"time_since_last_lan_connection": 5698
}
Reset urbackup server. Snapshot still exists
root@snap-leftover-nas-original:~# date
Sat 03 Apr 2021 02:53:55 PM MSK
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~# lvs
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
lv7zbackups vg7zbackups -wi-ao---- 1.76g
data1 vgdata owi-aos--- 500.02g
urbackup_snap_b3cf5c9e5d5a2608ebe1213058b9a6b258189da492bb3dd6 vgdata swi-aos--- 99.99g data1 0.01
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~#
root@snap-leftover-nas-original:~# urbackupclientctl status
{
"capability_bits": 257823,
"finished_processes": [],
"internet_connected": false,
"internet_status": "connected_local",
"last_backup_time": 1617401140,
"running_processes": [{
"action": "FULL",
"done_bytes": 942684096,
"eta_ms": 139550,
"percent_done": 25,
"process_id": 1,
"server_status_id": 1,
"speed_bpms": 31414.5,
"total_bytes": 3752245248
}
],
"servers": [{
"internet_connection": false,
"name": "30.30.30.233"
}
],
"time_since_last_lan_connection": 30078
}
Run backup again1
Urbackup server logs. Backup had an early error. Deleting partial backup
03.04.21 14:54 DEBUG Reflink copying is enabled
03.04.21 14:54 DEBUG Reflink copying is enabled
03.04.21 14:54 INFO Starting unscheduled full file backup...
03.04.21 14:54 DEBUG snap-leftover-nas-original.local: Connecting for filelist...
03.04.21 14:54 DEBUG snap-leftover-nas-original.local: Waiting for filelist
03.04.21 14:54 DEBUG snap-leftover-nas-original.local: Connecting for filelist (async)...
03.04.21 14:54 WARNING Old shadow copy of /srv/dev-disk-by-id-dm-name-vgdata-data1 still in use. Not deleting or using it.
03.04.21 14:54 WARNING Old shadow copy of /srv/dev-disk-by-id-dm-name-vgdata-data1 still in use. Not deleting or using it.
03.04.21 14:54 INFO Logical volume "urbackup_snap_17c64286402c2d394688a2c12d19980130dad37a52046a04" created.
03.04.21 14:54 ERROR Cannot access path to backup: "/mnt/urbackup_snaps/17c64286402c2d394688a2c12d19980130dad37a52046a04/213058b9a6b258189da492bb3dd6" Errorcode: 2 - No such file or directory
03.04.21 14:54 INFO Unmounting /dev/mapper/vgdata-urbackup_snap_17c64286402c2d394688a2c12d19980130dad37a52046a04 at /mnt/urbackup_snaps/17c64286402c2d394688a2c12d19980130dad37a52046a04...
03.04.21 14:54 INFO Destroying LVM snapshot /dev/mapper/vgdata-urbackup_snap_17c64286402c2d394688a2c12d19980130dad37a52046a04...
03.04.21 14:54 INFO Logical volume "urbackup_snap_17c64286402c2d394688a2c12d19980130dad37a52046a04" successfully removed
03.04.21 14:54 ERROR Indexing files failed, because of error
03.04.21 14:54 ERROR Constructing of filelist of "snap-leftover-nas-original.local" failed: error - index error
03.04.21 14:55 ERROR Backup had an early error. Deleting partial backup.
Urbackup client logs
ERROR: Cannot access path to backup: “/mnt/urbackup_snaps/17c64286402c2d394688a2c12d19980130dad37a52046a04/213058b9a6b258189da492bb3dd6” Errorcode: 2 - No such file or directory
This file can’t exists at this snaphot. Where UrBackup get this path?
2021-04-03 14:53:37: rc=0 hasError=true state=0
2021-04-03 14:54:07: ClientService cmd: STATUS DETAIL#pw=SiBTQVl9rm0ugsy8RsAXYFCOd3oSkP
2021-04-03 14:54:07: rc=0 hasError=true state=0
2021-04-03 14:54:37: ClientService cmd: PONG
2021-04-03 14:54:43: Client timeout in ClientConnector::Run
2021-04-03 14:54:46: ClientService cmd: #Iz2V2Y9GoJpXi8yVgb0oJ#2PING RUNNING pc_done=&status_id=1&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=Iq6thsabqfnQjZhD45YT
2021-04-03 14:54:46: ClientService cmd: #Iz2V2Y9GoJpXi8yVgb0oJ#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=1&async=1#token=Iq6thsabqfnQjZhD45YT
2021-04-03 14:54:46: Async index 0b8fa3acc527d612d3154e682a398f35
2021-04-03 14:54:46: Removing VSS log data...
2021-04-03 14:54:46: Final path: /srv/dev-disk-by-id-dm-name-vgdata-data1
2021-04-03 14:54:46: rc=0 hasError=true state=0
2021-04-03 14:54:46: Script list at "/usr/local/etc/urbackup/scripts/list" does not exist. Skipping.
2021-04-03 14:54:46: Deleting files... doing full index...
2021-04-03 14:54:46: Script "/usr/local/etc/urbackup/prefilebackup" does not exist
2021-04-03 14:54:46: Final path: /srv/dev-disk-by-id-dm-name-vgdata-data1
2021-04-03 14:54:46: Creating shadowcopy of "dev-disk-by-id-dm-name-vgdata-data1" in indexDirs()
2021-04-03 14:54:46: ClientService cmd: #Iz2V2Y9GoJpXi8yVgb0oJ#WAIT FOR INDEX async_id=0b8fa3acc527d612d3154e682a398f35#token=Iq6thsabqfnQjZhD45YT
2021-04-03 14:54:46: Wait for async index 0b8fa3acc527d612d3154e682a398f35
2021-04-03 14:54:51: WARNING: Old shadow copy of /srv/dev-disk-by-id-dm-name-vgdata-data1 still in use. Not deleting or using it.
2021-04-03 14:54:56: ClientService cmd: #Iz2V2Y9GoJpXi8yVgb0oJ#2PING RUNNING pc_done=&eta_ms=159542&status_id=1&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=Iq6thsabqfnQjZhD45YT
2021-04-03 14:54:56: WARNING: Old shadow copy of /srv/dev-disk-by-id-dm-name-vgdata-data1 still in use. Not deleting or using it.
2021-04-03 14:54:56: Logical volume "urbackup_snap_17c64286402c2d394688a2c12d19980130dad37a52046a04" created.
2021-04-03 14:54:56: Shadowcopy path: /mnt/urbackup_snaps/17c64286402c2d394688a2c12d19980130dad37a52046a04
2021-04-03 14:54:56: done.
2021-04-03 14:54:56: Indexing "dev-disk-by-id-dm-name-vgdata-data1"...
2021-04-03 14:54:56: ERROR: Cannot access path to backup: "/mnt/urbackup_snaps/17c64286402c2d394688a2c12d19980130dad37a52046a04/213058b9a6b258189da492bb3dd6" Errorcode: 2 - No such file or directory
2021-04-03 14:54:56: Deleting shadowcopy for path "/mnt/urbackup_snaps/17c64286402c2d394688a2c12d19980130dad37a52046a04/213058b9a6b258189da492bb3dd6" -2
2021-04-03 14:54:57: Unmounting /dev/mapper/vgdata-urbackup_snap_17c64286402c2d394688a2c12d19980130dad37a52046a04 at /mnt/urbackup_snaps/17c64286402c2d394688a2c12d19980130dad37a52046a04...
2021-04-03 14:54:57: Destroying LVM snapshot /dev/mapper/vgdata-urbackup_snap_17c64286402c2d394688a2c12d19980130dad37a52046a04...
2021-04-03 14:54:57: Logical volume "urbackup_snap_17c64286402c2d394688a2c12d19980130dad37a52046a04" successfully removed
2021-04-03 14:54:57: Deleting Shadowcopy for dir "/srv/dev-disk-by-id-dm-name-vgdata-data1"
2021-04-03 14:54:57: ERROR: Indexing files failed, because of error
2021-04-03 14:54:57: Script "/usr/local/etc/urbackup/postfileindex" does not exist
2021-04-03 14:54:57: Async index 0b8fa3acc527d612d3154e682a398f35 finished with "error - index error"
2021-04-03 14:54:57: ClientService cmd: #Iz2V2Y9GoJpXi8yVgb0oJ#GET VSSLOG
2021-04-03 14:54:57: VSS logdata - 996 bytes
2021-04-03 14:54:57: rc=0 hasError=true state=0
2021-04-03 14:54:57: rc=0 hasError=true state=0
2021-04-03 14:55:06: rc=0 hasError=true state=0
2021-04-03 14:55:07: ClientService cmd: #Iz2V2Y9GoJpXi8yVgb0oJ#2LOGDATA 1617450906 0-1617450886-Starting unscheduled full file backup...
1-1617450897-Old shadow copy of /srv/dev-disk-by-id-dm-name-vgdata-data1 still in use. Not deleting or using it.
1-1617450897-Old shadow copy of /srv/dev-disk-by-id-dm-name-vgdata-data1 still in use. Not deleting or using it.
0-1617450897-Logical volume "urbackup_snap_17c64286402c2d394688a2c12d19980130dad37a52046a04" created.
2-1617450897-Cannot access path to backup: "/mnt/urbackup_snaps/17c64286402c2d394688a2c12d19980130dad37a52046a04/213058b9a6b258189da492bb3dd6" Errorcode: 2 - No such file or directory
0-1617450897-Unmounting /dev/mapper/vgdata-urbackup_snap_17c64286402c2d394688a2c12d19980130dad37a52046a04 at /mnt/urbackup_snaps/17c64286402c2d394688a2c12d19980130dad37a52046a04...
0-1617450897-Destroying LVM snapshot /dev/mapper/vgdata-urbackup_snap_17c64286402c2d394688a2c12d19980130dad37a52046a04...
0-1617450897-Logical volume "urbackup_snap_17c64286402c2d394688a2c12d19980130dad37a52046a04" successfully removed
2-1617450897-Indexing files failed, because of error
2-1617450897-Constructing of filelist of "snap-leftover-nas-original.local" failed: error - index error
2-1617450906-Backup had an early error. Deleting partial backup.
2021-04-03 14:55:07: rc=0 hasError=true state=0
2021-04-03 14:55:37: ClientService cmd: PONG
2021-04-03 14:55:57: Reference not found. Iterating over all start tokens and share names for deletion
2021-04-03 14:55:57: dev-disk-by-id-dm-name-vgdata-data1 orig_target= target=/srv/dev-disk-by-id-dm-name-vgdata-data1 starttoken=Iq6thsabqfnQjZhD45YT gen=1 still in use. Not releasing. (2)
2 minutes later. Old snapshot deleted
root@snap-leftover-nas-original:~# date
Sat 03 Apr 2021 02:59:14 PM MSK
root@snap-leftover-nas-original:~# lvs
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
lv7zbackups vg7zbackups -wi-ao---- 1.76g
data1 vgdata -wi-ao---- 500.02g
root@snap-leftover-nas-original:~# df -h
Filesystem Size Used Avail Use% Mounted on
udev 977M 0 977M 0% /dev
tmpfs 200M 4.5M 196M 3% /run
/dev/sda1 19G 4.6G 14G 26% /
tmpfs 998M 0 998M 0% /dev/shm
tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs 998M 0 998M 0% /sys/fs/cgroup
tmpfs 998M 4.0K 998M 1% /tmp
/dev/mapper/vg7zbackups-lv7zbackups 1.7G 17M 1.6G 1% /backups/nas7zbackups
/dev/mapper/vgdata-data1 493G 3.6G 489G 1% /srv/dev-disk-by-id-dm-name-vgdata-data1
Urbackup client logs. Old snaphot deleted.
2021-04-03 14:55:07: rc=0 hasError=true state=0
2021-04-03 14:55:37: ClientService cmd: PONG
2021-04-03 14:55:57: Reference not found. Iterating over all start tokens and share names for deletion
2021-04-03 14:55:57: dev-disk-by-id-dm-name-vgdata-data1 orig_target= target=/srv/dev-disk-by-id-dm-name-vgdata-data1 starttoken=Iq6thsabqfnQjZhD45YT gen=1 still in use. Not releasing. (2)
2021-04-03 14:56:37: ClientService cmd: PONG
2021-04-03 14:56:57: Reference not found. Iterating over all start tokens and share names for deletion
2021-04-03 14:56:57: dev-disk-by-id-dm-name-vgdata-data1 orig_target= target=/srv/dev-disk-by-id-dm-name-vgdata-data1 starttoken=Iq6thsabqfnQjZhD45YT gen=1 still in use. Not releasing. (2)
2021-04-03 14:57:37: ClientService cmd: PONG
2021-04-03 14:57:52: FileSrv: Error: Sending data failed
2021-04-03 14:57:53: FileSrv: ClientThread deleted. 1024 KB Memory freed.
2021-04-03 14:57:57: Reference not found. Iterating over all start tokens and share names for deletion
2021-04-03 14:57:57: Deleting shadowcopy for path "/srv/dev-disk-by-id-dm-name-vgdata-data1" -2
2021-04-03 14:57:57: Unmounting /dev/mapper/vgdata-urbackup_snap_b3cf5c9e5d5a2608ebe1213058b9a6b258189da492bb3dd6 at /mnt/urbackup_snaps/b3cf5c9e5d5a2608ebe1213058b9a6b258189da492bb3dd6...
2021-04-03 14:57:57: Destroying LVM snapshot /dev/mapper/vgdata-urbackup_snap_b3cf5c9e5d5a2608ebe1213058b9a6b258189da492bb3dd6...
2021-04-03 14:57:57: Logical volume "urbackup_snap_b3cf5c9e5d5a2608ebe1213058b9a6b258189da492bb3dd6" successfully removed
2021-04-03 14:57:57: Deleting Shadowcopy for dir "/srv/dev-disk-by-id-dm-name-vgdata-data1"
2021-04-03 14:58:37: ClientService cmd: PONG
Run backup again3
root@snap-leftover-nas-original:~# lvs
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
lv7zbackups vg7zbackups -wi-ao---- 1.76g
data1 vgdata owi-aos--- 500.02g
urbackup_snap_6e4799294db944c6e19bf4e1c0028ee8f4cfa09cab7f830c vgdata swi-aos--- 99.99g data1 0.01
root@snap-leftover-nas-original:~# df -h
Filesystem Size Used Avail Use% Mounted on
udev 977M 0 977M 0% /dev
tmpfs 200M 7.0M 193M 4% /run
/dev/sda1 19G 4.6G 14G 26% /
tmpfs 998M 0 998M 0% /dev/shm
tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs 998M 0 998M 0% /sys/fs/cgroup
tmpfs 998M 4.0K 998M 1% /tmp
/dev/mapper/vg7zbackups-lv7zbackups 1.7G 17M 1.6G 1% /backups/nas7zbackups
/dev/mapper/vgdata-data1 493G 3.6G 489G 1% /srv/dev-disk-by-id-dm-name-vgdata-data1
/dev/dm-3 493G 3.6G 489G 1% /mnt/urbackup_snaps/6e4799294db944c6e19bf4e1c0028ee8f4cfa09cab7f830c
Run backup again4. Same error
Urbackup server logs. Backup had an early error. Deleting partial backup
|03.04.21 15:08 |DEBUG |Reflink copying is enabled|
|---|---|---|
|03.04.21 15:08 |DEBUG |Reflink copying is enabled|
|03.04.21 15:08 |INFO |Starting unscheduled full file backup...|
|03.04.21 15:08 |DEBUG |snap-leftover-nas-original.local: Connecting for filelist...|
|03.04.21 15:08 |DEBUG |snap-leftover-nas-original.local: Waiting for filelist|
|03.04.21 15:08 |DEBUG |snap-leftover-nas-original.local: Connecting for filelist (async)...|
|03.04.21 15:08 |WARNING |Old shadow copy of /srv/dev-disk-by-id-dm-name-vgdata-data1 still in use. Not deleting or using it.|
|03.04.21 15:08 |WARNING |Old shadow copy of /srv/dev-disk-by-id-dm-name-vgdata-data1 still in use. Not deleting or using it.|
|03.04.21 15:08 |INFO |Logical volume "urbackup_snap_abe8a4873d47f2252e1f2df74967c0936a6711aec56fc046" created.|
|03.04.21 15:08 |ERROR |Cannot access path to backup: "/mnt/urbackup_snaps/abe8a4873d47f2252e1f2df74967c0936a6711aec56fc046/f4e1c0028ee8f4cfa09cab7f830c" Errorcode: 2 - No such file or directory|
|03.04.21 15:08 |INFO |Unmounting /dev/mapper/vgdata-urbackup_snap_abe8a4873d47f2252e1f2df74967c0936a6711aec56fc046 at /mnt/urbackup_snaps/abe8a4873d47f2252e1f2df74967c0936a6711aec56fc046...|
|03.04.21 15:08 |INFO |Destroying LVM snapshot /dev/mapper/vgdata-urbackup_snap_abe8a4873d47f2252e1f2df74967c0936a6711aec56fc046...|
|03.04.21 15:08 |INFO |Logical volume "urbackup_snap_abe8a4873d47f2252e1f2df74967c0936a6711aec56fc046" successfully removed|
|03.04.21 15:08 |ERROR |Indexing files failed, because of error|
|03.04.21 15:08 |ERROR |Constructing of filelist of "snap-leftover-nas-original.local" failed: error - index error|
|03.04.21 15:08 |ERROR |Backup had an early error. Deleting partial backup.|
SSH:
root@snap-leftover-nas-original:~# date
Sat 03 Apr 2021 03:09:31 PM MSK
root@snap-leftover-nas-original:~# df -h
Filesystem Size Used Avail Use% Mounted on
udev 977M 0 977M 0% /dev
tmpfs 200M 7.0M 193M 4% /run
/dev/sda1 19G 4.6G 14G 26% /
tmpfs 998M 0 998M 0% /dev/shm
tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs 998M 0 998M 0% /sys/fs/cgroup
tmpfs 998M 4.0K 998M 1% /tmp
/dev/mapper/vg7zbackups-lv7zbackups 1.7G 17M 1.6G 1% /backups/nas7zbackups
/dev/mapper/vgdata-data1 493G 3.6G 489G 1% /srv/dev-disk-by-id-dm-name-vgdata-data1
/dev/dm-3 493G 3.6G 489G 1% /mnt/urbackup_snaps/6e4799294db944c6e19bf4e1c0028ee8f4cfa09cab7f830c
root@snap-leftover-nas-original:~# lvs
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
lv7zbackups vg7zbackups -wi-ao---- 1.76g
data1 vgdata owi-aos--- 500.02g
urbackup_snap_6e4799294db944c6e19bf4e1c0028ee8f4cfa09cab7f830c vgdata swi-aos--- 99.99g data1 0.01
root@snap-leftover-nas-original:~# urbackupclientctl status
{
"capability_bits": 257823,
"finished_processes": [],
"internet_connected": false,
"internet_status": "connected_local",
"last_backup_time": 1617401140,
"running_processes": [{
"action": "FULL",
"eta_ms": 159550,
"percent_done": -1,
"process_id": 4,
"server_status_id": 1,
"speed_bpms": 0
}
],
"servers": [{
"internet_connection": false,
"name": "30.30.30.233"
}
],
"time_since_last_lan_connection": 27187
}Yeah, that it doesn’t delete the snapshot if the server doesn’t start a new backup or says the backup is finished is currently expected behaviour.
W.r.t. to the wrong backup path, I wonder if following patch helps:
0001-Reset-target-path-when-snapshot-is-still-in-use.patch (855 Bytes)
I was only testing with dattobd, I that one seems to only be able to make one snapshot per volume, so it seems it didn’t matter there…
I’ll check this patch.
Can you please add function that Urbackup checks it every 5 minutes. And If urbackup don’t use snapshots then delete it.
???
It’s very important for me because I use SATA HDD 7200 drives at NAS servers. Nobody can use nas server if snapshots exist.
Thank you in advance!
Hello!
Sorry for long responce. I had a much work.
I got your last source code urbackup-client-2.4.12.0(1).tar.gz and pathed it 0001-Reset-target-path-when-snapshot-is-still-in-use.patch.
It helped. The problem is solved! All 4 snapshots deleted at the end of backup.
I think this is a victory! 
Full logs attached:
logs_Reset-target-path-when-snapshot-is-still-in-use.patch.zip (22.8 KB)
Reproduce1: Reset server a few times.
-
start new backup and reset server 3 times - all snapshots exists
-
start backup and wait when finished backup - Backup succeeded without errors and warnings.
-
All 4 snapshots deleted!
Before start backup:
root@snap-leftover-nas-original:~# date
Sun 11 Apr 2021 07:55:56 PM MSK
root@snap-leftover-nas-original:~# lvs
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
lv7zbackups vg7zbackups -wi-ao---- 1.76g
data1 vgdata -wi-ao---- 500.02g
root@snap-leftover-nas-original:~# df -h
Filesystem Size Used Avail Use% Mounted on
udev 977M 0 977M 0% /dev
tmpfs 200M 4.5M 196M 3% /run
/dev/sda1 19G 4.6G 14G 26% /
tmpfs 998M 0 998M 0% /dev/shm
tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs 998M 0 998M 0% /sys/fs/cgroup
tmpfs 998M 4.0K 998M 1% /tmp
/dev/mapper/vg7zbackups-lv7zbackups 1.7G 17M 1.6G 1% /backups/nas7zbackups
/dev/mapper/vgdata-data1 493G 2.0G 491G 1% /srv/dev-disk-by-id-dm-name-vgdata-data1
Start backup1:
root@snap-leftover-nas-original:~# date
Sun 11 Apr 2021 07:56:56 PM MSK
root@snap-leftover-nas-original:~# lvs
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
lv7zbackups vg7zbackups -wi-ao---- 1.76g
data1 vgdata owi-aos--- 500.02g
urbackup_snap_1c11ec20273f86b9ecee6ac47cdfd67fab161d8e72836f76 vgdata swi-aos--- 99.99g data1 0.01
root@snap-leftover-nas-original:~# df -h
Filesystem Size Used Avail Use% Mounted on
udev 977M 0 977M 0% /dev
tmpfs 200M 4.5M 195M 3% /run
/dev/sda1 19G 4.6G 14G 26% /
tmpfs 998M 0 998M 0% /dev/shm
tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs 998M 0 998M 0% /sys/fs/cgroup
tmpfs 998M 4.0K 998M 1% /tmp
/dev/mapper/vg7zbackups-lv7zbackups 1.7G 17M 1.6G 1% /backups/nas7zbackups
/dev/mapper/vgdata-data1 493G 2.0G 491G 1% /srv/dev-disk-by-id-dm-name-vgdata-data1
/dev/dm-4 493G 2.0G 491G 1% /mnt/urbackup_snaps/1c11ec20273f86b9ecee6ac47cdfd67fab161d8e72836f76
Reset urbackup server. Snapshot still exists
Run backup again2
root@snap-leftover-nas-original:~# date
Sun 11 Apr 2021 07:58:32 PM MSK
root@snap-leftover-nas-original:~# lvs
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
lv7zbackups vg7zbackups -wi-ao---- 1.76g
data1 vgdata owi-aos--- 500.02g
urbackup_snap_13ccefe426a13fbadda9cab1fb209b34f432c15fa7f272c8 vgdata swi-aos--- 50.00g data1 0.01
urbackup_snap_1c11ec20273f86b9ecee6ac47cdfd67fab161d8e72836f76 vgdata swi-aos--- 99.99g data1 0.01
root@snap-leftover-nas-original:~# date
Sun 11 Apr 2021 07:58:32 PM MSK
Repeat this 3 times (start backup and reset urbackup server).
After it we have:
root@snap-leftover-nas-original:~# lvs
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
lv7zbackups vg7zbackups -wi-ao---- 1.76g
data1 vgdata owi-aos--- 500.02g
urbackup_snap_13ccefe426a13fbadda9cab1fb209b34f432c15fa7f272c8 vgdata swi-aos--- 50.00g data1 0.01
urbackup_snap_1c11ec20273f86b9ecee6ac47cdfd67fab161d8e72836f76 vgdata swi-aos--- 99.99g data1 0.01
urbackup_snap_8650d59823f4297cf05712a78d92cdfe75e190928afffb56 vgdata swi-aos--- 25.00g data1 0.01
root@snap-leftover-nas-original:~# df -h
Filesystem Size Used Avail Use% Mounted on
udev 977M 0 977M 0% /dev
tmpfs 200M 7.0M 193M 4% /run
/dev/sda1 19G 4.6G 14G 26% /
tmpfs 998M 0 998M 0% /dev/shm
tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs 998M 0 998M 0% /sys/fs/cgroup
tmpfs 998M 4.0K 998M 1% /tmp
/dev/mapper/vg7zbackups-lv7zbackups 1.7G 17M 1.6G 1% /backups/nas7zbackups
/dev/mapper/vgdata-data1 493G 2.0G 491G 1% /srv/dev-disk-by-id-dm-name-vgdata-data1
/dev/dm-4 493G 2.0G 491G 1% /mnt/urbackup_snaps/1c11ec20273f86b9ecee6ac47cdfd67fab161d8e72836f76
/dev/dm-6 493G 2.0G 491G 1% /mnt/urbackup_snaps/13ccefe426a13fbadda9cab1fb209b34f432c15fa7f272c8
/dev/dm-8 493G 2.0G 491G 1% /mnt/urbackup_snaps/8650d59823f4297cf05712a78d92cdfe75e190928afffb56
Start backup and wait when finished backup (not reset server).
root@snap-leftover-nas-original:~# date
Sun 11 Apr 2021 08:02:24 PM MSK
root@snap-leftover-nas-original:~# df -h
Filesystem Size Used Avail Use% Mounted on
udev 977M 0 977M 0% /dev
tmpfs 200M 7.0M 193M 4% /run
/dev/sda1 19G 4.6G 14G 26% /
tmpfs 998M 0 998M 0% /dev/shm
tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs 998M 0 998M 0% /sys/fs/cgroup
tmpfs 998M 4.0K 998M 1% /tmp
/dev/mapper/vg7zbackups-lv7zbackups 1.7G 17M 1.6G 1% /backups/nas7zbackups
/dev/mapper/vgdata-data1 493G 2.0G 491G 1% /srv/dev-disk-by-id-dm-name-vgdata-data1
/dev/dm-4 493G 2.0G 491G 1% /mnt/urbackup_snaps/1c11ec20273f86b9ecee6ac47cdfd67fab161d8e72836f76
/dev/dm-6 493G 2.0G 491G 1% /mnt/urbackup_snaps/13ccefe426a13fbadda9cab1fb209b34f432c15fa7f272c8
/dev/dm-8 493G 2.0G 491G 1% /mnt/urbackup_snaps/8650d59823f4297cf05712a78d92cdfe75e190928afffb56
/dev/dm-10 493G 2.0G 491G 1% /mnt/urbackup_snaps/987e8215ec66025797eceeccba33240c18977377e8cd1cbb
root@snap-leftover-nas-original:~# lvs
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
lv7zbackups vg7zbackups -wi-ao---- 1.76g
data1 vgdata owi-aos--- 500.02g
urbackup_snap_13ccefe426a13fbadda9cab1fb209b34f432c15fa7f272c8 vgdata swi-aos--- 50.00g data1 0.01
urbackup_snap_1c11ec20273f86b9ecee6ac47cdfd67fab161d8e72836f76 vgdata swi-aos--- 99.99g data1 0.01
urbackup_snap_8650d59823f4297cf05712a78d92cdfe75e190928afffb56 vgdata swi-aos--- 25.00g data1 0.01
urbackup_snap_987e8215ec66025797eceeccba33240c18977377e8cd1cbb vgdata swi-aos--- 12.50g data1 0.01
Backup succeeded without errors and warnings. All 4 snapshots deleted!
I think now it works fine!
root@snap-leftover-nas-original:~# date
Sun 11 Apr 2021 08:06:59 PM MSK
root@snap-leftover-nas-original:~# lvs
LV VG Attr LSize Pool Origin Data% Meta% Move Log Cpy%Sync Convert
lv7zbackups vg7zbackups -wi-ao---- 1.76g
data1 vgdata -wi-ao---- 500.02g
root@snap-leftover-nas-original:~# df -h
Filesystem Size Used Avail Use% Mounted on
udev 977M 0 977M 0% /dev
tmpfs 200M 7.0M 193M 4% /run
/dev/sda1 19G 4.6G 14G 26% /
tmpfs 998M 0 998M 0% /dev/shm
tmpfs 5.0M 0 5.0M 0% /run/lock
tmpfs 998M 0 998M 0% /sys/fs/cgroup
tmpfs 998M 4.0K 998M 1% /tmp
/dev/mapper/vg7zbackups-lv7zbackups 1.7G 17M 1.6G 1% /backups/nas7zbackups
/dev/mapper/vgdata-data1 493G 2.0G 491G 1% /srv/dev-disk-by-id-dm-name-vgdata-data1
Interesting strings at client log1: Old shadow copy of /srv/dev-disk-by-id-dm-name-vgdata-data1 still in use. Not deleting or using it.
2021-04-11 20:06:52: ClientService cmd: #IVzl3Px15gOnrxDz0FnW4#2LOGDATA 1618160811 0-1618160511-Starting unscheduled full file backup...
1-1618160542-Old shadow copy of /srv/dev-disk-by-id-dm-name-vgdata-data1 still in use. Not deleting or using it.
1-1618160542-Old shadow copy of /srv/dev-disk-by-id-dm-name-vgdata-data1 still in use. Not deleting or using it.
1-1618160542-Old shadow copy of /srv/dev-disk-by-id-dm-name-vgdata-data1 still in use. Not deleting or using it.
1-1618160542-Old shadow copy of /srv/dev-disk-by-id-dm-name-vgdata-data1 still in use. Not deleting or using it.
1-1618160542-Old shadow copy of /srv/dev-disk-by-id-dm-name-vgdata-data1 still in use. Not deleting or using it.
1-1618160542-Old shadow copy of /srv/dev-disk-by-id-dm-name-vgdata-data1 still in use. Not deleting or using it.
0-1618160542-Logical volume "urbackup_snap_987e8215ec66025797eceeccba33240c18977377e8cd1cbb" created.
0-1618160542-Indexing of "dev-disk-by-id-dm-name-vgdata-data1" done. 45 filesystem lookups 0 db lookups and 0 db updates
0-1618160542-snap-leftover-nas-original.local: Loading file list...
0-1618160542-snap-leftover-nas-original.local: Started loading files...
0-1618160542-Waiting for file transfers...
Interesting strings at client log2: Destroying LVM snapshot. All 4 snapshots.
2021-04-11 20:05:46: Unmounting /dev/mapper/vgdata-urbackup_snap_987e8215ec66025797eceeccba33240c18977377e8cd1cbb at /mnt/urbackup_snaps/987e8215ec66025797eceeccba33240c18977377e8cd1cbb...
2021-04-11 20:05:46: Destroying LVM snapshot /dev/mapper/vgdata-urbackup_snap_987e8215ec66025797eceeccba33240c18977377e8cd1cbb...
2021-04-11 20:05:46: Logical volume "urbackup_snap_987e8215ec66025797eceeccba33240c18977377e8cd1cbb" successfully removed
2021-04-11 20:05:47: Deleting Shadowcopy for dir "/srv/dev-disk-by-id-dm-name-vgdata-data1"
2021-04-11 20:05:47: rc=0 hasError=true state=0
2021-04-11 20:05:47: FileSrv: Received data...
2021-04-11 20:05:47: FileSrv: Received a Packet.
2021-04-11 20:05:47: ClientService cmd: #IVzl3Px15gOnrxDz0FnW4#2DID BACKUP status_id=1&server_token=Iq6thsabqfnQjZhD45YT&group=0
2021-04-11 20:05:47: Removing running process (1) id 2 server_id 1 token Iq6thsabqfnQjZhD45YT action 2
2021-04-11 20:05:47: rc=0 hasError=true state=0
2021-04-11 20:05:47: FileSrv: Sending script urbackup/FILE_METADATA|Iq6thsabqfnQjZhD45YT|62 not finished yet
2021-04-11 20:05:47: FileSrv: Received data...
2021-04-11 20:05:47: FileSrv: Received a Packet.
2021-04-11 20:05:47: Received flush.
2021-04-11 20:05:47: FileSrv: Recv Error in RecvMessage
2021-04-11 20:05:47: FileSrv: ClientThread deleted. 1024 KB Memory freed.
2021-04-11 20:05:47: FileSrv: Received data...
2021-04-11 20:05:47: FileSrv: Received a Packet.
2021-04-11 20:05:47: FileSrv: Sending script output (normal) urbackup/FILE_METADATA|Iq6thsabqfnQjZhD45YT|62 metadata_id=0
2021-04-11 20:05:47: FileSrv: Mapped name: /usr/local/var/urbackup/data/FILE_METADATA|Iq6thsabqfnQjZhD45YT|62
2021-04-11 20:05:47: FileSrv: Sent script urbackup/FILE_METADATA|Iq6thsabqfnQjZhD45YT|62
2021-04-11 20:05:47: FileSrv: Received a Packet.
2021-04-11 20:05:47: Received flush.
2021-04-11 20:05:47: FileSrv: Received data...
2021-04-11 20:05:47: FileSrv: Received a Packet.
2021-04-11 20:05:47: FileSrv: Finishing script urbackup/FILE_METADATA|Iq6thsabqfnQjZhD45YT|62
2021-04-11 20:05:47: FileSrv: Mapped name: /usr/local/var/urbackup/data/FILE_METADATA|Iq6thsabqfnQjZhD45YT|62
2021-04-11 20:05:47: Removing pipe file urbackup/FILE_METADATA|Iq6thsabqfnQjZhD45YT|62
2021-04-11 20:05:47: Pipe file has exit code 0
2021-04-11 20:05:51: ClientService cmd: #IVzl3Px15gOnrxDz0FnW4#2PING RUNNING pc_done=100&status_id=1&speed_bpms=0&total_bytes=2041075712&done_bytes=2041137392&paused_fb=1#token=Iq6thsabqfnQjZhD45YT
2021-04-11 20:06:01: ClientService cmd: #IVzl3Px15gOnrxDz0FnW4#2PING RUNNING pc_done=100&status_id=1&speed_bpms=0&total_bytes=2041075712&done_bytes=2041137392&paused_fb=1#token=Iq6thsabqfnQjZhD45YT
2021-04-11 20:06:11: ClientService cmd: #IVzl3Px15gOnrxDz0FnW4#2PING RUNNING pc_done=100&status_id=1&speed_bpms=0&total_bytes=2041075712&done_bytes=2041137392&paused_fb=1#token=Iq6thsabqfnQjZhD45YT
2021-04-11 20:06:13: ClientService cmd: PONG
2021-04-11 20:06:21: ClientService cmd: #IVzl3Px15gOnrxDz0FnW4#2PING RUNNING pc_done=100&status_id=1&speed_bpms=0&total_bytes=2041075712&done_bytes=2041137392&paused_fb=1#token=Iq6thsabqfnQjZhD45YT
2021-04-11 20:06:31: ClientService cmd: #IVzl3Px15gOnrxDz0FnW4#2PING RUNNING pc_done=100&status_id=1&speed_bpms=0&total_bytes=2041075712&done_bytes=2041137392&paused_fb=1#token=Iq6thsabqfnQjZhD45YT
2021-04-11 20:06:41: ClientService cmd: #IVzl3Px15gOnrxDz0FnW4#2PING RUNNING pc_done=100&status_id=1&speed_bpms=0&total_bytes=2041075712&done_bytes=2041137392&paused_fb=1#token=Iq6thsabqfnQjZhD45YT
2021-04-11 20:06:47: Reference not found. Iterating over all start tokens and share names for deletion
2021-04-11 20:06:47: Deleting shadowcopy for path "/srv/dev-disk-by-id-dm-name-vgdata-data1" -2
2021-04-11 20:06:47: ClientService cmd: #IVzl3Px15gOnrxDz0FnW4#WRITE TOKENS
2021-04-11 20:06:47: FileSrv: 1 min Timeout deleting Buffers (1024 KB) and waiting 1h more...
2021-04-11 20:06:47: FileSrv: 1 min Timeout deleting Buffers (1024 KB) and waiting 1h more...
2021-04-11 20:06:47: Unmounting /dev/mapper/vgdata-urbackup_snap_1c11ec20273f86b9ecee6ac47cdfd67fab161d8e72836f76 at /mnt/urbackup_snaps/1c11ec20273f86b9ecee6ac47cdfd67fab161d8e72836f76...
2021-04-11 20:06:47: Destroying LVM snapshot /dev/mapper/vgdata-urbackup_snap_1c11ec20273f86b9ecee6ac47cdfd67fab161d8e72836f76...
2021-04-11 20:06:47: Logical volume "urbackup_snap_1c11ec20273f86b9ecee6ac47cdfd67fab161d8e72836f76" successfully removed
2021-04-11 20:06:47: Deleting Shadowcopy for dir "/srv/dev-disk-by-id-dm-name-vgdata-data1"
2021-04-11 20:06:47: Reference not found. Iterating over all start tokens and share names for deletion
2021-04-11 20:06:47: Deleting shadowcopy for path "/srv/dev-disk-by-id-dm-name-vgdata-data1" -2
2021-04-11 20:06:48: Unmounting /dev/mapper/vgdata-urbackup_snap_13ccefe426a13fbadda9cab1fb209b34f432c15fa7f272c8 at /mnt/urbackup_snaps/13ccefe426a13fbadda9cab1fb209b34f432c15fa7f272c8...
2021-04-11 20:06:48: Destroying LVM snapshot /dev/mapper/vgdata-urbackup_snap_13ccefe426a13fbadda9cab1fb209b34f432c15fa7f272c8...
2021-04-11 20:06:48: Logical volume "urbackup_snap_13ccefe426a13fbadda9cab1fb209b34f432c15fa7f272c8" successfully removed
2021-04-11 20:06:48: Deleting Shadowcopy for dir "/srv/dev-disk-by-id-dm-name-vgdata-data1"
2021-04-11 20:06:48: Reference not found. Iterating over all start tokens and share names for deletion
2021-04-11 20:06:48: Deleting shadowcopy for path "/srv/dev-disk-by-id-dm-name-vgdata-data1" -2
2021-04-11 20:06:48: Unmounting /dev/mapper/vgdata-urbackup_snap_8650d59823f4297cf05712a78d92cdfe75e190928afffb56 at /mnt/urbackup_snaps/8650d59823f4297cf05712a78d92cdfe75e190928afffb56...
2021-04-11 20:06:48: Destroying LVM snapshot /dev/mapper/vgdata-urbackup_snap_8650d59823f4297cf05712a78d92cdfe75e190928afffb56...
2021-04-11 20:06:48: Logical volume "urbackup_snap_8650d59823f4297cf05712a78d92cdfe75e190928afffb56" successfully removed
2021-04-11 20:06:48: Deleting Shadowcopy for dir "/srv/dev-disk-by-id-dm-name-vgdata-data1"Hi @uroni !
Your last patch works fine ( urbackup-client-2.4.12.0(1).tar.gz and pathed it 0001-Reset-target-path-when-snapshot-is-still-in-use.patch.). The problem is solved!
What next? I mean will you public new client version with this fixes?