ordering cycles with lvm2 init script with inappropriate rc2.d links

Indeed your dmesg shows that apparmor loads its profiles before the file system gets mounted r/w. Can you please confirm that

  systemctl show --no-pager -p After apparmor

includes "local-fs.target"? Does

  systemctl list-dependencies local-fs.target

includes "systemd-remount-fs.service"?

If all that is true, can you please boot with "debug" (in the grub "linux" command line), then do

  journalctl -ab > /tmp/debug.txt

and attach /tmp/debug.txt here?

Yes, both of those things are true. I have attached the output of journalctl -ab. This particular startup also triggered the network-manager-related bug that I reported, and I had to manually run the systemd-tmpfiles command you posted over there to actually get the system to finish booting to the point where journalctl would return anything.

Ah, thanks for the journal. That shows that early boot is completely messed up due to dependency cycles. This also affected systemd-tmpfiles-setup.service:

Mar 12 05:56:32 mamarley-laptop systemd[1]: Found ordering cycle on basic.target/start
Mar 12 05:56:32 mamarley-laptop systemd[1]: Found dependency on sysinit.target/start
Mar 12 05:56:32 mamarley-laptop systemd[1]: Found dependency on systemd-tmpfiles-setup.service/start
Mar 12 05:56:32 mamarley-laptop systemd[1]: Found dependency on local-fs.target/start
Mar 12 05:56:32 mamarley-laptop systemd[1]: Found dependency on lvm2.service/start
Mar 12 05:56:32 mamarley-laptop systemd[1]: Found dependency on basic.target/start
Mar 12 05:56:32 mamarley-laptop systemd[1]: Breaking ordering cycle by deleting job systemd-tmpfiles-setup.service/start
Mar 12 05:56:32 mamarley-laptop systemd[1]: Job systemd-tmpfiles-setup.service/start deleted to break ordering cycle starting with basic.target/start

But the shortest one is

Mar 12 05:56:32 mamarley-laptop systemd[1]: Found ordering cycle on basic.target/start
Mar 12 05:56:32 mamarley-laptop systemd[1]: Found dependency on sysinit.target/start
Mar 12 05:56:32 mamarley-laptop systemd[1]: Found dependency on local-fs.target/start
Mar 12 05:56:32 mamarley-laptop systemd[1]: Found dependency on lvm2.service/start
Mar 12 05:56:32 mamarley-laptop systemd[1]: Found dependency on basic.target/start
Mar 12 05:56:32 mamarley-laptop systemd[1]: Breaking ordering cycle by deleting job local-fs.target/start
Mar 12 05:56:32 mamarley-laptop systemd[1]: Job local-fs.target/start deleted to break ordering cycle starting with basic.target/start

Out of that I blame lvm2.service. That's shipped by default, but for some reason on your system it causes trouble. Can you please give me the output of

  systemctl show --no-pager -p Requires,Wants,Before,After lvm2

?

Sure, it says:

Requires=basic.target
Wants=system.slice
Before=multi-user.target shutdown.target graphical.target checkfs.service local-fs.target
After=system.slice basic.target cryptdisks-early.service mdadm-raid.service systemd-udevd.service mountdevsubfs.service systemd-journald.socket multipath-tools-boot.service

I don't use LVM though.

> Requires=basic.target

OK, that's surprising, and the cause for the woes.

Can you please attach your /etc/init.d/lvm2? It might differ from the default and add some more dependencies.

Can you please also give me the output of

  systemctl show lvm2 | grep Path
  cat /run/systemd/generator.late/lvm2.service

Thanks!

OK, here it is:

michael@mamarley-laptop:~$ cat /etc/init.d/lvm2
#!/bin/sh
### BEGIN INIT INFO
# Provides: lvm2 lvm
# Required-Start: mountdevsubfs
# Required-Stop:
# Should-Start: udev mdadm-raid cryptdisks-early multipath-tools-boot
# Should-Stop: umountroot mdadm-raid
# X-Start-Before: checkfs mountall
# X-Stop-After: umountfs
# Default-Start: S
# Default-Stop:
### END INIT INFO

# dummy job, Ubuntu does LVM setup in udev rules, so starting udev is enough
true

michael@mamarley-laptop:~$ systemctl show lvm2 | grep Path
FragmentPath=/run/systemd/generator.late/lvm2.service
SourcePath=/etc/init.d/lvm2

michael@mamarley-laptop:~$ cat /run/systemd/generator.late/lvm2.service
# Automatically generated by systemd-sysv-generator

[Unit]
Documentation=man:systemd-sysv-generator(8)
SourcePath=/etc/init.d/lvm2
Description=(null)
Before=runlevel2.target runlevel3.target runlevel4.target runlevel5.target shutdown.target checkfs.service local-fs.target
After=mountdevsubfs.service udev.service mdadm-raid.service cryptdisks-early.service multipath-tools-boot.service
Conflicts=shutdown.target

[Service]
Type=forking
Restart=no
TimeoutSec=5min
IgnoreSIGPIPE=no
KillMode=process
GuessMainPID=no
RemainAfterExit=yes
ExecStart=/etc/init.d/lvm2 start
ExecStop=/etc/init.d/lvm2 stop

Thanks. The init script works as expected, but the generated .service is missing "DefaultDependencies=no". Unfortunately the sysv generator doesn't have that many debug messages, so if you just run it with logs that won't tell me much yet. I think I'll need to prepare one with extra debugging information, as I don't see this effect on any other box.

If that's possible for you, it would also help immensely if I could ssh to your machine (via ssh port forwarding to a public server, or opening up port 22 on your router, etc.; my key is https://launchpad.net/~pitti/+sshkeys) . That would make it a lot easier to debug that problem; I don't need root privileges, just an unprivileged user account.

Ooh, something just occurred to me! sysv-generator doesn't actually read the information from "Default-Start:", but from the links in /etc/rc*, just like sysvinit would do. What's the output of

  ls -l /etc/rc*/*lvm2*

? There should be one link in /etc/rcS.d, but *none* in /etc/rc2.d or another number. It's likely that for some reason you have a link in rc2.d or so? Any idea how it got there?

Yeah, for some reason my system has them in in *all* the rcX.d directories. rc2-rc5 all have start scripts (S05lvm2) and the others have kill scripts, except for rcS.d, which actually has nothing. I guess I should delete all of them and add one in rcS.d? Should the one in rcS.d be a start or kill script?

Yes, please remove them from rc2.d to rc5.d, but keep the rcS.d link. So now I understand why the boot went completely wrong, I just don't know at all how these symlinks came into rc[2-5].d/ in the first place. For this particular case we can probably just ship a dummy lvm2.service, then we don't need the init.d script at all. But this will affect any rcS.d script with bogus symlinks, not that much that we can do about it I'm afraid.

That seems to make everything work OK on bootup. Thanks!

I have no idea how those symlinks got there. I definitely didn't put them there manually.

Mmmm I'm having a similar issue, but after ls -l /etc/rc*/*lvm2* I have "1rwxrwxrwx 1 root root 14 mar 8 19:43 /etc/rcS.d/S08lvm2-> ../init.d/lvm2".
I am not sure, does that means that I only have the symlink in rcS.d?
Btw I am using Kubuntu vivid.

Manglasape [2015-03-12 23:56 -0000]:
> Mmmm I'm having a similar issue, but after ls -l /etc/rc*/*lvm2* I have "1rwxrwxrwx 1 root root 14 mar 8 19:43 /etc/rcS.d/S08lvm2-> ../init.d/lvm2".
> I am not sure, does that means that I only have the symlink in rcS.d?

Yes, that looks fine then. Which links did you have before? It's
terribly worrying that something creates these invalid links, given
that /etc/init.d/lvm2's Default-Start: is only "S".

No, I only had these link, probably mine is another issue. It may be a disk failure, I'm trying a lot of distros lately.

Hi Martin,

I think I can reproduce the appaprmor failure on every boot:

$ systemctl status apparmor.service -l
● apparmor.service - LSB: AppArmor initialization
   Loaded: loaded (/etc/init.d/apparmor)
   Active: failed (Result: exit-code) since So 2015-03-15 22:42:54 CET; 12h ago
     Docs: man:systemd-sysv-generator(8)
  Process: 543 ExecStart=/etc/init.d/apparmor start (code=exited, status=123)

Mär 15 22:42:54 benediktZ50-70 apparmor[543]: Skipping profile in /etc/apparmor.d/disable: usr.bin.firefox
Mär 15 22:42:54 benediktZ50-70 apparmor[543]: AppArmor parser error for /etc/apparmor.d/usr.sbin.mysqld-akonadi in /etc/apparmor.d/usr.sbin.mysqld-akonadi at line 31: Could not open 'local/usr.sbin.mysqld-akonadi'
Mär 15 22:42:54 benediktZ50-70 apparmor[543]: Skipping profile in /etc/apparmor.d/disable: usr.bin.firefox
Mär 15 22:42:54 benediktZ50-70 apparmor[543]: AppArmor parser error for /etc/apparmor.d/usr.sbin.mysqld-akonadi in /etc/apparmor.d/usr.sbin.mysqld-akonadi at line 31: Could not open 'local/usr.sbin.mysqld-akonadi'
Mär 15 22:42:54 benediktZ50-70 apparmor[543]: Skipping profile in /etc/apparmor.d/disable: usr.sbin.rsyslogd
Mär 15 22:42:54 benediktZ50-70 apparmor[543]: ...fail!
Mär 15 22:42:54 benediktZ50-70 systemd[1]: apparmor.service: control process exited, code=exited status=123
Mär 15 22:42:54 benediktZ50-70 systemd[1]: Failed to start LSB: AppArmor initialization.
Mär 15 22:42:54 benediktZ50-70 systemd[1]: Unit apparmor.service entered failed state.
Mär 15 22:42:54 benediktZ50-70 systemd[1]: apparmor.service failed.

However I have only one symlink in rcS:

