Bug#669101: systemd: Boot hangs

[Mark Brown]

Package: systemd
Version: 44-1
Severity: important

Attempting to boot systemd on this system by adding init=/bin/systemd to
the end of the kernel command line results in:

- The output of the fsck processes for the disks being displayed
- The screen changes to a higher resolution console mode

but no further output or disk activity. The system still appears to be
running and ctrl-alt-delete triggers a clean reboot so it's presumably
blocked on something. This did work at some point in the past but it
was months ago so not useful for bisection.

Is there any way to get more diagnostics out of the system?

-- System Information:
Debian Release: wheezy/sid
APT prefers unstable
APT policy: (500, 'unstable'), (1, 'experimental')
Architecture: amd64 (x86_64)

Kernel: Linux 3.2.0-2-amd64 (SMP w/2 CPU cores)
Locale: LANG=en_GB.utf8, LC_CTYPE=en_GB.utf8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash

Versions of packages systemd depends on:
ii dpkg 1.16.2
ii initscripts 2.88dsf-22.1
ii libacl1 2.2.51-5
ii libaudit0 1:1.7.18-1.1
ii libc6 2.13-27
ii libcap2 1:2.22-1
ii libcryptsetup4 2:1.4.1-3
ii libdbus-1-3 1.5.12-1
ii libkmod2 6-2
ii liblzma5 5.1.1alpha+20110809-3
ii libpam0g 1.1.3-7
ii libselinux1 2.1.9-4
ii libsystemd-daemon0 44-1
ii libsystemd-id128-0 44-1
ii libsystemd-journal0 44-1
ii libsystemd-login0 44-1
ii libudev0 175-3.1
ii libwrap0 7.6.q-23
ii udev 175-3.1
ii util-linux 2.20.1-4

Versions of packages systemd recommends:
ii libpam-systemd 44-1

Versions of packages systemd suggests:
ii python 2.7.2-10
ii systemd-gui 44-1

-- no debconf information



--
To UNSUBSCRIBE, email to debian-bugs-...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org

[Tollef Fog Heen]

]] Mark Brown

> Attempting to boot systemd on this system by adding init=/bin/systemd to
> the end of the kernel command line results in:
>
> - The output of the fsck processes for the disks being displayed
> - The screen changes to a higher resolution console mode
>
> but no further output or disk activity. The system still appears to be
> running and ctrl-alt-delete triggers a clean reboot so it's presumably
> blocked on something. This did work at some point in the past but it
> was months ago so not useful for bisection.
>
> Is there any way to get more diagnostics out of the system?

http://fedoraproject.org/wiki/How_to_debug_Systemd_problems has a bunch
of help for debugging systemd problems.

The first thing I'd do is make sure you do not include «quiet» on the
command line, it should then output more than you list above.

--
Tollef Fog Heen
UNIX is user friendly, it's just picky about who its friends are

[Mark Brown]

On Tue, May 08, 2012 at 08:39:26PM +0200, Tollef Fog Heen wrote:

> http://fedoraproject.org/wiki/How_to_debug_Systemd_problems has a bunch
> of help for debugging systemd problems.

I tried this. As far as I can tell the job that should indicate that my
rootfs (which is encrypted) is failing to start and half the world is
waiting for it. This may well be due to the disk already being mounted
by the initramfs...

> The first thing I'd do is make sure you do not include «quiet» on the
> command line, it should then output more than you list above.

It shows more, but it just shows a bunch of things succeeding. There's
no errors visible.

[Tollef Fog Heen]

]] Mark Brown

> On Tue, May 08, 2012 at 08:39:26PM +0200, Tollef Fog Heen wrote:
>
> > http://fedoraproject.org/wiki/How_to_debug_Systemd_problems has a bunch
> > of help for debugging systemd problems.
>
> I tried this. As far as I can tell the job that should indicate that my
> rootfs (which is encrypted) is failing to start and half the world is
> waiting for it. This may well be due to the disk already being mounted
> by the initramfs...

