systemd hang during startup (Fedora15/16)

chrisham · #1 14th November 2011, 11:03 PM

I'm seeing a hang of systemd during bootup - I believe it started some time around my update to the 2.6.40 kernel on Fedora15. But since my system usually runs 24/7 I'm not really sure wich update caused the problem.

I then updated to F16, in the hope that this would somehow cure the problem, but no luck so far.

Symptoms:
- During bootup, first everything seems fine, but then all activity dies down and the boot process just sits there and does nothing for several minutes
- If I wait patiently, I finally get to the graphical login, but logging in is impossible: after entering my password, the system just sits there and does nothing again. After some time, the login prompt reappears
- Also, logging in on a TTY is impossible as well: after one minute, the login times out and drops me at the login prompt again.
- I can work around the blockage with 'Alt+SysRq+e' - killing all processes except init. Graphical login is spawned again, and suddenly, login is possible again (on TTY as well) - I can then manually restart all the missing services, and get back to a working system ...
- ... but upon next reboot, the same thing happens all over again

To me, this looks like some part of the systemd bootup is hanging, and thus blocking all further activity depending on this part. The restart forced by SysRq+e somehow clears the blockage, and gets things going again. Unfortunately, due to the asynchronous nature of the systemd boot, I cannot figure out which part is causing the hang.

I booted up with log.level set to debug, and had a look at dmesg. I believe this excerpt shows where things start going sideways (complete dmesg attached), and to me things seem to point to the ttyX.services hanging - but beyond this, I cannot see a further path for analysis.

Code:

[...]
[   29.856366] systemd[1]: Received SIGRTMIN+20 from PID 166 (plymouthd).
[   29.856369] systemd[1]: Enabling showing of status.
[   29.856470] systemd[1]: Running GC...
[   45.994458] systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.StartUnit() on /org/freedesktop/systemd1
[   45.994892] systemd[1]: Failed to load configuration for autovt@tty2.service: File exists
[   45.994901] systemd[1]: Trying to enqueue job autovt@tty2.service/start/fail
[   50.990169] systemd-logind[1027]: Failed to start unit: Unit autovt@tty2.service failed to load: File exists. See system logs and 'systemctl status autovt@tty2.service' for details.
[   50.993778] systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.StartUnit() on /org/freedesktop/systemd1
[   50.993887] systemd[1]: Failed to load configuration for autovt@tty5.service: File exists
[   50.993895] systemd[1]: Trying to enqueue job autovt@tty5.service/start/fail
[   50.994178] systemd-logind[1027]: Failed to start unit: Unit autovt@tty5.service failed to load: File exists. See system logs and 'systemctl status autovt@tty5.service' for details.
[   51.416940] systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.StartUnit() on /org/freedesktop/systemd1
[   51.417046] systemd[1]: Failed to load configuration for autovt@tty6.service: File exists
[   51.417055] systemd[1]: Trying to enqueue job autovt@tty6.service/start/fail
[   51.417366] systemd-logind[1027]: Failed to start unit: Unit autovt@tty6.service failed to load: File exists. See system logs and 'systemctl status autovt@tty6.service' for details.
[   52.263864] systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.StartUnit() on /org/freedesktop/systemd1
[   52.263883] systemd[1]: Trying to enqueue job autovt@tty5.service/start/fail
[   52.264163] systemd-logind[1027]: Failed to start unit: Unit autovt@tty5.service failed to load: File exists. See system logs and 'systemctl status autovt@tty5.service' for details.
[   66.202683] systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.StartUnit() on /org/freedesktop/systemd1
[   66.202815] systemd[1]: Failed to load configuration for autovt@tty4.service: File exists
[   66.202823] systemd[1]: Trying to enqueue job autovt@tty4.service/start/fail
[   66.203037] systemd-logind[1027]: Failed to start unit: Unit autovt@tty4.service failed to load: File exists. See system logs and 'systemctl status autovt@tty4.service' for details.
[   84.576682] systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.StartUnit() on /org/freedesktop/systemd1
[   84.576795] systemd[1]: Failed to load configuration for autovt@tty3.service: File exists
[   84.576803] systemd[1]: Trying to enqueue job autovt@tty3.service/start/fail
[   84.577014] systemd-logind[1027]: Failed to start unit: Unit autovt@tty3.service failed to load: File exists. See system logs and 'systemctl status autovt@tty3.service' for details.
[   85.615688] systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.StartUnit() on /org/freedesktop/systemd1
[...]

