Bug 1073778

Jiri gave me access to the virtual guest that's having this problem.
The problem is plymouth-reboot.service is timing out. Once it's masked, the reboot is fast.

Here's the journal output for the timing out plymouth-reboot.service, with systemd's logging set to debug level:

# journalctl -u plymouth-reboot -b -1
-- Logs begin at Thu 2014-02-13 11:55:23 GMT, end at Fri 2014-03-07 15:26:49 GMT. --
Mar 07 15:21:46 rhel7 systemd[1]: Installed new job plymouth-reboot.service/start as 571
Mar 07 15:21:46 rhel7 systemd[1]: ConditionKernelCommandLine=!plymouth.enable=0 succeeded for plymouth-reboot.service.
Mar 07 15:21:46 rhel7 systemd[1]: Starting Show Plymouth Reboot Screen...
Mar 07 15:21:46 rhel7 systemd[1]: About to execute: /usr/sbin/plymouthd --mode=shutdown --attach-to-session
Mar 07 15:21:46 rhel7 systemd[1]: Forked /usr/sbin/plymouthd as 2230
Mar 07 15:21:46 rhel7 systemd[1]: plymouth-reboot.service changed dead -> start
Mar 07 15:21:46 rhel7 systemd[2230]: Executing: /usr/sbin/plymouthd --mode=shutdown --attach-to-session
Mar 07 15:21:47 rhel7 systemd[1]: Child 2230 belongs to plymouth-reboot.service
Mar 07 15:21:47 rhel7 systemd[1]: plymouth-reboot.service: control process exited, code=exited status=0
Mar 07 15:21:47 rhel7 systemd[1]: plymouth-reboot.service got final SIGCHLD for state start
Mar 07 15:21:47 rhel7 systemd[1]: Main PID guessed: 2246
Mar 07 15:21:47 rhel7 systemd[1]: About to execute: /usr/bin/plymouth show-splash
Mar 07 15:21:47 rhel7 systemd[1]: Forked /usr/bin/plymouth as 2247
Mar 07 15:21:47 rhel7 systemd[1]: plymouth-reboot.service changed start -> start-post
Mar 07 15:21:47 rhel7 systemd[2247]: Executing: /usr/bin/plymouth show-splash
Mar 07 15:23:17 rhel7 systemd[1]: plymouth-reboot.service operation timed out. Stopping.
Mar 07 15:23:17 rhel7 systemd[1]: plymouth-reboot.service changed start-post -> stop-sigterm
Mar 07 15:23:17 rhel7 systemd[1]: Child 2247 belongs to plymouth-reboot.service
Mar 07 15:23:17 rhel7 systemd[1]: Child 2246 belongs to plymouth-reboot.service
Mar 07 15:23:17 rhel7 systemd[1]: plymouth-reboot.service: main process exited, code=killed, status=15/TERM
Mar 07 15:23:17 rhel7 systemd[1]: plymouth-reboot.service changed stop-sigterm -> failed
Mar 07 15:23:17 rhel7 systemd[1]: Job plymouth-reboot.service/start finished, result=failed
Mar 07 15:23:17 rhel7 systemd[1]: Failed to start Show Plymouth Reboot Screen.
Mar 07 15:23:17 rhel7 systemd[1]: Unit plymouth-reboot.service entered failed state.
Mar 07 15:23:17 rhel7 systemd[1]: plymouth-reboot.service: cgroup is empty

Jiri, what version of plymouth do you have installed?

Can you:

1) # mkdir /var/log/journal
2) reboot and add plymouth.debug=stream:/dev/kmsg to the kernel command line 
3) reproduce the problem
4) on the next boot run

# journactl -b -1 -a -l > full-journal-of-last-boot.txt

5) attach full-journal-of-last-boot.txt

?

Created attachment 872839 [details]
full-journal-of-last-boot.txt

Hi Ray.

plymouth-0.8.9-0.2014.01.13.1.el7.x86_64

The log you requested is attached.

Please do tell if you need anything else. I can also provide you access to the machine.

Thanks!

Mar 10 20:39:15 rhel7 plymouthd[1628]: [main.c:1869]                               check_verbosity:could not stream output to /dev/kmsg: Permission denied

hmm, can you try booting with enforcing=0 in case selinux is preventing the logs from getting written?

Created attachment 873030 [details]
full-journal-of-last-boot.txt

So there are a few things going on here:

1) you've got a serial console so it shouldn't be trying to use the graphics hardware but it is anyway. That's fixed in a newer plymouth than you have installed. so when you upgrade your problem should fix itself unless you take the console=ttyS0 off the kernel command line.

2) your graphics hardware supports modesetting but doesn't support 32bit bpp.  We should be able to fallback to /dev/fb or to just using the text console, but we fail to do it properly.  There are two problems:

a) the first problem is the create_seat_for_udev_device function will only try e.g. /dev/fb0 if the pci device doesn't have an associated e.g. /dev/dri/card0 device.  We need to also try it in case the the drm device is present but unsuitable.

b) the second, related problem is create_seat_for_udev_device has no way of indicating failure, so the code to do text fallback never gets run in the scenario that the drm device is unsuitable.  Fixing that will require making the seat_added handler provide a return value and propagating it.  It's a little complicated by the fact that the seat added handler can get called before systemd has instructed plymouth to use the display hardware.  So we may not always know what return value to return.

Ray, I'm unable to find plymouth package newer than plymouth-0.8.9-0.10.20140113.el7 (which I'm running) in brew.

I'm using default kvm machine. I believe that this is pretty common environment for customers.

Your logs are definitely for an older plymouth than that.  One tricky issue with plymouth is, the plymouth that gets run is in the initrd not necessarily the one on the running system.  You have to run "dracut -f" to import the latest plymouth into the initrd.

Still, we should fix the issue.

Created attachment 873935 [details]
full-journal-of-last-boot-with-updated-dracut-image.txt

I ran "dracut -f" and got the log again.

weird: 

Mar 12 13:43:16 rhel7 : [main.c:2011]                        initialize_environment:source built on Jan 13 2014

so "dracut -f" must not be rebuilding your initrd or it's rebuilding one you aren't using or something. or maybe you have an old plymouth installed even though the rpm database says otherwise.

Oh. I know where the problem is.

I have:
plymouth-0.8.9-0.2014.01.13.1.el7.x86_64

the latest version in brew is:
plymouth-0.8.9-0.10.20140113.el7

But that is by NVR older so my package was not upgraded. That confused me completely.

and plymouth-0.8.9-0.10.20140113.el7 works fine to me, without the timeout. Closing this bz. Thanks!

does it work if you take console=ttyS0 off the kernel command line?  if so, that's surprising.

I'm assuming the answer to comment 14 is the timeout comes back in that case, and so I'd like to use this bug to deal with 2) from comment 7.

reopening.  If it turns out there is no timeout, then I'll file a new bug to handle 2) separately.

Created attachment 874255 [details]
full-journal-of-last-boot_without_dev_ttyS0.txt

I removed console=/dev/ttyS0 from the kcommand line. No timeout, all works fine.

okay, great. I'll close this bug again, then, and address the remaining issue (/dev/fb not getting tried after /dev/card0 fails to work out) in a new bug (probably for 7.1 or later)