Can you verify that /lib/systemd/system/cryptdisks.service is a symlink
to /dev/null? (And if not, we'll have to figure out why not.) Are you
using some other tool than cryptdisks for encrypted /?

You might also be hit by
http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=670591, and if you
think you are, try the workaround listed in the bug:

ln -s /dev/null /lib/systemd/system/checkroot-bootclean.service

Cheers,

--
Tollef Fog Heen
UNIX is user friendly, it's just picky about who its friends are

[Mark Brown]

On Wed, May 09, 2012 at 07:56:40AM +0200, Tollef Fog Heen wrote:

> Can you verify that /lib/systemd/system/cryptdisks.service is a symlink
> to /dev/null? (And if not, we'll have to figure out why not.) Are you

It is.

> using some other tool than cryptdisks for encrypted /?

I'm using whatever d-i gave me.

> You might also be hit by
> http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=670591, and if you
> think you are, try the workaround listed in the bug:

> ln -s /dev/null /lib/systemd/system/checkroot-bootclean.service

Tried this, didn't seem to make any difference.

[Tollef Fog Heen]

]] Mark Brown

> On Wed, May 09, 2012 at 07:56:40AM +0200, Tollef Fog Heen wrote:
> > using some other tool than cryptdisks for encrypted /?
>
> I'm using whatever d-i gave me.

That should be cryptsetup and cryptdisks then.

It sounded like you got to a point where you had a shell last night,
could you try to get there again, then run systemctl --full and pastebin
or take a picture of that screen? It should have some clues as to what
is being waited for.

--
Tollef Fog Heen
UNIX is user friendly, it's just picky about who its friends are

[Mark Brown]

On Wed, May 09, 2012 at 03:49:53PM +0200, Tollef Fog Heen wrote:

> It sounded like you got to a point where you had a shell last night,
> could you try to get there again, then run systemctl --full and pastebin
> or take a picture of that screen? It should have some clues as to what
> is being waited for.

Here you are, it's showing the same thing as last time - the encrypted
disk service for sda2 failed:


UNIT LOAD ACTIVE SUB JOB DESCRIPTION
proc-sys-fs-binfmt_misc.automount loaded active waiting Arbitrary Executable File Formats File System Automount Point
dev-disk-by\x2did-dm\x2dname\x2dsda2_crypt.device loaded active plugged stop /dev/disk/by-id/dm-name-sda2_crypt
dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2d14b2f7c9af244c5cbbac98766083aa16\x2dsda2_crypt.device loaded active plugged stop /dev/disk/by-id/dm-uuid-CRYPT-LUKS1-14b2f7c9af244c5cbbac98766083aa16-sda2_crypt
dev-dm\x2d0.device loaded active plugged stop /dev/dm-0
dev-mapper-sda2_crypt.device loaded active plugged stop /dev/mapper/sda2_crypt
sys-devices-pci0000:00-0000:00:19.0-net-eth0.device loaded active plugged 82567LM Gigabit Network Connection
sys-devices-pci0000:00-0000:00:1a.0-usb3-3\x2d1-3\x2d1.3-3\x2d1.3:1.0-bluetooth-hci0.device loaded active plugged /sys/devices/pci0000:00/0000:00:1a.0/usb3/3-1/3-1.3/3-1.3:1.0/bluetooth/hci0
sys-devices-pci0000:00-0000:00:1b.0-sound-card0.device loaded active plugged 82801I (ICH9 Family) HD Audio Controller
sys-devices-pci0000:00-0000:00:1c.1-0000:0c:00.0-net-wlan0.device loaded active plugged WiFi Link 5100
sys-devices-pci0000:00-0000:00:1e.0-0000:02:01.1-mmc_host-mmc0-mmc0:1234-block-mmcblk0-mmcblk0p1.device loaded active plugged /sys/devices/pci0000:00/0000:00:1e.0/0000:02:01.1/mmc_host/mmc0/mmc0:1234/block/mmcblk0/mmcblk0p1
sys-devices-pci0000:00-0000:00:1e.0-0000:02:01.1-mmc_host-mmc0-mmc0:1234-block-mmcblk0-mmcblk0p2.device loaded active plugged /sys/devices/pci0000:00/0000:00:1e.0/0000:02:01.1/mmc_host/mmc0/mmc0:1234/block/mmcblk0/mmcblk0p2
sys-devices-pci0000:00-0000:00:1e.0-0000:02:01.1-mmc_host-mmc0-mmc0:1234-block-mmcblk0-mmcblk0p3.device loaded active plugged /sys/devices/pci0000:00/0000:00:1e.0/0000:02:01.1/mmc_host/mmc0/mmc0:1234/block/mmcblk0/mmcblk0p3
sys-devices-pci0000:00-0000:00:1e.0-0000:02:01.1-mmc_host-mmc0-mmc0:1234-block-mmcblk0.device loaded active plugged /sys/devices/pci0000:00/0000:00:1e.0/0000:02:01.1/mmc_host/mmc0/mmc0:1234/block/mmcblk0
sys-devices-pci0000:00-0000:00:1f.2-host0-target0:0:0-0:0:0:0-block-sda-sda1.device loaded active plugged WDC_WD1600BJKT-75F4T0
sys-devices-pci0000:00-0000:00:1f.2-host0-target0:0:0-0:0:0:0-block-sda-sda2.device loaded active plugged WDC_WD1600BJKT-75F4T0
sys-devices-pci0000:00-0000:00:1f.2-host0-target0:0:0-0:0:0:0-block-sda.device loaded active plugged WDC_WD1600BJKT-75F4T0
sys-devices-pci0000:00-0000:00:1f.2-host1-target1:0:0-1:0:0:0-block-sr0.device loaded active plugged TSSTcorp_DVD+_-RW_TS-U633F
sys-devices-platform-serial8250-tty-ttyS0.device loaded active plugged /sys/devices/platform/serial8250/tty/ttyS0
sys-devices-platform-serial8250-tty-ttyS1.device loaded active plugged /sys/devices/platform/serial8250/tty/ttyS1
sys-devices-platform-serial8250-tty-ttyS2.device loaded active plugged /sys/devices/platform/serial8250/tty/ttyS2
sys-devices-platform-serial8250-tty-ttyS3.device loaded active plugged /sys/devices/platform/serial8250/tty/ttyS3
sys-devices-virtual-block-dm\x2d0.device loaded active plugged stop /sys/devices/virtual/block/dm-0
sys-devices-virtual-block-dm\x2d1.device loaded active plugged /sys/devices/virtual/block/dm-1
sys-devices-virtual-block-dm\x2d2.device loaded active plugged /sys/devices/virtual/block/dm-2
sys-devices-virtual-tty-tty0.device loaded active plugged /sys/devices/virtual/tty/tty0
sys-devices-virtual-tty-tty1.device loaded active plugged /sys/devices/virtual/tty/tty1
sys-devices-virtual-tty-tty10.device loaded active plugged /sys/devices/virtual/tty/tty10
sys-devices-virtual-tty-tty11.device loaded active plugged /sys/devices/virtual/tty/tty11
sys-devices-virtual-tty-tty12.device loaded active plugged /sys/devices/virtual/tty/tty12
sys-devices-virtual-tty-tty2.device loaded active plugged /sys/devices/virtual/tty/tty2
sys-devices-virtual-tty-tty3.device loaded active plugged /sys/devices/virtual/tty/tty3
sys-devices-virtual-tty-tty4.device loaded active plugged /sys/devices/virtual/tty/tty4
sys-devices-virtual-tty-tty5.device loaded active plugged /sys/devices/virtual/tty/tty5
sys-devices-virtual-tty-tty6.device loaded active plugged /sys/devices/virtual/tty/tty6
sys-devices-virtual-tty-tty7.device loaded active plugged /sys/devices/virtual/tty/tty7
sys-devices-virtual-tty-tty8.device loaded active plugged /sys/devices/virtual/tty/tty8
sys-devices-virtual-tty-tty9.device loaded active plugged /sys/devices/virtual/tty/tty9
-.mount loaded active mounted /
boot.mount loaded active mounted /boot
dev-hugepages.mount loaded active mounted Huge Pages File System
dev-mqueue.mount loaded active mounted POSIX Message Queue File System
media.mount loaded active mounted Media Directory
sys-kernel-debug.mount loaded active mounted Debug File System
sys-kernel-security.mount loaded active mounted Security File System
cryptsetup@sda2_crypt.service loaded failed failed Cryptography Setup for sda2_crypt
emergency.service loaded active running Emergency Shell
systemd-journald.service loaded inactive dead start Journal Service
syslog.socket loaded active running stop Syslog Socket
systemd-journald.socket loaded active running Journal Socket
emergency.target loaded active active Emergency Mode

LOAD = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB = The low-level unit activation state, values depend on unit type.
JOB = Pending job for the unit.

50 units listed. Pass --all to see inactive units, too.

[Tollef Fog Heen]

]] Mark Brown

> On Wed, May 09, 2012 at 03:49:53PM +0200, Tollef Fog Heen wrote:
>
> > It sounded like you got to a point where you had a shell last night,
> > could you try to get there again, then run systemctl --full and pastebin
> > or take a picture of that screen? It should have some clues as to what
> > is being waited for.
>
> Here you are, it's showing the same thing as last time - the encrypted
> disk service for sda2 failed:

Indeed, thanks. What does your /etc/crypttab look like?

--
Tollef Fog Heen
UNIX is user friendly, it's just picky about who its friends are

[Mark Brown]

On Thu, May 17, 2012 at 09:03:49AM +0200, Tollef Fog Heen wrote:

> Indeed, thanks. What does your /etc/crypttab look like?

Like this:

# sda2_crypt /dev/sda2 none luks
sda2_crypt UUID=14b2f7c9-af24-4c5c-bbac-98766083aa16 none luks

[Tollef Fog Heen]

]] Mark Brown

> On Thu, May 17, 2012 at 09:03:49AM +0200, Tollef Fog Heen wrote:
>
> > Indeed, thanks. What does your /etc/crypttab look like?
>
> Like this:
>
> # sda2_crypt /dev/sda2 none luks
> sda2_crypt UUID=14b2f7c9-af24-4c5c-bbac-98766083aa16 none luks

And if you do blkid /dev/sda2, you get

/dev/sda2: UUID="14b2f7c9-af24-4c5c-bbac-98766083aa16" TYPE="crypto_LUKS"

right?

--
Tollef Fog Heen
UNIX is user friendly, it's just picky about who its friends are

[Mark Brown]

On Thu, May 17, 2012 at 06:36:24PM +0200, Tollef Fog Heen wrote:

> And if you do blkid /dev/sda2, you get

> /dev/sda2: UUID="14b2f7c9-af24-4c5c-bbac-98766083aa16" TYPE="crypto_LUKS"

Yes.

[Tollef Fog Heen]

]] Mark Brown

> On Thu, May 17, 2012 at 06:36:24PM +0200, Tollef Fog Heen wrote:
>
> > And if you do blkid /dev/sda2, you get
>
> > /dev/sda2: UUID="14b2f7c9-af24-4c5c-bbac-98766083aa16" TYPE="crypto_LUKS"
>
> Yes.

Ok, thanks.

Can you check what /run/systemd/generator/cryptsetup@sda2_crypt.service
looks like and tell me? Also, what does «systemctl show
cryptsetup@sda2_crypt.service» tell you?

In the .service file, you probably have a

ExecStart=/lib/systemd/systemd-cryptsetup attach 'sda2_crypt' '/dev/disk/by-uuid/14b2f7c9-af24-4c5c-bbac-98766083aa16' 'none' 'luks

line, right? Can you try running that by hand and see if you get any
errors?

Cheers,

--
Tollef Fog Heen
UNIX is user friendly, it's just picky about who its friends are

[Mark Brown]

On Thu, May 17, 2012 at 08:29:50PM +0200, Tollef Fog Heen wrote:

> Can you check what /run/systemd/generator/cryptsetup@sda2_crypt.service

> looks like and tell me? Also, what does ??systemctl show

[Unit]
Description=Cryptography Setup for %I
Conflicts=umount.target
DefaultDependencies=no
BindTo=dev-disk-by\x2duuid-14b2f7c9\x2daf24\x2d4c5c\x2dbbac\x2d98766083aa16.device dev-mapper-%i.device
After=systemd-readahead-collect.service systemd-readahead-replay.service dev-disk-by\x2duuid-14b2f7c9\x2daf24\x2d4c5c\x2dbbac\x2d98766083aa16.device
Before=umount.target
Before=cryptsetup.target
Before=local-fs.target

[Service]
Type=oneshot
RemainAfterExit=yes
TimeoutSec=0
ExecStart=/lib/systemd/systemd-cryptsetup attach 'sda2_crypt' '/dev/disk/by-uuid/14b2f7c9-af24-4c5c-bbac-98766083aa16' 'none' 'luks'
ExecStop=/lib/systemd/systemd-cryptsetup detach 'sda2_crypt'

> cryptsetup@sda2_crypt.service?? tell you?

Id=cryptsetup@sda2_crypt.service
Names=cryptsetup@sda2_crypt.service
Requires=systemd-journald.socket
BindTo=dev-disk-by\x2duuid-14b2f7c9\x2daf24\x2d4c5c\x2dbbac\x2d98766083aa16.device dev-mapper-sda2_crypt.device
RequiredBy=cryptsetup.target dev-mapper-sda2_crypt.device
WantedBy=dev-disk-by\x2duuid-14b2f7c9\x2daf24\x2d4c5c\x2dbbac\x2d98766083aa16.device
Conflicts=umount.target
Before=umount.target cryptsetup.target local-fs.target
After=systemd-readahead-collect.service systemd-readahead-replay.service dev-disk-by\x2duuid-14b2f7c9\x2daf24\x2d4c5c\x2dbbac\x2d98766083aa16.device systemd-journald.socket
Description=Cryptography Setup for sda2_crypt
LoadState=loaded
ActiveState=failed
SubState=failed
FragmentPath=/run/systemd/generator/cryptsetup@sda2_crypt.service
InactiveExitTimestamp=Fri, 18 May 2012 15:27:24 +0100
InactiveExitTimestampMonotonic=44876159
ActiveEnterTimestamp=Fri, 18 May 2012 15:27:25 +0100
ActiveEnterTimestampMonotonic=45316060
ActiveExitTimestamp=Fri, 18 May 2012 15:28:41 +0100
ActiveExitTimestampMonotonic=122176104
InactiveEnterTimestamp=Fri, 18 May 2012 15:28:42 +0100
InactiveEnterTimestampMonotonic=122344250
CanStart=yes
CanStop=yes
CanReload=no
CanIsolate=no
StopWhenUnneeded=no
RefuseManualStart=no
RefuseManualStop=no
AllowIsolate=no
DefaultDependencies=no
OnFailureIsolate=no
IgnoreOnIsolate=no
IgnoreOnSnapshot=no
DefaultControlGroup=name=systemd:/system/cryptsetup@.service/sda2_crypt
ControlGroup=cpu:/system/cryptsetup@.service/sda2_crypt name=systemd:/system/cryptsetup@.service/sda2_crypt
NeedDaemonReload=no
JobTimeoutUSec=0
ConditionTimestamp=Fri, 18 May 2012 15:27:24 +0100
ConditionTimestampMonotonic=44851399
ConditionResult=yes
Type=oneshot
Restart=no
NotifyAccess=none
RestartUSec=100ms
TimeoutUSec=0
WatchdogUSec=0
WatchdogTimestampMonotonic=0
StartLimitInterval=10000000
StartLimitBurst=5
StartLimitAction=none
ExecStart={ path=/lib/systemd/systemd-cryptsetup ; argv[]=/lib/systemd/systemd-cryptsetup attach sda2_crypt /dev/disk/by-uuid/14b2f7c9-af24-4c5c-bbac-98766083aa16 none luks ; ignore_errors=no ; start_time=[Fri, 18 May 2012 15:27:24 +0100] ; stop_time=[Fri, 18 May 2012 15:27:24 +0100] ; pid=676 ; code=exited ; status=0 }
ExecStop={ path=/lib/systemd/systemd-cryptsetup ; argv[]=/lib/systemd/systemd-cryptsetup detach sda2_crypt ; ignore_errors=no ; start_time=[Fri, 18 May 2012 15:28:41 +0100] ; stop_time=[Fri, 18 May 2012 15:28:42 +0100] ; pid=735 ; code=exited ; status=1 }
PermissionsStartOnly=no
RootDirectoryStartOnly=no
RemainAfterExit=yes
GuessMainPID=yes
MainPID=0
ControlPID=0
SysVStartPriority=-1
FsckPassNo=0
Result=exit-code
UMask=0022
LimitCPU=18446744073709551615
LimitFSIZE=18446744073709551615
LimitDATA=18446744073709551615
LimitSTACK=18446744073709551615
LimitCORE=18446744073709551615
LimitRSS=18446744073709551615
LimitNOFILE=4096
LimitAS=18446744073709551615
LimitNPROC=31242
LimitMEMLOCK=65536
LimitLOCKS=18446744073709551615
LimitSIGPENDING=31242
LimitMSGQUEUE=819200
LimitNICE=0
LimitRTPRIO=0
LimitRTTIME=18446744073709551615
OOMScoreAdjust=0
Nice=0
IOScheduling=0
CPUSchedulingPolicy=0
CPUSchedulingPriority=0
TimerSlackNSec=50000
CPUSchedulingResetOnFork=no
NonBlocking=no
StandardInput=null
StandardOutput=journal
StandardError=inherit
TTYReset=no
TTYVHangup=no
TTYVTDisallocate=no
SyslogPriority=30
SyslogLevelPrefix=yes
SecureBits=0
CapabilityBoundingSet=18446744073709551615
MountFlags=1048576
PrivateTmp=no
PrivateNetwork=no
SameProcessGroup=no
KillMode=control-group
KillSignal=15
ControlGroupModify=no
ControlGroupPersistent=no
IgnoreSIGPIPE=yes
ExecMainStartTimestamp=Fri, 18 May 2012 15:27:24 +0100
ExecMainStartTimestampMonotonic=44876150
ExecMainExitTimestamp=Fri, 18 May 2012 15:27:24 +0100
ExecMainExitTimestampMonotonic=44876150
ExecMainPID=676
ExecMainCode=1
ExecMainStatus=0

> In the .service file, you probably have a

> ExecStart=/lib/systemd/systemd-cryptsetup attach 'sda2_crypt' '/dev/disk/by-uuid/14b2f7c9-af24-4c5c-bbac-98766083aa16' 'none' 'luks

> line, right? Can you try running that by hand and see if you get any
> errors?

It says "Volume sda2_crypt already active." and exits with status 0 if I
put it in a file and source it but if I run it with $(cat file) I get:

| Password file path 'none' is not absolute. Ignoring.
| Encountered unknown /etc/crypttab options ''luks'', ignoring.
| crypt_init() failed: block device required

(I assume due to escaping). Interestingly if I start it by hand the job
shows itself as active/exited, I then get a failed udev.