The corresponding part of /var/log/messages looks like this:

Code:

[...]
Nov 14 00:47:45 calvin [   14.972323] smartd[992]: Device: /dev/sdb [SAT], found in smartd database: S
AMSUNG SpinPoint T166
Nov 14 00:47:45 calvin [   15.066964] avahi-daemon[1005]: Found user 'avahi' (UID 498) and group 'avah
i' (GID 494).
Nov 14 00:47:45 calvin [   15.067044] avahi-daemon[1005]: Successfully dropped root privileges.
Nov 14 00:47:45 calvin [   15.067239] avahi-daemon[1005]: avahi-daemon 0.6.30 starting up.
Nov 14 00:47:45 calvin [   15.249624] NetworkManager[998]: <info> NetworkManager (version 0.9.1.90-5.g
it20110927.fc16) is starting...
Nov 14 00:47:45 calvin [   15.249631] NetworkManager[998]: <info> Read config file /etc/NetworkManager
/NetworkManager.conf
Nov 14 00:47:45 calvin [   15.250454] NetworkManager[998]: NetworkManager[998]: <info> NetworkManager 
(version 0.9.1.90-5.git20110927.fc16) is starting...
Nov 14 00:47:45 calvin [   15.250469] NetworkManager[998]: NetworkManager[998]: <info> Read config fil
e /etc/NetworkManager/NetworkManager.conf
Nov 14 00:47:45 calvin [   15.252405] ntpd[1002]: 0.0.0.0 c016 06 restart
Nov 14 00:47:45 calvin [   15.252412] ntpd[1002]: 0.0.0.0 c012 02 freq_set kernel 3.231 PPM
Nov 14 00:47:45 calvin [   15.411691] smartd[992]: Device: /dev/sdb [SAT], is SMART capable. Adding to
 "monitor" list.
Nov 14 00:47:45 calvin [   15.417740] dbus-daemon[1040]: dbus[1040]: avc:  netlink poll: error 4
Nov 14 00:47:45 calvin [   15.417747] dbus[1040]: avc:  netlink poll: error 4
Nov 14 00:47:45 calvin [   15.418296] smartd[992]: Device: /dev/sdc, type changed from 'scsi' to 'sat'
Nov 14 00:47:45 calvin [   15.418306] smartd[992]: Device: /dev/sdc [SAT], opened
Nov 14 00:47:45 calvin [   15.422449] avahi-daemon[1005]: Successfully called chroot().
Nov 14 00:47:45 calvin [   15.422457] avahi-daemon[1005]: Successfully dropped remaining capabilities.
Nov 14 00:47:45 calvin [   15.422948] avahi-daemon[1005]: Loading service file /services/ssh.service.
Nov 14 00:47:45 calvin [   15.422954] avahi-daemon[1005]: Loading service file /services/udisks.service.
Nov 14 00:47:45 calvin [   15.422966] systemd-logind[1027]: New seat seat0.
Nov 14 00:47:45 calvin [   15.423046] avahi-daemon[1005]: Network interface enumeration completed.
Nov 14 00:47:45 calvin [   15.423130] avahi-daemon[1005]: Registering HINFO record with values 'X86_64'/'LINUX'.
Nov 14 00:47:45 calvin [   15.423210] avahi-daemon[1005]: Server startup complete. Host name is calvin.local. Local service cookie is 962166671.
Nov 14 00:47:45 calvin [   15.423258] avahi-daemon[1005]: Service "calvin" (/services/udisks.service) successfully established.
Nov 14 00:47:45 calvin [   15.423263] avahi-daemon[1005]: Service "calvin" (/services/ssh.service) successfully established.
Nov 14 00:47:45 calvin [   15.424892] smartd[992]: Device: /dev/sdc [SAT], SAMSUNG HD502IJ, S/N:S13TJ1CQ400922, WWN:5-0000f, FW:1AA01110, 500 GB
Nov 14 00:47:45 calvin [   15.426473] smartd[992]: Device: /dev/sdc [SAT], found in smartd database: SAMSUNG SpinPoint F1 DT
Nov 14 00:47:45 calvin [   15.473955] mcelog[1052]: mcelog: Unsupported new Family 6 Model 1e CPU: only decoding architectural errors
Nov 14 00:47:45 calvin [   15.502089] smartd[992]: Device: /dev/sdc [SAT], is SMART capable. Adding to "monitor" list.
Nov 14 00:47:45 calvin [   15.504355] smartd[992]: Device: /dev/sdd, type changed from 'scsi' to 'sat'
Nov 14 00:47:45 calvin [   15.504411] smartd[992]: Device: /dev/sdd [SAT], opened
Nov 14 00:47:45 calvin [   15.506543] smartd[992]: Device: /dev/sdd [SAT], SAMSUNG HD501LJ, S/N:S0MUJDWPC09184, WWN:5-0000f0-0dbc09184, FW:CR100-12, 500 GB
Nov 14 00:47:45 calvin [   15.509135] smartd[992]: Device: /dev/sdd [SAT], found in smartd database: SAMSUNG SpinPoint T166
Nov 14 00:47:45 calvin kernel: : [   15.582061] syslog-ng (1056): Attempt to access syslog with CAP_SYS_ADMIN but no CAP_SYSLOG (deprecated).
Nov 14 00:48:20 calvin [   50.990169] systemd-logind[1027]: Failed to start unit: Unit autovt@tty2.service failed to load: File exists. See system logs and 'systemctl status autovt@tty2.service' for details.
Nov 14 00:48:20 calvin [   50.994178] systemd-logind[1027]: Failed to start unit: Unit autovt@tty5.service failed to load: File exists. See system logs and 'systemctl status autovt@tty5.service' for details.
[...]

