cow file not left in clean state

crawfxrd commented 8 years ago

Seen on Fedora 24, Fedora 25. On reboot, dattobd fails to reload the incremental state for the root volume when remounted as R/W. Other volumes work as expected.

Reload script that gets run:

#!/bin/sh

echo "Reloading incremental - 2 ..." > /dev/kmsg
/usr/bin/dbdctl reload-incremental /dev/disk/by-uuid/92963e08-947c-450c-852c-655ecfc4aaf8 /.datto1 2

dmesg:

Nov 23 10:49:29 segv-fed-24 kernel: EXT4-fs (sda3): mounted filesystem with ordered data mode. Opts: (null)
Nov 23 10:49:30 segv-fed-24 unknown: datto looking for datto_reload
Nov 23 10:49:30 segv-fed-24 unknown: datto found /sbin/datto_reload
Nov 23 10:49:30 segv-fed-24 unknown: Reloading incremental - 0 ...
Nov 23 10:49:30 segv-fed-24 unknown: Reloading incremental - 1 ...
Nov 23 10:49:30 segv-fed-24 unknown: Reloading incremental - 2 ...
Nov 23 10:49:31 segv-fed-24 kernel: EXT4-fs (sda3): mounted filesystem with ordered data mode. Opts: (null)
Nov 23 10:49:31 segv-fed-24 kernel: random: crng init done
Nov 23 10:49:36 segv-fed-24 systemd-journald[171]: Received SIGTERM from PID 1 (systemd).
Nov 23 10:49:36 segv-fed-24 kernel: systemd: 16 output lines suppressed due to ratelimiting
Nov 23 10:49:36 segv-fed-24 kernel: SELinux: 32768 avtab hash slots, 106590 rules.
Nov 23 10:49:36 segv-fed-24 kernel: SELinux: 32768 avtab hash slots, 106590 rules.
Nov 23 10:49:36 segv-fed-24 kernel: SELinux:  8 users, 14 roles, 5044 types, 305 bools, 1 sens, 1024 cats
Nov 23 10:49:36 segv-fed-24 kernel: SELinux:  94 classes, 106590 rules
Nov 23 10:49:36 segv-fed-24 kernel: SELinux:  Permission validate_trans in class security not defined in policy.
Nov 23 10:49:36 segv-fed-24 kernel: SELinux:  Permission module_load in class system not defined in policy.
Nov 23 10:49:36 segv-fed-24 kernel: SELinux: the above unknown classes and permissions will be allowed
Nov 23 10:49:36 segv-fed-24 kernel: SELinux:  Completing initialization.
Nov 23 10:49:36 segv-fed-24 kernel: SELinux:  Setting up existing superblocks.
Nov 23 10:49:36 segv-fed-24 systemd[1]: Successfully loaded SELinux policy in 157.580ms.
Nov 23 10:49:36 segv-fed-24 systemd[1]: Relabelled /dev and /run in 12.764ms.
Nov 23 10:49:36 segv-fed-24 kernel: audit_printk_skb: 108 callbacks suppressed
Nov 23 10:49:36 segv-fed-24 kernel: audit: type=1130 audit(1479916173.738:47): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system
Nov 23 10:49:36 segv-fed-24 kernel: audit: type=1131 audit(1479916173.738:48): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system
Nov 23 10:49:36 segv-fed-24 kernel: audit: type=1130 audit(1479916173.738:49): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system
Nov 23 10:49:36 segv-fed-24 kernel: audit: type=1131 audit(1479916173.738:50): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system
Nov 23 10:49:36 segv-fed-24 kernel: audit: type=1130 audit(1479916173.738:51): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system
Nov 23 10:49:36 segv-fed-24 kernel: audit: type=1131 audit(1479916173.741:52): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system
Nov 23 10:49:36 segv-fed-24 kernel: audit: type=1130 audit(1479916174.128:53): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system
Nov 23 10:49:36 segv-fed-24 kernel: audit: type=1305 audit(1479916174.205:54): audit_enabled=1 old=1 auid=4294967295 ses=4294967295 subj=syste
Nov 23 10:49:36 segv-fed-24 kernel: audit: type=1130 audit(1479916174.237:55): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system
Nov 23 10:49:36 segv-fed-24 kernel: EXT4-fs (sda3): re-mounted. Opts: (null)
Nov 23 10:49:36 segv-fed-24 kernel: datto: cow file not left in clean state: 0: -22
Nov 23 10:49:36 segv-fed-24 kernel: datto: error opening cow manager header: -22
Nov 23 10:49:36 segv-fed-24 kernel: datto: error during cow manager initialization: -22
Nov 23 10:49:36 segv-fed-24 kernel: datto: error setting up cow manager: -22
Nov 23 10:49:36 segv-fed-24 kernel: datto: error transitioning incremental to active state: -22

/proc/datto-info:

{
    "version": "0.9.11",
    "devices": [
        {
            "minor": 0,
            "cow_file": "/.datto1",
            "block_device": "/dev/sda1",
            "max_cache": 314572800,
            "fallocate": 20971520,
            "seq_id": 190,
            "uuid": "9cadf9e31dc34d4cbfb6e28f46802206",
            "state": 2
        },
        {
            "minor": 1,
            "cow_file": "/.datto1",
            "block_device": "/dev/sda2",
            "max_cache": 314572800,
            "fallocate": 56623104,
            "seq_id": 190,
            "uuid": "a6d3b766e9f743deb642b73621d8a0e3",
            "state": 2
        },
        {
            "minor": 2,
            "cow_file": "/.datto1",
            "block_device": "/dev/disk/by-uuid/92963e08-947c-450c-852c-655ecfc4aaf8",
            "max_cache": 314572800,
            "error": -22,
            "state": 4
        }
    ]
}

tcaputi commented 8 years ago

The system is probably not completely unmounting the root filesystem before shutting down. This doesn't look to be a driver bug so I'm closing the issue.

crawfxrd commented 6 years ago

dbdctl setup-snapshot /dev/dm-0 /cow 0
dbdctl transition-to-incremental 0
sync
halt

On Fedora 28, the last output printed is:

[1317]: Failed to remount '/' read-only: Device or resource busy
systemd-shutdown[1]: Remounting '/' failed abnormally, child process 1317 aborted or exited non-zero.
[1318]: Failed to remount '/' read-only: Device or resource busy
dracut Warning: Cannot umount /oldroot
Kerenel  not configured for semaphores (System V IPC). Not using udev synchronisation code.
device-mapper: remove ioctl on fedora-root  failed: Device or resource busy
Command failed
Halting.

On Ubuntu 18.04, the last output printed is:

datto: device still mounted after umounting cow file's file-system. entering error state: -5

datto / dattobd

cow file not left in clean state #60