Datto: block device is already being traced

arthur_l · March 9, 2021, 4:56pm

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.

arthur_l · March 9, 2021, 11:34pm

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

DrRSatzteil · March 14, 2021, 9:33pm

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

uroni · March 15, 2021, 6:35pm

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…

arthur_l · March 16, 2021, 2:07pm

@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

uroni · March 16, 2021, 9:19pm

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

ckid · March 28, 2022, 7:06pm

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.

ckid · March 30, 2022, 10:51am

I disabled datto via

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

Now at least my backups work.

Rex2020 · May 9, 2023, 6:13pm

Same issue for me. 22.04 fresh host. Just setup in lab to test backup and every couple of days the backups will start failing saying the device is already being tracked. Reboot resolves issue, but would like to aviod regular reboots. Anyone found a fix for this?

Mishman · October 27, 2023, 10:23am

Same behaviour on MX Linux 21 (debian 11). Kernel 5.10.

UPD.
It seems like blok devices relating to dattobd persist in system and can be seen using lsblk. For me it is /.datto0 and disk mapping wsnap-******* under it. After reboot /.datto0 and mapping are not seen in system. I remove mapping using dmsetup, but it had no effect. I don’t know how to delete/.datto0, i can’t make echo 1, there is no ‘device’ under /sys/block/.datto0/