Bug 1140081

I suggest to disable nouveau driver support first via

nouveau.modeset=0

(already needs to be active in initrd of course).

(In reply to Fabian Vogt from comment #0)
> I set SYSTEMD_LOG_LEVEL=debug for logind now, once it happens again (if it
> does at all with that option...) I'll add the debug messages here.

So I guess you haven't managed to reproduce with the debug logs enabled, have you ?

(In reply to Franck Bui from comment #3)
> (In reply to Fabian Vogt from comment #0)
> > I set SYSTEMD_LOG_LEVEL=debug for logind now, once it happens again (if it
> > does at all with that option...) I'll add the debug messages here.
> 
> So I guess you haven't managed to reproduce with the debug logs enabled,
> have you ?

I didn't immediately reboot after configuring the loglevel and disabling nouveau, but waited until it happened again and was forced to reset. That was only two days ago, so now I'm waiting for it to happen again.

It happened again, with nouveau.modeset=0:

Jul 24 13:05:31 linux-e202.suse.de org_kde_powerdevil[1912]: The Wayland connection broke. Did the Wayland compositor die?
Jul 24 13:05:31 linux-e202.suse.de systemd-logind[1241]: Inhibitor PowerDevil (KDE handles power events) pid=1912 uid=1000 mode=block stopped.
Jul 24 13:05:31 linux-e202.suse.de systemd-logind[1241]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/login1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7424 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Jul 24 13:05:31 linux-e202.suse.de kernel: kwin_wayland[1787]: segfault at 7fb14eccb1e0 ip 00007fb154608190 sp 00007fffdd6e1e80 error 4 in libEGL_mesa.so.0.0.0[7fb1545f8000+23000]
Jul 24 13:05:31 linux-e202.suse.de kernel: Code: 00 00 4c 89 e2 48 89 ee 48 89 c7 e8 8a fe ff ff eb ce 0f 1f 84 00 00 00 00 00 55 48 8b 46 68 48 89 d5 48 8b 7a 20 48 8b 40 68 <ff> 50 20 48 89 ef e8 65 0d ff ff b8 01 00 00 00 5d c3 66 66 2e 0f
Jul 24 13:05:31 linux-e202.suse.de systemd-logind[1241]: Inhibitor Bildschirmsperre (Stellt sicher, dass der Bildschirm vor dem Herunterfahren gesperrt wird) pid=1787 uid=1000 mode=delay stopped.
Jul 24 13:05:31 linux-e202.suse.de systemd-logind[1241]: Sent message type=signal sender=n/a destination=n/a path=/org/freedesktop/login1 interface=org.freedesktop.DBus.Properties member=PropertiesChanged cookie=7425 reply_cookie=0 signature=sa{sv}as error-name=n/a error-message=n/a
Jul 24 13:05:32 linux-e202.suse.de dbus-daemon[1197]: [system] Activating via systemd: service name='org.freedesktop.resolve1' unit='dbus-org.freedesktop.resolve1.service' requested by ':1.2' (uid=0 pid=1205 comm="/usr/sbin/NetworkManager --no-daemon ")
Jul 24 13:05:32 linux-e202.suse.de dbus-daemon[1197]: [system] Activation via systemd failed for unit 'dbus-org.freedesktop.resolve1.service': Unit dbus-org.freedesktop.resolve1.service not found.
Jul 24 13:05:32 linux-e202.suse.de systemd-logind[1241]: Got message type=signal sender=:1.0 destination=n/a path=/org/freedesktop/systemd1 interface=org.freedesktop.systemd1.Manager member=UnitRemoved cookie=15623 reply_cookie=0 signature=so error-name=n/a error-message=n/a
Jul 24 13:05:34 linux-e202.suse.de systemd-logind[1241]: Got message type=signal sender=org.freedesktop.DBus destination=n/a path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=NameOwnerChanged cookie=875 reply_cookie=0 signature=sss error-name=n/a error-message=n/a
Jul 24 13:05:34 linux-e202.suse.de systemd-logind[1241]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=RemoveMatch cookie=7426 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Jul 24 13:05:35 linux-e202.suse.de sddm-helper[1723]: [PAM] Closing session
Jul 24 13:05:35 linux-e202.suse.de kernel: traps: ThreadPoolSingl[2756] trap int3 ip:5650f3898797 sp:7f14f9115f60 error:0 in vivaldi-bin[5650f144a000+6c6f000]
Jul 24 13:05:35 linux-e202.suse.de systemd[23050]: run-user-1000-doc.mount: Succeeded.
Jul 24 13:05:35 linux-e202.suse.de systemd[23050]: run-user-1000-gvfs.mount: Succeeded.
Jul 24 13:05:35 linux-e202.suse.de systemd[1726]: run-user-1000-doc.mount: Succeeded.
Jul 24 13:05:35 linux-e202.suse.de systemd[1726]: run-user-1000-gvfs.mount: Succeeded.
Jul 24 13:05:35 linux-e202.suse.de systemd-logind[1241]: Failed to reset keyboard mode, ignoring: Input/output error
Jul 24 13:05:35 linux-e202.suse.de systemd-logind[1241]: Failed to set VT_AUTO mode, ignoring: Input/output error
Jul 24 13:05:35 linux-e202.suse.de systemd-logind[1241]: Failed to restore VT, ignoring: Input/output error
Jul 24 13:05:35 linux-e202.suse.de systemd-logind[1241]: Got message type=method_call sender=:1.1406 destination=org.freedesktop.login1 path=/org/freedesktop/login1 interface=org.freedesktop.login1.Manager member=ReleaseSession cookie=2 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Jul 24 13:05:35 linux-e202.suse.de systemd-logind[1241]: Sent message type=method_call sender=n/a destination=org.freedesktop.DBus path=/org/freedesktop/DBus interface=org.freedesktop.DBus member=GetConnectionUnixUser cookie=7427 reply_cookie=0 signature=s error-name=n/a error-message=n/a
Jul 24 13:05:35 linux-e202.suse.de systemd-logind[1241]: Got message type=method_return sender=org.freedesktop.DBus destination=:1.6 path=n/a interface=n/a member=n/a cookie=876 reply_cookie=7427 signature=u error-name=n/a error-message=n/a
Jul 24 13:05:35 linux-e202.suse.de systemd-logind[1241]: Sent message type=method_return sender=n/a destination=:1.1406 path=n/a interface=n/a member=n/a cookie=7428 reply_cookie=2 signature=n/a error-name=n/a error-message=n/a
Jul 24 13:05:35 linux-e202.suse.de sddm-helper[1723]: pam_unix(sddm:session): session closed for user fabian
Jul 24 13:05:35 linux-e202.suse.de sddm-helper[1723]: [PAM] Ended.

@Fabian, as discussed privately I'll attach a patch that you could try out after making sure that you still reproduce this issue.

Thanks !

Created attachment 821945 [details]
Patch that tries to restore VT twice

(In reply to Franck Bui from comment #9)
> Created attachment 821945 [details]
> Patch that tries to restore VT twice

Added on top of v243 and after triggering some crashes I get "systemd-logind[1587]: FOO: First attempt to restore VT failed, retrying a 2nd time with a fresh handle" and am able to switch VTs.

I can't say for sure that it's a 100% fix, but so far the issue hasn't returned.

Thanks Fabian for the testing. I'll submit the patch to upstream.

However I can't remember why my first attempt [1] to fix this race was about to make logind spawn a process to become the controlling terminal process. The new fix seems much simpler but maybe I'm missing something...

Takashi, could you confirm that there's no need for a process (such as logind) to become the controlling terminal process before restoring VT_AUTO ?

Also, one thing I'm still wondering: if the process that has set VT_PROCESS dies, why doesn't the kernel automatically restore VT_AUTO for the VT ?

Leaving the VT unusable until another "foreign" process restore VT_AUTO doesn't sound the best option.

[1] https://github.com/systemd/systemd/pull/9961

Erm, that's a way old issue I worked on it, so my memory is really vague.  Now reading back the bsc#1101591, too...

IIRC, the switch to the fallback ops happens at disassociate_ctty() function, that is, when the control process exits.  And the race that was seen in the past was where another process (dbus stuff) was a session leader and it exits in a racy way while logind tries to restore it.  So the fix was that logind itself takes the control.

But yeah, just for restoring the VT mode itself, the process doesn't need to be the control process.

The restore to VC_AUTO is handled in reset_vc() which is called only at change_console() and vc_init().  This might be improved by invoking reset_vc() somehow at vt's close op when the control process exits.

But I believe Jiri is the right person to ask this; he is the maintainer of tty layer, after all ;)  Cc'ed.

(In reply to Takashi Iwai from comment #13)
> Erm, that's a way old issue I worked on it, so my memory is really vague. 
> Now reading back the bsc#1101591, too...

yeah sorry, but my question is only about the kernel behavior here that is why it doesn't restore VT_AUTO when the control process (i.e. the one that set VT_PROCESS) dies.

(In reply to Franck Bui from comment #14)
> (In reply to Takashi Iwai from comment #13)
> > Erm, that's a way old issue I worked on it, so my memory is really vague. 
> > Now reading back the bsc#1101591, too...
> 
> yeah sorry, but my question is only about the kernel behavior here that is
> why it doesn't restore VT_AUTO when the control process (i.e. the one that
> set VT_PROCESS) dies.

As far as I read the code, the kernel seems restoring to VT_AUTO not at hangup or close but only at changing the VT.  As mentioned, change_console() has a couple of places checking the presence of the control session and calls reset_vc() accordingly.  But I don't know why it's written so and whether it's the intentional behavior, too.

I finally queued the fix for Factory/TW. It should be available in the next update so I'm closing this bug.

I prefer not backporting the fix to SLE as I'm not enterily sure that it won't cause any regression and since it addresses a corner case, let's wait until someone face it again on the older distros.

Jiri, it would be nice if you could answer the question in comment #12 though.