Datto: block device is already being traced

Hey Guys,

We’re running several instances with the failed file backups running on CentOS 7 with dattobd snapshotting enabled:

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.

Server version: 2.4.13
Clinet version: 2.4.11

Could you please take a look?

Thank you.

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.

Hope someone find this usefull :wink:

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 :man_shrugging:

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

Yes the previous backup wasn’t removed. We’d need a log of that. Maybe that shows why it couldn’t be removed…

Is this any nearer to a solution?

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**

dmesg | grep datto

[    5.154706] dattobd: loading out-of-tree module taints kernel.
[    5.156867] dattobd: module verification failed: signature and/or required key missing - tainting kernel
[    5.160117] datto: failed to locate system call table, persistence disabled
[    5.162073] dattobd: root block device = /dev/disk/by-uuid/64a65c41-0a19-4f9c-b68b-8577bc58b2e0
[    5.175881] dattobd: mounting /dev/disk/by-uuid/64a65c41-0a19-4f9c-b68b-8577bc58b2e0 as ext4

dmesg | grep urbackup

[    6.019669] systemd[1]: Configuration file /lib/systemd/system/urbackupclientbackend.service is marked executable. Please remove executable permission bits. Proceeding anyway.

I disabled datto via

 rm /usr/local/etc/urbackup/snapshot.cfg

Now at least my backups work.