The dmesg logs shows:
Mar 9 16:17:43 corp101 kernel: datto: block device is already being traced: -22
Mar 9 16:17:43 corp101 kernel: datto: error setting up base block device: -22
Mar 9 16:17:43 corp101 kernel: datto: error setting up tracer as active snapshot: -22
Mar 9 16:17:43 corp101 kernel: datto: error during setup ioctl handler: -22
The issue seems to be sporadic, sometimes it went just fine.
Seems like I found the issue. For some reason, last successful file backup reported:
Info
02/18/21 05:18
Removing snapshot on “MYHOSTNAME” for path “rootfs” failed: FAILED
so there was still /dev/mapper/wsnap-38… which I tried to remove with:
dmsetup remove wsnap-38
it reported to me the error “Device or resource busy”. I tried to catch it up with lsof, but no luck on this. dmesg also said:
Mar 9 22:33:13 corp101 kernel: datto: device specified is busy: -16
So I was forced to reboot the server to get this mapper removed. Next incremental backup went smoothly, snapshot was created and removed by Urbackup.
I’d be very interested in an actual fix for this. I experience this problem for a while now and could only solve this with reboots so far. I’m not sure though whether that is urbackup related at all or a dattobd problem
Turn on client debug logging, then post when it fails to cleanup the previous snapshot. Maybe there is some information there to narrow down the problem…
@uroni Hey Martin. Attaching start of the process with the debug enabled:
2021-03-16 14:51:21: Started UrBackupClient Backend...
2021-03-16 14:51:22: Looking for old Sessions... 0 sessions
2021-03-16 14:51:22: Internet only mode not enabled. Waiting for local server for 3:00...
2021-03-16 14:51:22: Final path: /
2021-03-16 14:51:28: urbackupserver: No available slots... starting new Worker
2021-03-16 14:51:28: ClientService cmd: #IB4y7kvzROD4neEsnKpgm#1CHANNEL capa=5652&token=a10XN2zCblpBlU9NlJUv&restore_version=1&virtual_client=
2021-03-16 14:51:28: New channel: Number of Channels: 1
2021-03-16 14:51:29: ClientService cmd: #IB4y7kvzROD4neEsnKpgm#2PING RUNNING pc_done=&status_id=2117&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=a10XN2zCblpBlU9NlJUv
2021-03-16 14:51:29: ClientService cmd: #IB4y7kvzROD4neEsnKpgm#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=2117&async=1#token=a10XN2zCblpBlU9NlJUv
2021-03-16 14:51:29: Removing VSS log data...
2021-03-16 14:51:29: Final path: /
2021-03-16 14:51:29: rc=0 hasError=true state=0
2021-03-16 14:51:29: ClientService cmd: #IB4y7kvzROD4neEsnKpgm#WAIT FOR INDEX async_id=07fc413db545ba0635493c5afb9a50e1#token=a10XN2zCblpBlU9NlJUv
2021-03-16 14:51:29: Wait for async index 07fc413db545ba0635493c5afb9a50e1
2021-03-16 14:51:29: Script list at "/usr/local/etc/urbackup/scripts/list" does not exist. Skipping.
2021-03-16 14:51:29: Script "/usr/local/etc/urbackup/prefilebackup" does not exist
2021-03-16 14:51:29: Final path: /
2021-03-16 14:51:29: Creating shadowcopy of "rootfs" in indexDirs()
2021-03-16 14:51:29: ERROR: Creating snapshot of "/" failed
2021-03-16 14:51:29: ERROR: Snapshotting device /dev/sda2 via dattobd...
2021-03-16 14:51:29: ERROR: Using /dev/datto1...
2021-03-16 14:51:29: ERROR: driver returned an error performing specified action. check dmesg for more info: Invalid argument
2021-03-16 14:51:29: done.
2021-03-16 14:51:29: ERROR: Creating snapshot of "rootfs" failed.
2021-03-16 14:51:29: Indexing "rootfs"...
2021-03-16 14:51:29: Not following symlink "/etc/mtab" because symlink target at "/proc/4031194/mounts" is excluded
2021-03-16 14:51:29: Not following symlink "/etc/apache2/run" because symlink target at "/run/apache2" is excluded
2021-03-16 14:51:29: Not following symlink "/etc/systemd/system/NetworkManager.service" because symlink target at "/dev/null" is excluded
2021-03-16 14:51:29: Not following symlink "/etc/systemd/system/firewalld.service" because symlink target at "/dev/null" is excluded
2021-03-16 14:51:39: ClientService cmd: #IB4y7kvzROD4neEsnKpgm#2PING RUNNING pc_done=&eta_ms=1849941&status_id=2117&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=a10XN2zCblpBlU9NlJUv
2021-03-16 14:51:49: ClientService cmd: #IB4y7kvzROD4neEsnKpgm#2PING RUNNING pc_done=&eta_ms=1839940&status_id=2117&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=a10XN2zCblpBlU9NlJUv
2021-03-16 14:51:59: ClientService cmd: #IB4y7kvzROD4neEsnKpgm#2PING RUNNING pc_done=&eta_ms=1829939&status_id=2117&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=a10XN2zCblpBlU9NlJUv
2021-03-16 14:52:09: ClientService cmd: #IB4y7kvzROD4neEsnKpgm#2PING RUNNING pc_done=&eta_ms=1819938&status_id=2117&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=a10XN2zCblpBlU9NlJUv
2021-03-16 14:52:19: ClientService cmd: #IB4y7kvzROD4neEsnKpgm#2PING RUNNING pc_done=&eta_ms=1809934&status_id=2117&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=a10XN2zCblpBlU9NlJUv
2021-03-16 14:52:28: ClientService cmd: PONG
2021-03-16 14:52:29: ClientService cmd: #IB4y7kvzROD4neEsnKpgm#2PING RUNNING pc_done=&eta_ms=1799933&status_id=2117&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=a10XN2zCblpBlU9NlJUv
2021-03-16 14:52:34: Not following symlink "/var/lock" because symlink target at "/run/lock" is excluded
2021-03-16 14:52:39: ClientService cmd: #IB4y7kvzROD4neEsnKpgm#2PING RUNNING pc_done=&eta_ms=1789932&status_id=2117&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=a10XN2zCblpBlU9NlJUv
2021-03-16 14:52:46: Indexing of "rootfs" done. 119762 filesystem lookups 0 db lookups and 0 db updates
2021-03-16 14:52:46: Script "/usr/local/etc/urbackup/postfileindex" does not exist
2021-03-16 14:52:46: Async index 07fc413db545ba0635493c5afb9a50e1 finished with "done"
2021-03-16 14:52:46: ClientService cmd: #IB4y7kvzROD4neEsnKpgm#GET VSSLOG
2021-03-16 14:52:46: VSS logdata - 409 bytes
2021-03-16 14:52:46: rc=0 hasError=true state=0
2021-03-16 14:52:46: rc=0 hasError=true state=0
After that it’s coming with a lot of debug related to pushed files and ended with:
2021-03-16 15:03:13: FileSrv: Recv Error in RecvMessage
2021-03-16 15:03:16: FileSrv: ClientThread deleted. 1024 KB Memory freed.
2021-03-16 15:03:19: rc=0 hasError=true state=0
2021-03-16 15:03:20: FileSrv: Recv Error in RecvMessage
2021-03-16 15:03:20: ClientService cmd: #IB4y7kvzROD4neEsnKpgm#2LOGDATA 1615903399 0-1615902689-Starting unscheduled incremental file backup...
2-1615902766-Creating snapshot of "/" failed
2-1615902766-Snapshotting device /dev/sda2 via dattobd...
2-1615902766-Using /dev/datto1...
2-1615902766-driver returned an error performing specified action. check dmesg for more info: Invalid argument
2-1615902766-Creating snapshot of "rootfs" failed.
0-1615902766-Indexing of "rootfs" done. 119762 filesystem lookups 0 db lookups and 0 db updates
0-1615902766-MYHOSTNAME: Loading file list...
0-1615902767-MYHOSTNAME: Calculating file tree differences...
0-1615902768-MYHOSTNAME: Calculating tree difference size...
0-1615902768-MYHOSTNAME: Linking unchanged and loading new files...
0-1615902768-Referencing snapshot on "MYHOSTNAME" for path "rootfs" failed: FAILED
1-1615902852-Error getting complete file "a10XN2zCblpBlU9NlJUv|rootfs/home/josmulle/mail/josmuller.nl/info/cur/1615820490.M128260P3479079.MYHOSTNAME,S=17675,W=18039:2," from MYHOSTNAME. Errorcode: CANNOT_OPEN_FILE (3)
1-1615903117-Error getting complete file "a10XN2zCblpBlU9NlJUv|rootfs/usr/local/var/urbackup/data/filelist_new_0.ub" from MYHOSTNAME. Errorcode: CANNOT_OPEN_FILE (3)
1-1615903318-Error getting complete file "a10XN2zCblpBlU9NlJUv|rootfs/var/log/dcpumon/toplog.1615900801" from MYHOSTNAME. Errorcode: CANNOT_OPEN_FILE (3)
1-1615903318-Error getting complete file "a10XN2zCblpBlU9NlJUv|rootfs/var/log/dcpumon/toplog.1615901101" from MYHOSTNAME. Errorcode: CANNOT_OPEN_FILE (3)
1-1615903318-Error getting complete file "a10XN2zCblpBlU9NlJUv|rootfs/var/log/dcpumon/toplog.1615901401" from MYHOSTNAME. Errorcode: CANNOT_OPEN_FILE (3)
0-1615903326-Waiting for file transfers...
0-1615903326-Waiting for file hashing and copying threads...
1-1615903387-Not all folder metadata could be applied. Metadata was inconsistent.
0-1615903387-Writing new file list...
0-1615903391-All metadata was present
0-1615903392-Transferred 5.25319 GB - Average speed: 80.6505 MBit/s
0-1615903399-Time taken for backing up client MYHOSTNAME: 11m 50s
0-1615903399-Backup completed with issues
Just in case I’ve hidden our server’s hostname with MYHOSTNAME.
It seems like previous snapshot wasn’t removed, still exists at:
[root@MYHOSTNAME][/dev/mapper]: ll
total 0
drwxr-xr-x 2 root root 80 Mar 10 22:51 .
drwxr-xr-x 20 root root 5.9K Mar 10 22:51 …
crw------- 1 root root 10, 236 Mar 9 22:42 control
lrwxrwxrwx 1 root root 7 Mar 10 22:51 wsnap-4a591d721923cb63b3eafb74527ac15030c8e4d4aac5dd1c -> …/dm-0
I have the same issue on a Ubuntu 20.04.4 LTS; Kernel 5.4.0-105-generic x86_64
Level Time Message
Errors
03/28/22 19:55
Creating snapshot of "/mailcow_backups" failed
Errors
03/28/22 19:55
Snapshotting device /dev/sda1 via dattobd...
Errors
03/28/22 19:55
Using /dev/datto1...
Errors
03/28/22 19:55
driver returned an error performing specified action. check dmesg for more info: Invalid argument
Errors
03/28/22 19:55
Creating snapshot of "mailcow_backups" failed.
dmesg
[200809.885307] datto: block device is already being traced: -22
[200809.886917] datto: error setting up base block device: -22
[200809.888380] datto: error setting up tracer as active snapshot: -22
[200809.889929] datto: error during setup ioctl handler: -22
reboot fixed it for now.
But the logs in Ur show
Info
03/28/22 21:15
Removing snapshot on "116.xxx.224.xxx" for path "mailcow_backups" failed: FAILED**
