RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1073778 - plymouth-reboot.service times out on reboot, causing 90s delay
Summary: plymouth-reboot.service times out on reboot, causing 90s delay
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: plymouth
Version: 7.0
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: rc
: ---
Assignee: Ray Strode [halfline]
QA Contact: Desktop QE
URL:
Whiteboard:
Depends On:
Blocks: 1076587
TreeView+ depends on / blocked
 
Reported: 2014-03-07 08:03 UTC by Jiri Pirko
Modified: 2015-05-05 01:25 UTC (History)
4 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
: 1076587 (view as bug list)
Environment:
Last Closed: 2014-03-14 14:58:48 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)
full-journal-of-last-boot.txt (205.57 KB, text/plain)
2014-03-10 20:54 UTC, Jiri Pirko 		no flags Details
full-journal-of-last-boot.txt (216.73 KB, text/plain)
2014-03-11 09:44 UTC, Jiri Pirko 		no flags Details
full-journal-of-last-boot-with-updated-dracut-image.txt (247.47 KB, text/plain)
2014-03-13 11:42 UTC, Jiri Pirko 		no flags Details
full-journal-of-last-boot_without_dev_ttyS0.txt (254.81 KB, text/plain)
2014-03-14 07:10 UTC, Jiri Pirko 		no flags Details
Show Obsolete (1) View All

Description Jiri Pirko 2014-03-07 08:03:44 UTC 
Description of problem:

When I run reboot or poweroff on my testing machine, the shutdown process stops at:
...
[  OK  ] Removed slice system-getty.slice.
[  OK  ] Removed slice system-serial\x2dgetty.slice.
         Stopping Permit User Sessions...
[145613.468456] nfsd: last server has exited, flushing export cache
[145613.700794] type=1305 audit(1394178328.633:502): audit_pid=0 old=419 auid=4294967295 ses=4294967295 subj=system_u:system_r:auditd_t:s0 res=1
[145613.703352] type=1130 audit(1394178328.636:503): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg=' comm="auditd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[145613.706213] type=1131 audit(1394178328.639:504): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg=' comm="auditd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[145613.712105] type=1130 audit(1394178328.645:505): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg=' comm="rhel-readonly" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[145613.713940] type=1131 audit(1394178328.646:506): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg=' comm="rhel-readonly" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[145613.720845] type=1130 audit(1394178328.653:507): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg=' comm="systemd-random-seed" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[145613.723413] type=1131 audit(1394178328.656:508): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg=' comm="systemd-random-seed" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[145614.169366] type=1130 audit(1394178329.102:509): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg=' comm="systemd-remount-fs" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[145614.173241] type=1131 audit(1394178329.106:510): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg=' comm="systemd-remount-fs" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'

