Bug 681167

Created attachment 481588 [details]
rpm -qa output

Looks like bug 663380. Should be fixed in systemd-19. Can you retest with that version? Get it from Koji if you don't see it in updates-testing yet.

I was randomly seeing this on some kvm guests with serial console enabled.  I couldn't figure out the pattern why some guests exhibit the problem, while others didn't.  I'll be sure to test the updated systemd-19-1.fc15 (https://admin.fedoraproject.org/updates/systemd-19-1.fc15).

Adding CommonBugs so we ensure this gets documented for the Alpha

No, systemd-19-1.fc15 doesn't fix the problem, still the same problem. Also, if I boot without console=ttyS0, the login credentials are echoed (the password is in cleartext). IIRC there was some bugreport about this already.

Kamil, can you paste the output of the following command when this haoppens on systemd 19?

systemctl show plymouth-quit-wait.service

Kamil, are you using Plymouth? or are you using rd_NO_PLYMOUTH on the kernel cmdline? Or maybe you removed rhgb or quiet from the cmdline?

(In reply to comment #5)
> Kamil, can you paste the output of the following command when this haoppens on
> systemd 19?
> 
> systemctl show plymouth-quit-wait.service

"This happens" meaning "login over serial device fails"? This is the output then:

$ systemctl show plymouth-quit-wait.service

Id=plymouth-quit-wait.service
Names=plymouth-quit-wait.service
Requires=basic.target
WantedBy=multi-user.target
Conflicts=shutdown.target
Before=shutdown.target multi-user.target serial-getty getty getty getty getty getty getty
After=rc-local.service plymouth-start.service basic.target
Description=Wait for Plymouth Boot Screen to Quit
LoadState=loaded
ActiveState=inactive
SubState=dead
FragmentPath=/lib/systemd/system/plymouth-quit-wait.service
InactiveExitTimestamp=Tue, 01 Mar 2011 10:31:23 -0500
InactiveEnterTimestamp=Tue, 01 Mar 2011 10:31:23 -0500
CanStart=yes
CanStop=yes
CanReload=no
CanIsolate=no
StopWhenUnneeded=no
RefuseManualStart=no
RefuseManualStop=no
AllowIsolate=no
DefaultDependencies=yes
DefaultControlGroup=name=systemd:/system/plymouth-quit-wait.service
ControlGroup=cpu:/system/plymouth-quit-wait.service name=systemd:/system/plymouth-quit-wait.service
NeedDaemonReload=no
JobTimeoutUSec=0
Type=oneshot
Restart=no
NotifyAccess=none
RestartUSec=100ms
TimeoutUSec=20s
ExecStart={ path=/bin/plymouth ; argv[]=/bin/plymouth --wait ; ignore=yes ; start_time=[n/a] ; stop_time=[Tue, 01 Mar 2011 10:31:23 -0500] ; pid=632 ; code=exited ; status=0 }
UMask=0002
LimitCPU=4294967295
LimitFSIZE=4294967295
LimitDATA=4294967295
LimitSTACK=4294967295
LimitCORE=4294967295
LimitRSS=4294967295
LimitNOFILE=1024
LimitAS=4294967295
LimitNPROC=7921
LimitMEMLOCK=65536
LimitLOCKS=4294967295
LimitSIGPENDING=7921
LimitMSGQUEUE=819200
LimitNICE=0
LimitRTPRIO=0
LimitRTTIME=4294967295
OOMScoreAdjust=0
Nice=0
IOScheduling=0
CPUSchedulingPolicy=0
CPUSchedulingPriority=0
TimerSlackNSec=50000
CPUSchedulingResetOnFork=no
NonBlocking=no
StandardInput=null
StandardOutput=inherit
StandardError=inherit
SyslogPriority=30
SyslogLevelPrefix=yes
SecureBits=0
CapabilityBoundingSetDrop=0
MountFlags=1048576
PrivateTmp=no
SameProcessGroup=no
KillMode=control-group
KillSignal=15
PermissionsStartOnly=no
RootDirectoryStartOnly=no
RemainAfterExit=no
GuessMainPID=yes
ExecMainPID=632
ExecMainCode=1
ExecMainStatus=0
MainPID=0
ControlPID=0
SysVStartPriority=-1
FsckPassNo=0


(In reply to comment #6)
> Kamil, are you using Plymouth? or are you using rd_NO_PLYMOUTH on the kernel
> cmdline? Or maybe you removed rhgb or quiet from the cmdline?

plymouth is installed. "rhgb" nor "quiet" nor "rd_NO_PLYMOUTH" are present on the kernel cmdline. When I remove "console=ttyS0" from kernel cmdline, I don't see plymouth graphics, I see standard kernel boot output.

Hmm, if you add "rhgb quiet", does the problem go away?

(In reply to comment #8)
> Hmm, if you add "rhgb quiet", does the problem go away?

In my testing 

Adding "rhgb quiet" to the boot arguments allows me to proceed and login on the serial console (ttyS0).  

# cat /proc/cmdline 
ro root=/dev/mapper/vg_test189-lv_root rd_LVM_LV=vg_test189/lv_root rd_LVM_LV=vg_test189/lv_swap rd_NO_LUKS rd_NO_MD rd_NO_DM LANG=en_US.UTF-8 SYSFONT=latarcyrheb-sun16 KEYTABLE=us console=ttyS0 rhgb quiet

While booting without "rhgb quiet" (which is the default), I'm not able to login.

ro root=/dev/mapper/vg_test189-lv_root rd_LVM_LV=vg_test189/lv_root rd_LVM_LV=vg_test189/lv_swap rd_NO_LUKS rd_NO_MD rd_NO_DM LANG=en_US.UTF-8 SYSFONT=latarcyrheb-sun16 KEYTABLE=us console=ttyS0

Hmm, so we do call "plymouth --wait" and synchronize properly to it, but somehow the tty is still locked by plymouth when the getty's open it. There's something wrong here, possibly that "plymouth --wait" doesn't correctly synchronously wait for the ply exit when "rhgb" is not passed.

(In reply to comment #8)
> Hmm, if you add "rhgb quiet", does the problem go away?

I just successfully logged in without "rhgb quiet" ... so I guess my test results differ :(

# cat /proc/cmdline 
ro root=/dev/mapper/vg_test189-lv_root rd_LVM_LV=vg_test189/lv_root rd_LVM_LV=vg_test189/lv_swap rd_NO_LUKS rd_NO_MD rd_NO_DM LANG=en_US.UTF-8 SYSFONT=latarcyrheb-sun16 KEYTABLE=us console=ttyS0

Which plymouth version is this?

Hmm, if you do "dracut -f" and reboot, does this fix the issue?

the fact that sometimes things work and sometimes they don't suggests this is a race.

/var/log/plymouth-debug.log with plymouth.debug on kernel command line would be useful as well.

(In reply to comment #12)
> Which plymouth version is this?

 * plymouth-0.8.4-0.20110209.2.fc15.x86_64
 * kernel-2.6.38-0.rc5.git1.1.fc15.x86_64
 * systemd-17-5.fc15.x86_64

(In reply to comment #13)
> Hmm, if you do "dracut -f" and reboot, does this fix the issue?

After running $(dracut -f), I repeated the following test at least 15 times.

 1. Boot system
 2. Attempt to login from ttyS0 as root (with valid password), then logout
 3. Attempt to login from ttyS0 as root (with *invalid* password)
 4. Attempt to login again from ttyS0 as root (with valid password)
 5. Shutdown system

I'm still trying to figure out the failure case.  Sometimes the test passes, sometimes it fails.  It doesn't seem like the `dracut -f` made a difference.  Your impression about timing/race seems likely.

I next updated my system to the following packages, and repeated the tests.  

 * kernel-2.6.38-0.rc6.git6.1.fc15.x86_64
 * systemd-19-1.fc15.x86_64
 * plymouth-0.8.4-0.20110209.2.fc15.x86_64

The test results with the updated packages were not noticeably different.

Will try to reproduce the failure with 'plymouth.debug' enabled ...

Can you upgrade to plymouth-0.8.4-0.20110419.1 and see if that makes a difference? (get it from koji) You need to run "dracut -f" after upgrading to make sure it is properly copied into the initrd.

(In reply to comment #16)
> Can you upgrade to plymouth-0.8.4-0.20110419.1 and see if that makes a
> difference? (get it from koji) You need to run "dracut -f" after upgrading to
> make sure it is properly copied into the initrd.

I installed plymouth-0.8.4-0.20110419.1.fc16 (http://koji.fedoraproject.org/koji/buildinfo?buildID=229463) and rebuilt the initrd (using `dracut -f`).  Following the test procedure outlined in comment#15 ... I *still* see the problem.

Created attachment 481748 [details]
/var/log/boot.log

At Ray's request, and for completeness, I am attaching /var/log/boot.log from a failed login attempt.  After encountering the failure, I gracefully shutdown the system, and accessed /var/log/boot.log from rescue-mode.

Hmm, given that the boot.log ends where it ends we at least know that the gettys are indeed started only after plymouth has exited. So I am really tempted to claim that ply is at fault here, not systemd...

That said, James, Ray was actually asking for /var/log/plymouth-debug.log. Can you attach that too please?

Created attachment 481855 [details]
plymouth-debug.log

(In reply to comment #8)
> Hmm, if you add "rhgb quiet", does the problem go away?

No. (But it stopped echoing the password on tty1.)

(In reply to comment #13)
> Hmm, if you do "dracut -f" and reboot, does this fix the issue?

No.
 
(In reply to comment #12)
> Which plymouth version is this?

plymouth-scripts-0.8.4-0.20110209.2.fc15.i686
plymouth-0.8.4-0.20110209.2.fc15.i686
plymouth-core-libs-0.8.4-0.20110209.2.fc15.i686

(In reply to comment #14)
> /var/log/plymouth-debug.log with plymouth.debug on kernel command line would be
> useful as well.

Attached.

There we are:

[ply-terminal.c]               ply_terminal_set_buffered_input:couldn't unlock terminal settings: Bad file descriptor

Reassigning to Plymouth, as Plymouth apparently doesn't unlock the TTY settings properly.

*** Bug 678720 has been marked as a duplicate of this bug. ***

(In reply to comment #19)
> That said, James, Ray was actually asking for /var/log/plymouth-debug.log. Can
> you attach that too please?

Sorry, I discussed with Ray on IRC that I haven't managed to reproduce the failure with plymouth.debug enabled.  Thankfully, Kamil managed to.

Hmm, but then again Kamil didn't use plymouth-0.8.4-0.20110419.1.fc16 to reproduce this issue.

Kamil, any chance you can try to reproduce the issue with a newer plymouth (steal it from koji) and attach the plymouth debug log for us?

Created attachment 481878 [details]
plymouth-debug.log (plymouth-0.8.4-0.20110419.1.fc16)

Here you go.

The first time I booted after upgrade the system froze just before starting gettys (it happened a few times before already). It is probably a non-relevant bug. But some of that may be left in the logs, so just mentioning.

The second time I booted everything went as expected (login failed over ttyS0), log is attached.

So this looks like it may be a problem that Lennart coincidentally warned me about recently.

In the log there is this:

[ply-terminal.c]                           on_tty_disconnected:tty disconnected (fd 9)
[ply-terminal.c]                           on_tty_disconnected:trying to reopen terminal '/dev/ttyS0'
[ply-terminal.c]                      ply_terminal_open_device:Unable to open terminal device '/dev/ttyS0': Input/output error

The kernel now returns EIO in some cases to mean "try again"

See

https://bugs.launchpad.net/ubuntu/+source/linux/+bug/554172/comments/245

for more details.  I'll try post update packages soon to retry on EIO.

Regarding relationship of bug #678720, I'll paste the symptoms of that here so we can remember to test it when we get a fix for this.  I've tested with the following versions:

Rawhide i686 VM (kvm setup by virt-manager)
systemd-19-1.fc15.i686
plymouth-0.8.4-0.20110419.1.jlaskatest.fc16.i686

Note that I've discovered that setting plymouth.debug in grub.conf makes those symptoms go away.

= adamw's reproducer =

So, here's the ins and outs. This happens when you manage to get boot messages
displayed. There's a few ways to achieve this.

You can boot and hit 'esc' during boot, but *only* if you have the 'fixed'
systemd - systemd-18-1 . This systemd is not in the Alpha at present. You can
get this systemd, though, if you install Alpha and enable the updates-testing
repo, and that's the *default* configuration for a net install (which I think
may be a bug too).

You can also hit this with any version of systemd by booting with 'rhgb quiet'
parameters removed. That will cause you to get system messages spewed to
console, and hit this bug if you try to log in at the console.

So, to review - you don't hit this at all if you don't interact with boot at
all. You hit it just by pressing 'esc' during boot if you have the updated
systemd. You hit it by dropping 'rhgb quiet' from boot parameters with any
systemd.

= symptoms description =

When logging in, the username and password are echoed to the screen like this:
"""
Username: badger
badger
Password: fake_password_that's_displayed

Last Login: Wed Mar  2
"""

After logging in, the console is in a bad state.  tab and arrow keys are not expanded by the shell (the shell apparently gets the proper input but it doesn't display the right thing on the screen.)  vim and less don't display the buffer correctly, commands are echoed to the top line of the screen.  Control-L doesn't redraw the screen.

Discussed at the go/no-go meeting of 2011-03-02. We agreed this shouldn't be a blocker - there's no criterion for serial installs (any more) and we agree this is fine, we don't care about them certainly at Alpha. The test priority in the install matrix should be changed.

plymouth-0.8.4-0.20110304.1.fc15 has been submitted as an update for Fedora 15.
https://admin.fedoraproject.org/updates/plymouth-0.8.4-0.20110304.1.fc15

plymouth-0.8.4-0.20110304.1.fc15 has been pushed to the Fedora 15 testing repository.  If problems still persist, please make note of it in this bug report.
 If you want to test the update, you can install it with 
 su -c 'yum --enablerepo=updates-testing update plymouth'.  You can provide feedback for this update here: https://admin.fedoraproject.org/updates/plymouth-0.8.4-0.20110304.1.fc15

The update does not fix the symptoms I reported in comment 27.  Kamil, does  this update fix your problems?

Toshio, did you run "dracut -f" after updating the plymouth package? I was able to reproduce the bug (as in the original description by Kamil) before doing that, but not afterwards.
Maybe your issue has a different cause after all.

(In reply to comment #31)
> The update does not fix the symptoms I reported in comment 27.  Kamil, does 
> this update fix your problems?

Yes, it does fix this problem. (First I updated only plymouth and the problem remained, but after updating plymouth* it finally worked).

(In reply to comment #33)
> Yes, it does fix this problem. (First I updated only plymouth and the problem
> remained, but after updating plymouth* it finally worked).

Thanks Kamil!  I had also only updated plymouth.  With an update of plymouth-scripts and plymouth-core-libs as well, my symptoms are gone as well.  Thanks Ray!

plymouth-0.8.4-0.20110304.1.fc15 has been pushed to the Fedora 15 stable repository.  If problems still persist, please make note of it in this bug report.