Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Dattobd not working on Ubuntu Server 16.04.1 #47

Closed
Codyksp opened this issue Aug 24, 2016 · 20 comments
Closed

Dattobd not working on Ubuntu Server 16.04.1 #47

Codyksp opened this issue Aug 24, 2016 · 20 comments

Comments

@Codyksp
Copy link

Codyksp commented Aug 24, 2016

I have recently installed dattobd to be used together with UrBackup to make full file backups with a snapshot. We have 2 Ubuntu servers, both the same version. One server works fine and the other one won't even start a backup.

I have only performed a fresh install of UrBackup (choosing dattobd) and a fresh installation of dattobd according to the install file.

sudo apt-key adv --recv-keys --keyserver keyserver.ubuntu.com 29FF164C
echo "deb https://cpkg.datto.com/repositories $(lsb_release -sc) main" | sudo tee /etc/apt/sources.list.d/datto-linux-agent.list
sudo apt-get update
sudo apt-get install dattobd-dkms dattobd-utils

The following is output from dmesg on both servers:

Server A (working):

root@VVICT23:~# dmesg | grep datto
[    3.400489] dattobd: module verification failed: signature and/or required key missing - tainting kernel
[ 1478.065268] datto: illegal to perform setup while unmounted: -22
[ 1478.065389] datto: error during setup ioctl handler: -22
[95846.519870] datto: illegal to perform setup while unmounted: -22
[95846.519954] datto: error during setup ioctl handler: -22

I don't know what the last 4 errors mean (or if they even matter) but the backups are working fine.

Server B (not working):

root@VVICT14:~# dmesg | grep datto
[    3.144832] dattobd: module verification failed: signature and/or required key missing - tainting kernel
[    3.193966] IP: [<ffffffffc016811d>] agent_init+0x11d/0x1000 [dattobd]
[    3.193984] Modules linked in: dattobd(OE+) autofs4 dm_mirror dm_region_hash dm_log hid_generic usbhid hid psmouse ttm drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm pata_acpi ahci libahci floppy
[    3.193992] RIP: 0010:[<ffffffffc016811d>]  [<ffffffffc016811d>] agent_init+0x11d/0x1000 [dattobd]
[    3.194111] RIP  [<ffffffffc016811d>] agent_init+0x11d/0x1000 [dattobd]

I have absolutely no idea what these messages mean but they don't look good to me.

Here is also the log output from UrBackup on the working server:

Level Time Message
Info 24/08/16 10:10 Starting full file backup...
Info 24/08/16 10:10 Snapshotting device /dev/mapper/TetraSSH--vg-root via dattobd...
Info 24/08/16 10:10 Using /dev/datto0...
Info 24/08/16 10:10 Mounting /dev/mapper/wsnap-66a48c9364f7486614c74c9493f6bf4c0557d4788d32b663...
Info 24/08/16 10:10 Indexing of "root" done. 16245 filesystem lookups 0 db lookups and 0 db updates
Info 24/08/16 10:10 VVICT23: Loading file list...
Info 24/08/16 10:10 VVICT23: Started loading files...
Info 24/08/16 10:15 Waiting for file transfers...
Info 24/08/16 10:18 Waiting for file hashing and copying threads...
Info 24/08/16 10:18 Saving file metadata...
Info 24/08/16 10:18 Writing new file list...
Info 24/08/16 10:18 All metadata was present
Info 24/08/16 10:18 Transferred 1.49572 GB - Average speed: 26.3852 MBit/s
Info 24/08/16 10:18 Time taken for backing up client VVICT23: 8m 40s
Info 24/08/16 10:18 Backup succeeded

@tcaputi
Copy link

tcaputi commented Aug 24, 2016

The messages from server A are normal. They are simply messages indicating usage errors.

Server B is a kernel panic which is a much more serious problem. In your case, this is almost definitely the result of having updated your kernel without rebooting your machine. DKMS tries to build kernel modules for every installed and running kernel, but in an effort to save space / work it has a feature called "weak modules" that tries to detect whether 2 installed kernels are similar enough that they can use the same kernel module. Unfortunately, dattobd has to do some unusual things (namely hooking into the syscall table) which DKMS fails to account for. In the end, it tries to use the kernel module for the running kernel for the installed kernel, which promptly causes a crash.

The solution is simply to uninstall dattobd, reboot your machine (which will cause the system to use latest installed kernel) and then reinstall dattobd.

We should have a paragraph about this in the troubleshooting section, so I will leave this issue open until we get around to it.

@Codyksp
Copy link
Author

Codyksp commented Aug 24, 2016

We already tried reinstalling before but it did not help, I have now done the following:

apt-get purge datto*
reboot
apt-get install datto-dkms
apt-get install datto-utils
reboot

After these commands I receive slightly different errors:

root@VVICT14:~# dmesg | grep datto
[    3.047646] dattobd: module verification failed: signature and/or required key missing - tainting kernel
[    3.102477] IP: [<ffffffffc00f411d>] agent_init+0x11d/0x1000 [dattobd]
[    3.102498] Modules linked in: dattobd(OE+) autofs4 dm_mirror dm_region_hash dm_log hid_generic usbhid hid pata_acpi psmouse ttm drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm ahci libahci floppy
[    3.102509] RIP: 0010:[<ffffffffc00f411d>]  [<ffffffffc00f411d>] agent_init+0x11d/0x1000 [dattobd]
[    3.102631] RIP  [<ffffffffc00f411d>] agent_init+0x11d/0x1000 [dattobd]

@wspeirs
Copy link

wspeirs commented Aug 24, 2016

Looks like you are still getting a kernel panic. Can you post the output from dmesg from about 3.0 onwards? Thanks!

