Bug#782793: systemd: ext4 filesystem on lvm on raid causes boot to enter emergency shell

[Rick Thomas]

On Apr 22, 2015, at 8:17 AM, Michael Biebl <biebl at debian.org> wrote:

> Am 22.04.2015 um 12:10 schrieb Rick Thomas:
>> This works.  Interestingly, without the sleep loop the vgchange
>> fails.
>> 
>> Now, you say that a VM with two virtual disks configured as RAID1
>> with a logical volume works fresh out of the box.  This makes me
>> wonder if it’s some kind of a timing problem…  It takes a few seconds
>> for the freshly rebooted system to find the USB-Flash sticks and
>> assemble them.  So  some time-out is triggered in the systemd stuff
>> on my setup, while your setup has no such physical constraints —
>> everything is available immediately.
> 
> So you're running vgchange in a loop, which suggests that the
> lvm2-activation.service and lvm2-activation-early.service unitsas
> shipped by lvm2 are not sufficient. Those are supposed to run vgchange.
> 
> I notice, that the /etc/init.d/lvm2 init script has
> Should-Start: mdadm-raid
> but the systemd unit files have no such ordering.
> 
> I wonder, if that makes a difference.
> 
> Could you copy /lib/systemd/system/lvm2-activation.service to
> /etc/systemd/system and add a line
> After=mdadm-raid.service
> to the [Unit] section.


Odd… That didn’t work.  I was almost sure you had it nailed!  /-:

It’s worth noting that there is no file named “mdadm-raid.service” anywhere that I could find in /etc/systemd/ or /lib/systemd/.
Also, the files /lib/systemd/system/mdadm-waitidle.service  and /lib/systemd/system/mdadm.service are both symlinks to /dev/null.

Does that tell you anything?

Attached is the output of journalctl for that boot…

The potentially interesting parts (with time-stamps as pointers to the context in which they occur in the full journal) are:

rbthomas at cube:~$ egrep -i 'md127|mdadm|lvm|backup|md array|mount' < /tmp/boot-journal.txt 
Apr 22 23:58:02 cube kernel: Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
Apr 22 23:58:02 cube kernel: Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
Apr 22 23:58:02 cube kernel: EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
Apr 22 23:58:02 cube kernel: EXT4-fs (mmcblk0p2): re-mounted. Opts: errors=remount-ro
Apr 22 23:58:02 cube mdadm-raid[185]: Generating udev events for MD arrays...done.
Apr 22 23:58:03 cube lvm[196]: 1 logical volume(s) in volume group "vg" now active
Apr 22 23:58:03 cube lvm[260]: 1 logical volume(s) in volume group "vg" now active
Apr 22 23:58:03 cube kernel: EXT4-fs (mmcblk0p1): mounting ext2 file system using the ext4 subsystem
Apr 22 23:58:03 cube kernel: EXT4-fs (mmcblk0p6): mounted filesystem with ordered data mode. Opts: (null)
Apr 22 23:58:04 cube kernel: EXT4-fs (mmcblk0p1): mounted filesystem without journal. Opts: (null)
Apr 22 23:58:04 cube kernel: EXT4-fs (mmcblk0p7): mounted filesystem with ordered data mode. Opts: (null)
Apr 22 23:58:04 cube kernel: EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
Apr 22 23:58:04 cube lvm[296]: 1 logical volume(s) in volume group "vg" monitored
Apr 22 23:58:05 cube kernel: md/raid:md127: device sdf operational as raid disk 4
Apr 22 23:58:05 cube kernel: md/raid:md127: device sde operational as raid disk 3
Apr 22 23:58:05 cube kernel: md/raid:md127: device sdd operational as raid disk 2
Apr 22 23:58:05 cube kernel: md/raid:md127: device sdc operational as raid disk 1
Apr 22 23:58:05 cube kernel: md/raid:md127: device sdb operational as raid disk 0
Apr 22 23:58:05 cube kernel: md/raid:md127: allocated 0kB
Apr 22 23:58:05 cube kernel: md/raid:md127: raid level 6 active with 5 out of 5 devices, algorithm 2
Apr 22 23:58:05 cube kernel: md127: detected capacity change from 0 to 93731684352
Apr 22 23:58:05 cube kernel:  md127: unknown partition table
Apr 22 23:59:31 cube systemd[1]: Job dev-disk-by\x2dlabel-BACKUP.device/start timed out.
Apr 22 23:59:31 cube systemd[1]: Timed out waiting for device dev-disk-by\x2dlabel-BACKUP.device.
Apr 22 23:59:31 cube systemd[1]: Dependency failed for /backup.
Apr 22 23:59:53 cube lvm[588]: 1 logical volume(s) in volume group "vg1" now active
Apr 22 23:59:54 cube lvm[588]: 1 logical volume(s) in volume group "vg" now active
Apr 22 23:59:54 cube systemd[1]: backup.mount: Directory /backup to mount over is not empty, mounting anyway.
Apr 22 23:59:54 cube kernel: EXT4-fs (dm-1): mounted filesystem with ordered data mode. Opts: (null)
Apr 22 23:59:54 cube lvm[635]: 1 logical volume(s) in volume group "vg1" now active
Apr 22 23:59:54 cube lvm[635]: 1 logical volume(s) in volume group “vg” now active


I don’t see any events having to do with LVM between the point when the md127 raid is assembled by the kernel (not by systemd) and the point when the systemd time-out occurs a minute and a half later.  However, there is an LVM event for vg (the volume group on the eSATA disk) a second or two before the md127 raid stuff…

Hope this helps!

Rick


-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: boot-journal.txt
URL: <http://alioth-lists.debian.net/pipermail/pkg-systemd-maintainers/attachments/20150423/0b9c88e1/attachment-0002.txt>