After that it waits for couple of minutes and it continues with:
Sending SIGTERM to remaining processes...
[145703.441280] systemd-journald[305]: Received SIGTERM
[145703.615091] type=1106 audit(1394178418.548:512): pid=4386 uid=0 auid=0 ses=45 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:session_close acct="root" exe="/usr/sbin/sshd" hostname=ovpn-116-16.ams2.redhat.com addr=10.36.116.16 terminal=ssh res=failed'
[145703.661166] type=1104 audit(1394178418.594:513): pid=4386 uid=0 auid=0 ses=45 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=PAM:setcred acct="root" exe="/usr/sbin/sshd" hostname=ovpn-116-16.ams2.redhat.com addr=10.36.116.16 terminal=ssh res=success'
[145703.664660] type=1106 audit(1394178418.597:514): pid=4386 uid=0 auid=0 ses=45 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=login id=0 exe="/usr/sbin/sshd" hostname=? addr=? terminal=/dev/pts/1 res=success'
[145703.667994] type=1113 audit(1394178418.600:515): pid=4386 uid=0 auid=0 ses=45 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=login id=0 exe="/usr/sbin/sshd" hostname=? addr=? terminal=/dev/pts/1 res=success'
[145703.671173] type=2404 audit(1394178418.604:516): pid=4386 uid=0 auid=0 ses=45 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=destroy kind=server fp=03:97:bb:3e:44:08:3d:95:d2:19:b6:cb:15:09:0b:6e direction=? spid=4386 suid=0  exe="/usr/sbin/sshd" hostname=? addr=10.36.116.16 terminal=? res=success'
[145703.673456] type=2404 audit(1394178418.606:517): pid=4386 uid=0 auid=0 ses=45 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=destroy kind=server fp=4a:a2:ba:1e:96:43:06:54:6d:a7:1c:76:fc:de:48:18 direction=? spid=4386 suid=0  exe="/usr/sbin/sshd" hostname=? addr=10.36.116.16 terminal=? res=success'
[145703.675655] type=2404 audit(1394178418.608:518): pid=4386 uid=0 auid=0 ses=45 subj=unconfined_u:unconfined_r:unconfined_t:s0-s0:c0.c1023 msg='op=destroy kind=session fp=? direction=both spid=4386 suid=0 rport=58233 laddr=10.34.33.210 lport=22  exe="/usr/sbin/sshd" hostname=? addr=10.36.116.16 terminal=? res=success'
Sending SIGKILL to remaining processes...
Unmounting file systems.
Unmounting /proc/fs/nfsd.
Unmounting /var/lib/nfs/rpc_pipefs.
Unmounting /dev/mqueue.
Unmounting /sys/kernel/debug.
Unmounting /dev/hugepages.
Unmounting /sys/kernel/config.

Version-Release number of selected component (if applicable):
systemd-208-8.el7.x86_64
kernel-3.10.0-105.el7.x86_64

How reproducible:
Always on my testing machine

Steps to Reproduce:
1. poweroff

Actual results:
Long wait and "systemd-journald[XXX]: Received SIGTERM" message

Expected results:
No wait, instant poweroff

Additional info:
None
Comment 2 Michal Schmidt 2014-03-07 15:37:54 UTC 
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
Comment 3 Ray Strode [halfline] 2014-03-10 18:39:25 UTC 
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

?
Comment 4 Jiri Pirko 2014-03-10 20:54:26 UTC 
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!
Comment 5 Ray Strode [halfline] 2014-03-10 21:57:24 UTC 
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?
Comment 6 Jiri Pirko 2014-03-11 09:44:39 UTC 
Created attachment 873030 [details]
full-journal-of-last-boot.txt
Comment 7 Ray Strode [halfline] 2014-03-12 06:01:45 UTC 
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.
Comment 8 Jiri Pirko 2014-03-12 08:01:39 UTC 
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.
Comment 9 Ray Strode [halfline] 2014-03-12 13:23:25 UTC 
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.
Comment 10 Jiri Pirko 2014-03-13 11:42:21 UTC 
Created attachment 873935 [details]
full-journal-of-last-boot-with-updated-dracut-image.txt

I ran "dracut -f" and got the log again.
Comment 11 Ray Strode [halfline] 2014-03-13 15:57:30 UTC 
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.
Comment 12 Jiri Pirko 2014-03-13 16:27:39 UTC 
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.
Comment 13 Jiri Pirko 2014-03-13 16:28:34 UTC 
and plymouth-0.8.9-0.10.20140113.el7 works fine to me, without the timeout. Closing this bz. Thanks!
Comment 14 Ray Strode [halfline] 2014-03-13 17:01:26 UTC 
does it work if you take console=ttyS0 off the kernel command line?  if so, that's surprising.
Comment 15 Ray Strode [halfline] 2014-03-13 17:06:26 UTC 
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.
Comment 16 Jiri Pirko 2014-03-14 07:10:56 UTC 
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.
Comment 17 Ray Strode [halfline] 2014-03-14 14:58:48 UTC 
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)
Note You need to log in before you can comment on or make changes to this bug.