[systemd-devel] systemd hangs on shutdown

[Lennart Poettering]

On Thu, 29.09.11 14:29, Daniel Drake (dsd at laptop.org) wrote:

> sysrq-T (show task state) shows the following userspace processes running:
> systemd, udevd (several threads/instances), systemd-stdout-,
> systemd-kmsg-sy, plymouthd. (they are all epolling stuff)
> 
> Can you confirm that at this point, those tasks should still be
> running (and should not have been killed by the mass kill of processes
> that just happened)? Just wondering if systemd is waiting for them to
> die, or is waiting on some other condition.

Yupp, those processes look OK.

> Another observation: after waiting several minutes,
> systemd-stdout-syslog-bridge.service generates a notification message
> and seems to nudge systemd a little closer to completing the shutdown
> routine (please see 387.600571 in the full logs below).

Nah, that looks rather uninteristing, as this is just the bridge
terminating after being idle for too long.

> 
> Weird ordering of messages here:
> [   61.831071] systemd[1]: Child 1464 belongs to var-lib-random\x2dseed.mount
> [   61.837978] systemd[1]: var-lib-random\x2dseed.mount mount process
> exited, code=exited status=0
> [   61.847778] systemd[1]: var-lib-random\x2dseed.mount changed
> unmounting -> dead
> [   61.890550] systemd[1]: Job var-lib-random\x2dseed.mount/stop
> finished, result=done
> snip
> [   62.298212] systemd[1]: Got SIGCHLD for process 1477 (umount)
> [   62.305426] systemd[1]: Child 1477 died (code=exited, status=0/SUCCESS)
> [   62.312138] systemd[1]: Child 1477 belongs to var-lib-dbus.mount
> [   62.318182] systemd[1]: var-lib-dbus.mount mount process exited,
> code=exited status=0
> [   62.327267] systemd[1]: var-lib-dbus.mount changed unmounting -> dead
> [   62.370552] systemd[1]: Job var-lib-dbus.mount/stop finished, result=done
> snip
> [   62.955961] systemd[1]: var-lib-random\x2dseed.mount changed dead -> mounted
> [   62.967152] systemd[1]: var-lib-dbus.mount changed dead -> mounted
> 
> Why do they get marked as mounted after being unmounted?
> The other similar mounts all got 'collected', these 2 did not.

So this is a the big issue here I believe. If you look at 87.293308
you'll see that tmp.mount is suddenly mounted again for some reason,
which systemd then takes as hint to get rid of
poweroff.target/poweroff.service, since they conflict with that.

It key to the mystery here is figuring out why systemd suddenly sees
those mount points coming back. It would be good to figure out what the
mount table is when that happens.

> Is it normal for the systemd-kmsg-syslogd service to be *started*
> quite late in the shutdown process?

Yupp. It's started whenever something logs and no real syslog is
running. It just connects /dev/log to kmsg and has no impact
otherwise. It's just to make sure that your logs are complete from the
start of boot to the shutdown.

> Some services have a "cgroup is empty" message logged before or after
> they are marked as done (such as prefdm.service, avahi-daemon.service_
> bu some services have no such line logged (e.g. sshd-keygen.service,
> console-kit-daemon.service)

That's completely fine as these messages are generated async.

> Some mounts/services are "collected" (e.g. console-kit-daemon.service,
> var-spool.mount) and others are not (e.g. crond.service,
> var-log.mount, var-lib-dbus.mount)

That's fine too. Depends on how they are referenced. Basically all units
not explicitly referenced will eventually be GC'ed. Stuff that isn't
GC'ed is hence still referenced by some unit that is still running.

> I can't see anything that tries to shut down
> systemd-stdout-syslog-bridge.service. Is that normal? Might systemd be
> waiting for it?

Nope. Much like kmsg-syslogd this service should not delay shutdown.

> Any new ideas?

Yupp, the mount issue is the key to the mystery...

Lennart

-- 
Lennart Poettering - Red Hat, Inc.