@Codyksp
Copy link
Author

Codyksp commented Aug 24, 2016

[    2.951542] systemd[1]: Set hostname to <VVICT14>.
[    3.240227] systemd[1]: Configuration file /lib/systemd/system/urbackupclientbackend.service is marked executable. Please remove executable permission bits. Proceeding anyway.
[    3.276576] systemd[1]: Created slice System Slice.
[    3.280883] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[    3.284477] systemd[1]: Reached target Encrypted Volumes.
[    3.287126] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
[    3.289624] systemd[1]: Reached target Remote File Systems (Pre).
[    3.292091] systemd[1]: Listening on Device-mapper event daemon FIFOs.
[    3.294409] systemd[1]: Reached target Remote File Systems.
[    3.296551] systemd[1]: Listening on udev Kernel Socket.
[    3.298530] systemd[1]: Listening on fsck to fsckd communication Socket.
[    3.300655] systemd[1]: Listening on Journal Socket.
[    3.314464] systemd[1]: Starting Create list of required static device nodes for the current kernel...
[    3.322501] systemd[1]: Starting Load Kernel Modules...
[    3.327360] systemd[1]: Starting Set console keymap...
[    3.331602] dattobd: module verification failed: signature and/or required key missing - tainting kernel
[    3.332221] systemd[1]: Mounting Debug File System...
[    3.337202] systemd[1]: Created slice User and Session Slice.
[    3.339944] systemd[1]: Reached target Slices.
[    3.342475] systemd[1]: Listening on LVM2 metadata daemon socket.
[    3.345957] systemd[1]: Starting Monitoring of LVM2 mirrors, snapshots etc. using dmeventd or progress polling...
[    3.350013] systemd[1]: Listening on LVM2 poll daemon socket.
[    3.352413] systemd[1]: Listening on udev Control Socket.
[    3.355397] systemd[1]: Mounting Huge Pages File System...
[    3.357724] systemd[1]: Listening on Journal Audit Socket.
[    3.360492] systemd[1]: Starting Uncomplicated firewall...
[    3.363382] systemd[1]: Mounting POSIX Message Queue File System...
[    3.365721] systemd[1]: Reached target User and Group Name Lookups.
[    3.368054] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    3.370445] systemd[1]: Listening on Syslog Socket.
[    3.372868] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[    3.373558] BUG: unable to handle kernel paging request at ffff880000800000
[    3.373567] IP: [<ffffffffc00fc11d>] agent_init+0x11d/0x1000 [dattobd]
[    3.373569] PGD 4200067 PUD 4201067 PMD 4204067 PTE 0
[    3.373570] Oops: 0000 [#1] SMP
[    3.373595] Modules linked in: dattobd(OE+) autofs4 dm_mirror dm_region_hash dm_log hid_generic usbhid hid psmouse ttm drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm ahci libahci pata_acpi floppy
[    3.373600] CPU: 1 PID: 818 Comm: systemd-modules Tainted: G           OE   4.4.0-34-generic #53-Ubuntu
[    3.373600] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 0.0.0 02/06/2015
[    3.373609] task: ffff8800348a2580 ti: ffff880079828000 task.ti: ffff880079828000
[    3.373612] RIP: 0010:[<ffffffffc00fc11d>]  [<ffffffffc00fc11d>] agent_init+0x11d/0x1000 [dattobd]
[    3.373615] RSP: 0018:ffff88007982bc80  EFLAGS: 00010286
[    3.373615] RAX: ffff8800007ffad8 RBX: 0000000000000000 RCX: 0000000000000000
[    3.373616] RDX: 0000000000000000 RSI: ffff880034bf1a90 RDI: ffffffff81ec4c00
[    3.373616] RBP: ffff88007982bc88 R08: 000000000001a080 R09: ffffffff813f4a1b
[    3.373617] R10: ffffea0000d12000 R11: 0000000000000000 R12: ffff880034854440
[    3.373617] R13: 0000000000000000 R14: ffffffffc00fc000 R15: ffff880034ac73c0
[    3.373618] FS:  00007f3e4430f740(0000) GS:ffff88007e080000(0000) knlGS:0000000000000000
[    3.373619] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[    3.373620] CR2: ffff880000800000 CR3: 0000000034ca2000 CR4: 00000000000006e0
[    3.373623] Stack:
[    3.373624]  ffffffff81e11080 ffff88007982bd08 ffffffff81002123 ffffea0000d34440
[    3.373626]  ffff88007982bce0 0000000000000286 0000000000000001 0000000000000014
[    3.373627]  ffffffff811eb843 0000000000000001 ffffffffc0165300 0000000000000018
[    3.373630] Call Trace:
[    3.373666]  [<ffffffff81002123>] do_one_initcall+0xb3/0x200
[    3.373676]  [<ffffffff811eb843>] ? kmem_cache_alloc_trace+0x183/0x1f0
[    3.373686]  [<ffffffff8118c763>] do_init_module+0x5f/0x1cf
[    3.373692]  [<ffffffff8110a1c7>] load_module+0x1667/0x1c00
[    3.373693]  [<ffffffff81106770>] ? __symbol_put+0x60/0x60
[    3.373702]  [<ffffffff81213180>] ? kernel_read+0x50/0x80
[    3.373704]  [<ffffffff8110a9a4>] SYSC_finit_module+0xb4/0xe0
[    3.373705]  [<ffffffff8110a9ee>] SyS_finit_module+0xe/0x10
[    3.373717]  [<ffffffff8182def2>] entry_SYSCALL_64_fastpath+0x16/0x71
[    3.373729] Code: c6 48 c7 c7 a8 3d 16 c0 e8 b8 01 09 c1 e9 b7 00 00 00 31 c0 80 3d b3 91 06 00 00 0f 84 af 00 00 00 48 b8 00 00 00 00 00 88 ff ff <48> 81 b8 28 05 00 00 00 08 23 81 75 0d 48 81 b8 30 05 00 00 d0
[    3.373731] RIP  [<ffffffffc00fc11d>] agent_init+0x11d/0x1000 [dattobd]
[    3.373731]  RSP <ffff88007982bc80>
[    3.373732] CR2: ffff880000800000
[    3.373757] ---[ end trace c78a060e8cff2c7e ]---
[    3.449597] systemd[1]: Listening on Journal Socket (/dev/log).
[    3.452252] systemd[1]: Starting Journal Service...
[    3.455361] systemd[1]: Mounted Huge Pages File System.
[    3.457340] systemd[1]: Mounted Debug File System.
[    3.459449] systemd[1]: Mounted POSIX Message Queue File System.
[    3.461659] systemd[1]: Started Create list of required static device nodes for the current kernel.
[    3.465019] systemd[1]: systemd-modules-load.service: Main process exited, code=killed, status=9/KILL
[    3.467118] systemd[1]: Failed to start Load Kernel Modules.
[    3.470441] systemd[1]: systemd-modules-load.service: Unit entered failed state.
[    3.471627] systemd[1]: systemd-modules-load.service: Failed with result 'signal'.
[    3.472872] systemd[1]: Started Set console keymap.
[    3.475407] systemd[1]: Started Uncomplicated firewall.
[    3.493371] systemd[1]: Started Journal Service.
[    3.711682] EXT4-fs (dm-0): re-mounted. Opts: errors=remount-ro
[    3.730734] systemd-journald[840]: Received request to flush runtime journal from PID 1
[    3.861172] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
[    3.866265] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0xb100, revision 0
[    4.089369] ppdev: user-space parallel port driver
[    4.100086] EXT4-fs (sda2): mounting ext2 file system using the ext4 subsystem
[    4.102523] random: nonblocking pool is initialized
[    4.108431] EXT4-fs (sda2): mounted filesystem without journal. Opts: (null)
[    4.137010] Adding 1048572k swap on /dev/mapper/VVICT14--vg-swap_1.  Priority:-1 extents:1 across:1048572k FS
[    4.329046] audit: type=1400 audit(1472042950.332:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/sbin/dhclient" pid=1921 comm="apparmor_parser"
[    4.329058] audit: type=1400 audit(1472042950.332:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=1921 comm="apparmor_parser"
[    4.329063] audit: type=1400 audit(1472042950.332:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=1921 comm="apparmor_parser"
[    4.329066] audit: type=1400 audit(1472042950.332:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/connman/scripts/dhclient-script" pid=1921 comm="apparmor_parser"
[    4.329579] audit: type=1400 audit(1472042950.332:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/mysqld" pid=1922 comm="apparmor_parser"
[    4.329931] audit: type=1400 audit(1472042950.332:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/tcpdump" pid=1924 comm="apparmor_parser"
[    4.372724] cgroup: new mount options do not match the existing superblock, will be ignored

@crawfxrd
Copy link
Contributor

What are the outputs of dkms status and uname -r?

@Codyksp
Copy link
Author

Codyksp commented Aug 24, 2016

root@VVICT14:~# dkms status
dattobd, 0.9.8, 4.4.0-34-generic, x86_64: installed
root@VVICT14:~# uname -r
4.4.0-34-generic

@nixomose
Copy link
Contributor

If you get the problem in init of the module, it's a kernel mismatch like tom said.

On August 24, 2016 8:55:57 AM EDT, Codyksp notifications@github.com wrote:

[    2.951542] systemd[1]: Set hostname to <VVICT14>.
[    3.240227] systemd[1]: Configuration file
/lib/systemd/system/urbackupclientbackend.service is marked executable.
Please remove executable permission bits. Proceeding anyway.
[    3.276576] systemd[1]: Created slice System Slice.
[    3.280883] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[    3.284477] systemd[1]: Reached target Encrypted Volumes.
[    3.287126] systemd[1]: Listening on /dev/initctl Compatibility
Named Pipe.
[    3.289624] systemd[1]: Reached target Remote File Systems (Pre).
[    3.292091] systemd[1]: Listening on Device-mapper event daemon
FIFOs.
[    3.294409] systemd[1]: Reached target Remote File Systems.
[    3.296551] systemd[1]: Listening on udev Kernel Socket.
[    3.298530] systemd[1]: Listening on fsck to fsckd communication
Socket.
[    3.300655] systemd[1]: Listening on Journal Socket.
[    3.314464] systemd[1]: Starting Create list of required static
device nodes for the current kernel...
[    3.322501] systemd[1]: Starting Load Kernel Modules...
[    3.327360] systemd[1]: Starting Set console keymap...
[    3.331602] dattobd: module verification failed: signature and/or
required key missing - tainting kernel
[    3.332221] systemd[1]: Mounting Debug File System...
[    3.337202] systemd[1]: Created slice User and Session Slice.
[    3.339944] systemd[1]: Reached target Slices.
[    3.342475] systemd[1]: Listening on LVM2 metadata daemon socket.
[    3.345957] systemd[1]: Starting Monitoring of LVM2 mirrors,
snapshots etc. using dmeventd or progress polling...
[    3.350013] systemd[1]: Listening on LVM2 poll daemon socket.
[    3.352413] systemd[1]: Listening on udev Control Socket.
[    3.355397] systemd[1]: Mounting Huge Pages File System...
[    3.357724] systemd[1]: Listening on Journal Audit Socket.
[    3.360492] systemd[1]: Starting Uncomplicated firewall...
[    3.363382] systemd[1]: Mounting POSIX Message Queue File System...
[    3.365721] systemd[1]: Reached target User and Group Name Lookups.
[    3.368054] systemd[1]: Started Forward Password Requests to Wall
Directory Watch.
[    3.370445] systemd[1]: Listening on Syslog Socket.
[    3.372868] systemd[1]: Set up automount Arbitrary Executable File
Formats File System Automount Point.
[    3.373558] BUG: unable to handle kernel paging request at
ffff880000800000
[    3.373567] IP: [<ffffffffc00fc11d>] agent_init+0x11d/0x1000
[dattobd]
[    3.373569] PGD 4200067 PUD 4201067 PMD 4204067 PTE 0
[    3.373570] Oops: 0000 [#1] SMP
[    3.373595] Modules linked in: dattobd(OE+) autofs4 dm_mirror
dm_region_hash dm_log hid_generic usbhid hid psmouse ttm drm_kms_helper
syscopyarea sysfillrect sysimgblt fb_sys_fops drm ahci libahci
pata_acpi floppy
[    3.373600] CPU: 1 PID: 818 Comm: systemd-modules Tainted: G        
 OE   4.4.0-34-generic #53-Ubuntu
[    3.373600] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS 0.0.0 02/06/2015
[    3.373609] task: ffff8800348a2580 ti: ffff880079828000 task.ti:
ffff880079828000
[    3.373612] RIP: 0010:[<ffffffffc00fc11d>]  [<ffffffffc00fc11d>]
agent_init+0x11d/0x1000 [dattobd]
[    3.373615] RSP: 0018:ffff88007982bc80  EFLAGS: 00010286
[    3.373615] RAX: ffff8800007ffad8 RBX: 0000000000000000 RCX:
0000000000000000
[    3.373616] RDX: 0000000000000000 RSI: ffff880034bf1a90 RDI:
ffffffff81ec4c00
[    3.373616] RBP: ffff88007982bc88 R08: 000000000001a080 R09:
ffffffff813f4a1b
[    3.373617] R10: ffffea0000d12000 R11: 0000000000000000 R12:
ffff880034854440
[    3.373617] R13: 0000000000000000 R14: ffffffffc00fc000 R15:
ffff880034ac73c0
[    3.373618] FS:  00007f3e4430f740(0000) GS:ffff88007e080000(0000)
knlGS:0000000000000000
[    3.373619] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[    3.373620] CR2: ffff880000800000 CR3: 0000000034ca2000 CR4:
00000000000006e0
[    3.373623] Stack:
[    3.373624]  ffffffff81e11080 ffff88007982bd08 ffffffff81002123
ffffea0000d34440
[    3.373626]  ffff88007982bce0 0000000000000286 0000000000000001
0000000000000014
[    3.373627]  ffffffff811eb843 0000000000000001 ffffffffc0165300
0000000000000018
[    3.373630] Call Trace:
[    3.373666]  [<ffffffff81002123>] do_one_initcall+0xb3/0x200
[    3.373676]  [<ffffffff811eb843>] ?
kmem_cache_alloc_trace+0x183/0x1f0
[    3.373686]  [<ffffffff8118c763>] do_init_module+0x5f/0x1cf
[    3.373692]  [<ffffffff8110a1c7>] load_module+0x1667/0x1c00
[    3.373693]  [<ffffffff81106770>] ? __symbol_put+0x60/0x60
[    3.373702]  [<ffffffff81213180>] ? kernel_read+0x50/0x80
[    3.373704]  [<ffffffff8110a9a4>] SYSC_finit_module+0xb4/0xe0
[    3.373705]  [<ffffffff8110a9ee>] SyS_finit_module+0xe/0x10
[    3.373717]  [<ffffffff8182def2>]
entry_SYSCALL_64_fastpath+0x16/0x71
[    3.373729] Code: c6 48 c7 c7 a8 3d 16 c0 e8 b8 01 09 c1 e9 b7 00 00
00 31 c0 80 3d b3 91 06 00 00 0f 84 af 00 00 00 48 b8 00 00 00 00 00 88
ff ff <48> 81 b8 28 05 00 00 00 08 23 81 75 0d 48 81 b8 30 05 00 00 d0
[    3.373731] RIP  [<ffffffffc00fc11d>] agent_init+0x11d/0x1000
[dattobd]
[    3.373731]  RSP <ffff88007982bc80>
[    3.373732] CR2: ffff880000800000
[    3.373757] ---[ end trace c78a060e8cff2c7e ]---
[    3.449597] systemd[1]: Listening on Journal Socket (/dev/log).
[    3.452252] systemd[1]: Starting Journal Service...
[    3.455361] systemd[1]: Mounted Huge Pages File System.
[    3.457340] systemd[1]: Mounted Debug File System.
[    3.459449] systemd[1]: Mounted POSIX Message Queue File System.
[    3.461659] systemd[1]: Started Create list of required static
device nodes for the current kernel.
[    3.465019] systemd[1]: systemd-modules-load.service: Main process
exited, code=killed, status=9/KILL
[    3.467118] systemd[1]: Failed to start Load Kernel Modules.
[    3.470441] systemd[1]: systemd-modules-load.service: Unit entered
failed state.
[    3.471627] systemd[1]: systemd-modules-load.service: Failed with
result 'signal'.
[    3.472872] systemd[1]: Started Set console keymap.
[    3.475407] systemd[1]: Started Uncomplicated firewall.
[    3.493371] systemd[1]: Started Journal Service.
[    3.711682] EXT4-fs (dm-0): re-mounted. Opts: errors=remount-ro
[    3.730734] systemd-journald[840]: Received request to flush runtime
journal from PID 1
[    3.861172] shpchp: Standard Hot Plug PCI Controller Driver version:
0.4
[    3.866265] piix4_smbus 0000:00:01.3: SMBus Host Controller at
0xb100, revision 0
[    4.089369] ppdev: user-space parallel port driver
[    4.100086] EXT4-fs (sda2): mounting ext2 file system using the ext4
subsystem
[    4.102523] random: nonblocking pool is initialized
[    4.108431] EXT4-fs (sda2): mounted filesystem without journal.
Opts: (null)
[    4.137010] Adding 1048572k swap on /dev/mapper/VVICT14--vg-swap_1. 
Priority:-1 extents:1 across:1048572k FS
[    4.329046] audit: type=1400 audit(1472042950.332:2):
apparmor="STATUS" operation="profile_load" profile="unconfined"
name="/sbin/dhclient" pid=1921 comm="apparmor_parser"
[    4.329058] audit: type=1400 audit(1472042950.332:3):
apparmor="STATUS" operation="profile_load" profile="unconfined"
name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=1921
comm="apparmor_parser"
[    4.329063] audit: type=1400 audit(1472042950.332:4):
apparmor="STATUS" operation="profile_load" profile="unconfined"
name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=1921
comm="apparmor_parser"
[    4.329066] audit: type=1400 audit(1472042950.332:5):
apparmor="STATUS" operation="profile_load" profile="unconfined"
name="/usr/lib/connman/scripts/dhclient-script" pid=1921
comm="apparmor_parser"
[    4.329579] audit: type=1400 audit(1472042950.332:6):
apparmor="STATUS" operation="profile_load" profile="unconfined"
name="/usr/sbin/mysqld" pid=1922 comm="apparmor_parser"
[    4.329931] audit: type=1400 audit(1472042950.332:7):
apparmor="STATUS" operation="profile_load" profile="unconfined"
name="/usr/sbin/tcpdump" pid=1924 comm="apparmor_parser"
[    4.372724] cgroup: new mount options do not match the existing
superblock, will be ignored

You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
#47 (comment)

@nixomose
Copy link
Contributor

Look in /lib/modules for weak-modules

On August 24, 2016 10:03:54 AM EDT, Codyksp notifications@github.com wrote:

root@VVICT14:~# dkms status
dattobd, 0.9.8, 4.4.0-34-generic, x86_64: installed
root@VVICT14:~# uname -r
4.4.0-34-generic

You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
#47 (comment)

@Codyksp
Copy link
Author

Codyksp commented Aug 25, 2016

The modules folder contains 4.4.0-31-generic and 4.4.0-34-generic. I can't find anything called weak-modules anywhere on the server.

@crawfxrd
Copy link
Contributor

A modprobe dattobd still fails with the rebuilt module? What do you get if you run modinfo -F vermagic /path/to/dattobd.ko?

@Codyksp
Copy link
Author

Codyksp commented Aug 25, 2016

root@VVICT14:~# locate dattobd.ko
/lib/modules/4.4.0-34-generic/updates/dkms/dattobd.ko
/var/lib/dkms/dattobd/0.9.8/4.4.0-34-generic/x86_64/module/dattobd.ko
root@VVICT14:~# modinfo -F vermagic /lib/modules/4.4.0-34-generic/updates/dkms/dattobd.ko
4.4.0-34-generic SMP mod_unload modversions
root@VVICT14:~# modinfo -F vermagic /var/lib/dkms/dattobd/0.9.8/4.4.0-34-generic/x86_64/module/dattobd.ko
4.4.0-34-generic SMP mod_unload modversions

@crawfxrd
Copy link
Contributor

Do you have any kind of antivirus running on that server?

@Codyksp
Copy link
Author

Codyksp commented Aug 31, 2016

None that I am aware of, no.

@crawfxrd
Copy link
Contributor

Reproduced on Fedora 23.

[root@fedora-23-srv-std ~]# dmesg
[  181.344056] dattobd: module verification failed: signature and/or required key missing - tainting kernel
[  182.207265] BUG: unable to handle kernel paging request at ffff8800dee36000
[  182.207363] IP: [<ffffffffc032611d>] agent_init+0x11d/0x1000 [dattobd]
[  182.207414] PGD 29077067 PUD 11fffd067 PMD 11fffc067 PTE 0
[  182.209254] Oops: 0000 [#1] SMP
[  182.209780] Modules linked in: dattobd(OE+) vfat fat intel_powerclamp crct10dif_pclmul xfs crc32_pclmul libcrc32c crc32c_intel ghash_clmulni_intel snd_intel8x0 snd_ac97_codec ac97_bus snd_pcm intel_rapl_perf snd_timer joydev snd ppdev i2c_piix4 parport_pc soundcore video parport acpi_cpufreq tpm_tis tpm nfsd auth_rpcgss nfs_acl lockd grace sunrpc e1000 fjes serio_raw
[  182.213101] CPU: 1 PID: 26449 Comm: modprobe Tainted: G           OE   4.7.3-100.fc23.x86_64 #1
[  182.213730] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS VirtualBox 12/01/2006
[  182.214354] task: ffff880002adbd00 ti: ffff8800c79b0000 task.ti: ffff8800c79b0000
[  182.214905] RIP: 0010:[<ffffffffc032611d>]  [<ffffffffc032611d>] agent_init+0x11d/0x1000 [dattobd]
[  182.215457] RSP: 0018:ffff8800c79b3c70  EFLAGS: 00010286
[  182.215998] RAX: ffff8800dee35ad8 RBX: 0000000000000000 RCX: 0000000000000000
[  182.216608] RDX: ffffffffa8c47460 RSI: ffffffffa8ccc330 RDI: ffffffffa8ccc300
[  182.217165] RBP: ffff8800c79b3c78 R08: ffffffffa8c47460 R09: ffffffffa83d972c
[  182.217722] R10: ffffea00031e8200 R11: 0000000000000000 R12: 0000000000000001
[  182.218281] R13: ffffffffc0326000 R14: ffffffffc0323390 R15: 0000000000000001
[  182.218843] FS:  00007f63ebef5700(0000) GS:ffff88011fd00000(0000) knlGS:0000000000000000
[  182.219397] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  182.219941] CR2: ffff8800dee36000 CR3: 000000000206b000 CR4: 00000000000406e0
[  182.220493] Stack:
[  182.221072]  0000000000000000 ffff8800c79b3cf8 ffffffffa8002190 ffff8800c79b3ca0
[  182.221643]  ffffffffa87e01a8 00000000024000c0 00000000024000c0 ffffffffa81b1785
[  182.222221]  ffff8800c79b3cf8 ffffffffa821ce8f ffffffffa821e26b ffffffffa81b1785
[  182.222803] Call Trace:
[  182.223383]  [<ffffffffa8002190>] do_one_initcall+0x50/0x180
[  182.223965]  [<ffffffffa87e01a8>] ? preempt_schedule_common+0x18/0x30
[  182.224547]  [<ffffffffa81b1785>] ? do_init_module+0x27/0x1d7
[  182.225126]  [<ffffffffa821ce8f>] ? kmem_cache_alloc_trace+0x10f/0x1f0
[  182.225705]  [<ffffffffa821e26b>] ? kfree+0x15b/0x170
[  182.226280]  [<ffffffffa81b1785>] ? do_init_module+0x27/0x1d7
[  182.226847]  [<ffffffffa81b17bd>] do_init_module+0x5f/0x1d7
[  182.227393]  [<ffffffffa8129a46>] load_module+0x20a6/0x2720
[  182.227922]  [<ffffffffa8126810>] ? __symbol_put+0x60/0x60
[  182.228434]  [<ffffffffa8244023>] ? vfs_read+0x123/0x140
[  182.228948]  [<ffffffffa812a336>] SYSC_finit_module+0xe6/0x120
[  182.229456]  [<ffffffffa812a38e>] SyS_finit_module+0xe/0x10
[  182.229960]  [<ffffffffa87e42b2>] entry_SYSCALL_64_fastpath+0x1a/0xa4
[  182.230459] Code: c6 48 c7 c7 70 1d 32 c0 e8 1b b3 e8 e7 e9 b7 00 00 00 31 c0 80 3d f3 d1 ff ff 00 0f 84 af 00 00 00 48 b8 00 00 00 00 00 88 ff ff <48> 81 b8 28 05 00 00 30 7d 26 81 75 0d 48 81 b8 30 05 00 00 80 
[  182.233303] RIP  [<ffffffffc032611d>] agent_init+0x11d/0x1000 [dattobd]
[  182.233847]  RSP <ffff8800c79b3c70>
[  182.234485] CR2: ffff8800dee36000
[  182.235021] ---[ end trace 1efdf11b4d32b1d7 ]---
[root@fedora-23-srv-std ~]# lsmod | grep dattobd
dattobd                45056  1
[root@fedora-23-srv-std ~]# uname -r
4.7.3-100.fc23.x86_64
[root@fedora-23-srv-std ~]# dkms status
dattobd, 0.9.9, 4.7.3-100.fc23.x86_64, x86_64: installed
[root@fedora-23-srv-std ~]# modinfo /var/lib/dkms/dattobd/0.9.9/4.7.3-100.fc23.x86_64/x86_64/module/dattobd.ko 
filename:       /var/lib/dkms/dattobd/0.9.9/4.7.3-100.fc23.x86_64/x86_64/module/dattobd.ko
version:        0.9.8
description:    Kernel module for supporting block device snapshots and incremental backups.
author:         Tom Caputi
license:        GPL
srcversion:     8454306388C4D2DC79B5249
depends:        
vermagic:       4.7.3-100.fc23.x86_64 SMP mod_unload 
parm:           MAY_HOOK_SYSCALLS:if true, allows the kernel module to find and alter the system call table to allow tracing to work across remounts (bool)
parm:           COW_MAX_MEMORY_DEFAULT:default maximum cache size (in bytes) (ulong)
parm:           COW_FALLOCATE_PERCENTAGE_DEFAULT:default space allocated to the cow file (as integer percentage) (uint)
parm:           MAX_SNAP_DEVICES:maximum number of tracers available (uint)

@crawfxrd
Copy link
Contributor

I only see it on Fedora 23 and Fedora 24, which are now running the 4.7.3 kernel. Unable to reproduce anywhere else (including Arch running 4.7.3).

@nixomose
Copy link
Contributor

I have an idea what's going on, still flushing out details. Tom will work it out in seconds, I expect.

On September 15, 2016 4:06:50 PM EDT, Tim Crawford notifications@github.com wrote:

I only see it on Fedora 23 and Fedora 24, which are now running the
4.7.3 kernel. Unable to reproduce anywhere else (including Arch running
4.7.3).

You are receiving this because you commented.
Reply to this email directly or view it on GitHub:
#47 (comment)

@crawfxrd
Copy link
Contributor

@Codyksp can you try with the latest commit?

@Codyksp
Copy link
Author

Codyksp commented Sep 17, 2016

Same results as before, as far as I can see. UrBackup doesn't receive a file list and dattobd shows the same errors. I completely uninstalled both UrBackup Client and dattobd before installing them again. I actually had some trouble removing dattobd aswell, it was giving me errors about dkms and hanging.

root@VVICT14:~# dmesg | grep datto
[    3.684246] dattobd: module verification failed: signature and/or required key missing - tainting kernel
[    3.723620] IP: [<ffffffffc016211d>] agent_init+0x11d/0x1000 [dattobd]
[    3.726655] Modules linked in: dattobd(OE+) autofs4 dm_mirror dm_region_hash dm_log hid_generic usbhid hid ttm drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm psmouse ahci libahci pata_acpi floppy
[    3.726663] RIP: 0010:[<ffffffffc016211d>]  [<ffffffffc016211d>] agent_init+0x11d/0x1000 [dattobd]
[    3.726782] RIP  [<ffffffffc016211d>] agent_init+0x11d/0x1000 [dattobd]
[    2.974383] systemd[1]: Set hostname to <VVICT14>.
[    3.536094] systemd[1]: Configuration file /lib/systemd/system/urbackupclientbackend.service is marked executable. Please remove executable permission bits. Proceeding anyway.
[    3.592974] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[    3.595336] systemd[1]: Listening on LVM2 metadata daemon socket.
[    3.597331] systemd[1]: Listening on Journal Audit Socket.
[    3.599462] systemd[1]: Reached target Remote File Systems (Pre).
[    3.601481] systemd[1]: Reached target Remote File Systems.
[    3.603785] systemd[1]: Listening on Device-mapper event daemon FIFOs.
[    3.605884] systemd[1]: Listening on Syslog Socket.
[    3.607899] systemd[1]: Listening on Journal Socket (/dev/log).
[    3.609711] systemd[1]: Listening on LVM2 poll daemon socket.
[    3.611591] systemd[1]: Reached target User and Group Name Lookups.
[    3.613389] systemd[1]: Reached target Encrypted Volumes.
[    3.615272] systemd[1]: Listening on fsck to fsckd communication Socket.
[    3.617082] systemd[1]: Listening on Journal Socket.
[    3.619021] systemd[1]: Created slice User and Session Slice.
[    3.620823] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point.
[    3.624157] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
[    3.626195] systemd[1]: Listening on udev Kernel Socket.
[    3.628348] systemd[1]: Created slice System Slice.
[    3.645678] systemd[1]: Starting Monitoring of LVM2 mirrors, snapshots etc. using dmeventd or progress polling...
[    3.649733] systemd[1]: Mounting Debug File System...
[    3.656343] systemd[1]: Starting Load Kernel Modules...
[    3.659188] systemd[1]: Mounting Huge Pages File System...
[    3.662006] systemd[1]: Starting Uncomplicated firewall...
[    3.665004] systemd[1]: Mounting POSIX Message Queue File System...
[    3.667909] systemd[1]: Starting Journal Service...
[    3.670252] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[    3.672923] systemd[1]: Starting Set console keymap...
[    3.675806] systemd[1]: Starting Create list of required static device nodes for the current kernel...
[    3.679118] systemd[1]: Reached target Slices.
[    3.681382] systemd[1]: Listening on udev Control Socket.
[    3.684246] dattobd: module verification failed: signature and/or required key missing - tainting kernel
[    3.684750] systemd[1]: Mounted Huge Pages File System.
[    3.689209] systemd[1]: Mounted Debug File System.
[    3.691520] systemd[1]: Mounted POSIX Message Queue File System.
[    3.695296] systemd[1]: Started Uncomplicated firewall.
[    3.697918] systemd[1]: Started Create list of required static device nodes for the current kernel.
[    3.719579] systemd[1]: Started Journal Service.
[    3.722534] BUG: unable to handle kernel paging request at ffff880000800000
[    3.723620] IP: [<ffffffffc016211d>] agent_init+0x11d/0x1000 [dattobd]
[    3.724659] PGD 4200067 PUD 4201067 PMD 4204067 PTE 0
[    3.725653] Oops: 0000 [#1] SMP
[    3.726655] Modules linked in: dattobd(OE+) autofs4 dm_mirror dm_region_hash dm_log hid_generic usbhid hid ttm drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm psmouse ahci libahci pata_acpi floppy
[    3.726659] CPU: 0 PID: 314 Comm: systemd-modules Tainted: G           OE   4.4.0-36-generic #55-Ubuntu
[    3.726660] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 0.0.0 02/06/2015
[    3.726661] task: ffff880034835780 ti: ffff88007c200000 task.ti: ffff88007c200000
[    3.726663] RIP: 0010:[<ffffffffc016211d>]  [<ffffffffc016211d>] agent_init+0x11d/0x1000 [dattobd]
[    3.726664] RSP: 0018:ffff88007c203c80  EFLAGS: 00010286
[    3.726665] RAX: ffff8800007ffad8 RBX: 0000000000000000 RCX: 0000000000000000
[    3.726666] RDX: 0000000000000000 RSI: ffff880076321290 RDI: ffffffff81ec4c00
[    3.726666] RBP: ffff88007c203c88 R08: 000000000001a080 R09: ffffffff813f4c1b
[    3.726667] R10: ffffea0000d59800 R11: 0000000000000000 R12: ffff88007cc2a6a0
[    3.726669] R13: 0000000000000000 R14: ffffffffc0162000 R15: ffff88000014b780
[    3.726670] FS:  00007f81eaa06740(0000) GS:ffff88007e000000(0000) knlGS:0000000000000000
[    3.726670] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[    3.726671] CR2: ffff880000800000 CR3: 000000007633a000 CR4: 00000000000006f0
[    3.726674] Stack:
[    3.726675]  ffffffff81e11080 ffff88007c203d08 ffffffff81002123 000000009800b0e7
[    3.726676]  ffff880035752e80 ffff880035752e80 ffffffff811cf671 ffffffffc015f300
[    3.726677]  ffffffff811eb823 ffff88007c203cf0 ffffffff811ec61a 0000000000000018
[    3.726677] Call Trace:
[    3.726684]  [<ffffffff81002123>] do_one_initcall+0xb3/0x200
[    3.726694]  [<ffffffff811cf671>] ? __vunmap+0x91/0xe0
[    3.726700]  [<ffffffff811eb823>] ? kmem_cache_alloc_trace+0x183/0x1f0
[    3.726702]  [<ffffffff811ec61a>] ? kfree+0x13a/0x150
[    3.726709]  [<ffffffff8118c7a3>] do_init_module+0x5f/0x1cf
[    3.726734]  [<ffffffff8110a1f7>] load_module+0x1667/0x1c00
[    3.726735]  [<ffffffff811067a0>] ? __symbol_put+0x60/0x60
[    3.726742]  [<ffffffff81213160>] ? kernel_read+0x50/0x80
[    3.726757]  [<ffffffff8110a9d4>] SYSC_finit_module+0xb4/0xe0
[    3.726759]  [<ffffffff8110aa1e>] SyS_finit_module+0xe/0x10
[    3.726769]  [<ffffffff8182dfb2>] entry_SYSCALL_64_fastpath+0x16/0x71
[    3.726780] Code: c6 48 c7 c7 a8 dd 15 c0 e8 f8 a1 02 c1 e9 b7 00 00 00 31 c0 80 3d b3 d1 ff ff 00 0f 84 af 00 00 00 48 b8 00 00 00 00 00 88 ff ff <48> 81 b8 28 05 00 00 b0 07 23 81 75 0d 48 81 b8 30 05 00 00 a0
[    3.726782] RIP  [<ffffffffc016211d>] agent_init+0x11d/0x1000 [dattobd]
[    3.726783]  RSP <ffff88007c203c80>
[    3.726783] CR2: ffff880000800000
[    3.726785] ---[ end trace 64484b0bf1b17c9e ]---
[    4.071034] EXT4-fs (dm-0): re-mounted. Opts: errors=remount-ro
[    4.084776] systemd-journald[323]: Received request to flush runtime journal from PID 1
[    4.165243] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0xb100, revision 0
[    4.210961] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
[    4.252484] ppdev: user-space parallel port driver
[    4.336641] Adding 1048572k swap on /dev/mapper/VVICT14--vg-swap_1.  Priority:-1 extents:1 across:1048572k FS
[    4.463575] EXT4-fs (sda2): mounting ext2 file system using the ext4 subsystem
[    4.473095] EXT4-fs (sda2): mounted filesystem without journal. Opts: (null)
[    4.591686] random: nonblocking pool is initialized
[    4.897875] audit: type=1400 audit(1474134662.092:2): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/tcpdump" pid=645 comm="apparmor_parser"
[    4.900177] audit: type=1400 audit(1474134662.092:3): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/sbin/mysqld" pid=643 comm="apparmor_parser"
[    4.902925] audit: type=1400 audit(1474134662.096:4): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/sbin/dhclient" pid=642 comm="apparmor_parser"
[    4.902931] audit: type=1400 audit(1474134662.096:5): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=642 comm="apparmor_parser"
[    4.902935] audit: type=1400 audit(1474134662.096:6): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=642 comm="apparmor_parser"
[    4.902939] audit: type=1400 audit(1474134662.096:7): apparmor="STATUS" operation="profile_load" profile="unconfined" name="/usr/lib/connman/scripts/dhclient-script" pid=642 comm="apparmor_parser"
[    4.972078] cgroup: new mount options do not match the existing superblock, will be ignored

@tcaputi
Copy link

tcaputi commented Sep 17, 2016

Hmmmm. I'm sorry for the trouble you've been having and I'm sorry we can't seem to reproduce the issue on our end. A couple of last things that could help us debug the issue if you can spare the time and are ok with allowing us to crash the machine one more time:

  1. Recompile the module with debug enabled by changing the following line in src/Makefile:
EXTRA_CFLAGS := -g

to this:

EXTRA_CFLAGS := -g -DDATTO_DEBUG

and then running make again. This will just activate the debug messages that are already in the code.

  1. Try inserting the module with insmod src/dattobd.ko.

  2. When it crashes again copy the output of dmesg and paste it here (there should be a few messages in there now that start with 'datto: '

  3. In the stack trace portion of the output, note the line listed for the RIP. In the stack trace you provided above that line is:

[    3.726663] RIP: 0010:[<ffffffffc016211d>]  [<ffffffffc016211d>] agent_init+0x11d/0x1000 [dattobd]

This line will probably be slightly different when you run it this time.

  1. The agent_init+0x11d in that indicates the instruction where the module crashed. In order to turn that into a line number for us to debug, run gdb src/dattobd.ko. You may have to install gdb first if you haven't already (available with apt-get install gdb). This will bring up the gdb prompt. From there run the following command (but replace the aforementioned agent_init+0x11d with the new value.
list *(agent_init+0x11d)

That will output the 5 lines of code around the line that caused the crash along with the line number itself. Paste that output here and then you can quit out of gdb just by entering quit.

@Codyksp
Copy link
Author

Codyksp commented Oct 4, 2016

Hello Tom,

Thank you for the extra support, however we are currently moving to a different backup/restore solution for our linux servers as we also some running on Arch Linux which don't properly support dattobd (or UrBackup for that matter).

I'm sorry that I can't try your last solution to troubleshoot this further but we have spent too much time on this and have found a solution that meets our needs for now.

@Codyksp Codyksp closed this as completed Oct 4, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants