Bug#920234: systemd: insufficient log options when there is a bad /etc/crypttab entry

[Russell Coker]

Package: systemd
Version: 240-4
Severity: normal

When I have a bogus /etc/crypttab entry (for example when converting an
encrypted laptop to a virtual machine that's not encrypted) the boot process
hangs for 90 seconds for no obvious reason.

[    **] A start job is running for /dev/dis·9597-dbdb2fedbd1f (24s / 1min 30s)

When seeing the above anyone who doesn't know that "grep -R dbdb2fedbd1f /etc"
is necessary will have trouble determining the cause of this.

# systemd-analyze blame
Bootup is not yet finished (org.freedesktop.systemd1.Manager.FinishTimestampMonotonic=0).
Please try again later.
Hint: Use 'systemctl list-jobs' to see active jobs
# systemctl list-jobs
JOB UNIT                                                           TYPE  STATE  
181 dev-disk-by\x2duuid-…75\x2d410c\x2d9597\x2ddbdb2fedbd1f.device start running
179 systemd-cryptsetup at nvme0n1p2_crypt.service                     start waiting

2 jobs listed

The above commands run during the boot process makes the problem obvious.  But
what if the cryptsetup command completely fails before the sysadmin logs in?

# systemd-analyze blame|head
          1.051s ifupdown-wait-online.service
           958ms tor at default.service
           753ms postfix at -.service
           494ms udisks2.service
           480ms networking.service
           445ms dev-vda.device
           260ms accounts-daemon.service
           245ms gdomap.service
           217ms systemd-timesyncd.service
           216ms auditd.service

I would hope to see a 90 second entry in the above, but we don't get one.

# systemd-analyze critical-chain
The time after the unit is active or started is printed after the "@" character.
The time the unit takes to start is printed after the "+" character.

graphical.target @1min 31.348s
└─multi-user.target @1min 31.347s
  └─postfix.service @1min 31.339s +7ms
    └─postfix at -.service @1min 30.583s +753ms
      └─basic.target @1min 30.512s
        └─sockets.target @1min 30.506s
          └─dbus.socket @1min 30.505s
            └─sysinit.target @1min 30.492s
              └─systemd-update-utmp.service @902ms +41ms
                └─auditd.service @664ms +216ms
                  └─systemd-tmpfiles-setup.service @602ms +50ms
                    └─local-fs.target @598ms
                      └─run-user-0.mount @1min 45.931s
                        └─swap.target @940ms
                          └─dev-vdb.swap @909ms +27ms
                            └─dev-vdb.device @876ms

I expect to see something with +90s in the above, but it doesn't happen.
Something between systemd-update-utmp.service and sysinit.target took 90
seconds and there's no obvious way of discovering what it was.

-- Package-specific info:

-- System Information:
Debian Release: buster/sid
  APT prefers stable-updates
  APT policy: (500, 'stable-updates'), (500, 'testing'), (1, 'experimental')
Architecture: amd64 (x86_64)

Kernel: Linux 4.19.0-1-amd64 (SMP w/2 CPU cores)
Locale: LANG=en_AU.UTF-8, LC_CTYPE=en_AU.UTF-8 (charmap=UTF-8), LANGUAGE=en_AU:en (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)
LSM: SELinux: enabled - Mode: Enforcing - Policy name: default

Versions of packages systemd depends on:
ii  adduser          3.118
ii  libacl1          2.2.52-3+b1
ii  libapparmor1     2.13.2-3
ii  libaudit1        1:2.8.4-2
ii  libblkid1        2.33.1-0.1
ii  libc6            2.28-5
ii  libcap2          1:2.25-1.2
ii  libcryptsetup12  2:2.0.6-1
ii  libgcrypt20      1.8.4-4
ii  libgnutls30      3.6.5-2
ii  libgpg-error0    1.33-3
ii  libidn11         1.33-2.2
ii  libip4tc0        1.8.2-3
ii  libkmod2         25-2
ii  liblz4-1         1.8.3-1
ii  liblzma5         5.2.2-1.3
ii  libmount1        2.33.1-0.1
ii  libpam0g         1.1.8-4
ii  libseccomp2      2.3.3-3
ii  libselinux1      2.8-1+b1
ii  libsystemd0      240-4
ii  mount            2.33.1-0.1
ii  util-linux       2.33.1-0.1

Versions of packages systemd recommends:
ii  dbus            1.12.12-1
ii  libpam-systemd  240-4

Versions of packages systemd suggests:
ii  policykit-1        0.105-25
ii  systemd-container  240-4

Versions of packages systemd is related to:
pn  dracut           <none>
ii  initramfs-tools  0.132
ii  udev             240-4

-- no debconf information