I also attached /var/log/boot.log - the only thing that sticks out to me is NetworkManager failing - but I cannot tell if this is cause or effect.

Could anybody please point me in the direction of further useful things to do, or pieces of information I forgot to provide?

Thanks,

-chris

----------------------
SOLVED

Pls. see below

chrisham · #2 16th November 2011, 08:08 PM

The problem 'disappeared' after todays update to kernel 3.1.1-1 together with the corresponding NVIDIA driver from RPMfusion. Booting into the new kernel went through witout any hangups, no failed services, no 'quiet waits' during the boot process.

Still, having this problem just disappear without any analysis or understanding of what caused the problem in the first place leaves a bit of a bad feeling.

So, if anyone can still shed some light onto what might have caused the problem, I'd be grateful.

chrisham · #3 17th November 2011, 09:03 PM

And here we go again - after another reboot it turns out the problem is still there.

Again a hang during boot, 'Alt+SysRq+e' gets things going again ... I still need help figuring out where to look for a real solution.

chrisham · #4 6th December 2011, 11:49 PM

OK - after much suffering I finally found a solution for my problem:

It turns out that systemd does not agree with syslog-ng

Fedora offers the choice between three logging daemons: sysklogd, syslog-ng and rsyslog. My system has been updated (without ever reinstalling) all the way from the early pre-Fedora (Redhat) days - somewhere along the line, I must have switched from the original sysklogd to syslog-ng. This was then propagated through all the updates, just waiting to fail as soon as systemd was introduced, and a certain change made it into syslog-ng.

Unfortunately, I cannot find the Web page anymore that finally pointed me in the right directions. However, after replacing syslog-ng with rsyslog, my boot immediately went all the way through to the KDM start screen - everything seems alright now.

Ernst0 · #5 19th February 2012, 03:46 AM

I have this problem and I can stand all the hand holding anyone cares to offer.

I just followed the installation of the NVIDIA files as directed in that thread.

What do I do to change this? This is a fresh install from the F16 Gnome distro plus the updates and NVIDIA.

I appreciate the help.

I don't know if it is related but the encrypted file system reports corruption every time software is installed or updates. It is rebuilding the files and directories right now. I figure the new repair is not like the old fsck