ls -l /etc/rc*/*lvm2
lrwxrwxrwx 1 root root 14 Dez 21 01:18 /etc/rcS.d/S08lvm2 -> ../init.d/lvm2

I will now try a debug boot.

System: Kubuntu 15.04

$ systemctl show --no-pager -p After apparmor
After=system.slice systemd-journald.socket local-fs.target

and:

$ systemctl list-dependencies local-fs.target
local-fs.target
● ├─-.mount
● ├─boot-efi.mount
● ├─home.mount
● ├─systemd-fsck-root.service
● └─systemd-remount-fs.service

I think this is another bug that only shows the same symptoms as this bug. Could you please confirm this, before I open a new bug?

I have the same problem with udev, screen-cleanup and udev-finish

 daniel@daniel-vaio:~$ grep Default-Start.*S /etc/rc[0-9].d/S0*
 /etc/rc2.d/S01udev:# Default-Start: S
 /etc/rc2.d/S02screen-cleanup:# Default-Start: S
 /etc/rc2.d/S02udev-finish:# Default-Start: S
 /etc/rc3.d/S01udev:# Default-Start: S
 /etc/rc3.d/S02screen-cleanup:# Default-Start: S
 /etc/rc3.d/S02udev-finish:# Default-Start: S
 /etc/rc4.d/S01udev:# Default-Start: S
 /etc/rc4.d/S02screen-cleanup:# Default-Start: S
 /etc/rc4.d/S02udev-finish:# Default-Start: S
 /etc/rc5.d/S01udev:# Default-Start: S
 /etc/rc5.d/S02screen-cleanup:# Default-Start: S
 /etc/rc5.d/S02udev-finish:# Default-Start: S

My system sometimes boots ok, sometimes pymouth keeps using CPU after boot, sometimes NetworManagers can't run dnsmasq.

I can't fix that in general, as I don't know what causes these invalid rc2.d/ to rc5.d/ links with rcS init scripts. But for /etc/init.d/lvm2 in particular we can avoid running this pointless dummy script at all, I committed a change for this.

This bug was fixed in the package systemd - 219-6ubuntu1

---------------
systemd (219-6ubuntu1) vivid; urgency=medium

  * Merge with Debian experimental branch. Remaining Ubuntu changes:
    - Hack to support system-image read-only /etc, and modify files in
      /etc/writable/ instead.
    - Keep our much simpler udev maintainer scripts (all platforms must
      support udev, no debconf).
    - initramfs init-top: Drop $ROOTDELAY, we do that in a more sensible way
      with wait-for-root. Will get applicable to Debian once Debian gets
      wait-for-root in initramfs-tools.
    - initramfs init-bottom: If LVM is installed, settle udev,
      otherwise we get missing LV symlinks. Workaround for LP #1185394.
    - Add debian/udev.lvm2.init: Dummy SysV init script to satisfy insserv
      dependencies to "lvm2" which is handled with udev rules in Ubuntu.
    - Provide shutdown fallback for upstart. (LP: #1370329)
    - debian/extra/ifup@.service: Additionally run for "auto" class. We don't
      really support "allow-hotplug" in Ubuntu at the moment, so we need to
      deal with "auto" devices appearing after "/etc/init.d/networking start"
      already ran. (LP: #1374521) Also, check if devices are actually defined
      in /etc/network/interfaces as we don't use Debian's net.agent.
    - ifup@.service: Drop dependency on networking.service (i. e.
      /etc/init.d/networking), and merely ensure that /run/network exists.
      This avoids unnecessary dependencies/waiting during boot and dependency
      cycles if hooks wait for other interfaces to come up (like ifenslave
      with bonding interfaces). (LP: #1414544)
    - Add Get-RTC-is-in-local-time-setting-from-etc-default-rc.patch: In
      Ubuntu we currently keep the setting whether the RTC is in local or UTC
      time in /etc/default/rcS "UTC=yes|no", instead of /etc/adjtime.
      (LP: #1377258)
    - Put session scopes into all cgroup controllers. This makes unprivileged
      user LXC containers work under systemd. (LP: #1346734)
    - systemctl: Don't forward telinit u to upstart. This works around
      upstart's Restart() always reexec'ing /sbin/init on Restart(), even if
      that changes to point to systemd during the upgrade. This avoids running
      systemd during a dist-upgrade. (LP: #1430479)
    - Lower Breaks: to plymouth version which has the udev inotify fix in
      Ubuntu.
    - Lower libappamor1 dep to the Ubuntu version where it moved to /lib.
    - Change systemd-sysv's conflicts to upstart-sysv. (LP: #1422681)
    - Make failure of boot-and-services NSpawn.test_boot non-fatal for now.
      This currently fails when being triggered by Jenkins, but is totally
      unreproducible when running this manually on the exact same machine.

    Upgrade fixes, keep until 16.04 LTS release:
    - systemd Conflicts/Replaces/Provides systemd-services.
    - Remove obsolete systemd-logind upstart job.
    - Clean up obsolete /etc/udev/rules.d/README.

  * Add debian/udev.lvm2.service to avoid running the dummy lvm2 init script.
    (LP: #1431107)

systemd (219-6) experimental; urgency=medium

  [ Martin Pitt ]
  * Import patches from v219-stable branch (up to 85a6fab).
 ...

Im running Ubuntu 16.04 LTS and still this bug affecting me.