Bug 939571

Probably again related to systemd-logind.

I tried to downgrade gdm to 3.10, and now it (a kind of) works.  There is a long delay (20-30 seconds) before each login / switch, but gdm login screen reappears at least.

BTW, I've checked the behavior on both KVM and bare metal.

The problem of lightdm looks different.  It's a problem that was seen on FACTORY once, the empty lightdm-default-greeter.desktop.  It seems that something is incompatible regarding update-alternative.  Let's track the lightdm issue in another bug entry.

(In reply to Takashi Iwai from comment #3)
> The problem of lightdm looks different.  It's a problem that was seen on
> FACTORY once, the empty lightdm-default-greeter.desktop.  It seems that
> something is incompatible regarding update-alternative.  Let's track the
> lightdm issue in another bug entry.

lightdm problem is tracked on bug 939693.

The problem with gdm seems appearing only with autologin.  Without autologin, the greeter is shown properly after logout.

This could be a dupe of boo#939594.

Frankly, I don't see how this is a problem of the X Window System. IHMO, this is a gdm issue.

Or yet another Plymouth race.

(In reply to Egbert Eich from comment #6)
> This could be a dupe of boo#939594.
> 
> Frankly, I don't see how this is a problem of the X Window System. IHMO,
> this is a gdm issue.

Yes, we can change the component to GNOME.  I firstly thought it being a generic X and systemd issue because both gdm and lightdm don't work.  But it turned out that the problem of lightdm is its own.  And the gdm problem is its own as well.

Though, a problem with xdm and loginctl still remains.  (Just check loginctl output after login twice via xdm.  You'll see two assigned seats.)
But this can be tracked in another bug.

(In reply to Egbert Eich from comment #7)

plymouth is onyl used at system init

(In reply to Egbert Eich from comment #6)
> This could be a dupe of boo#939594.

Looks so.  FWIW, it happens only with autologin.

Or a DUP of bug 936028

Finally got 42 installed.
My Xserver doesn't start either.

grep systemd-logind /var/log/Xorg.0.log

gives me:

[  1074.204] (II) systemd-logind: took control of session /org/freedesktop/login1/session/_32
[  1074.253] (II) systemd-logind: got fd for /dev/input/event3 13:67 fd 13 paused 1
[  1074.253] (II) systemd-logind: releasing fd for 13:67
[  1074.286] (EE) systemd-logind: failed to release device: Device not taken
[  1074.297] (II) systemd-logind: got fd for /dev/input/event4 13:68 fd 13 paused 1
[  1074.297] (II) systemd-logind: releasing fd for 13:68
[  1074.328] (EE) systemd-logind: failed to release device: Device not taken
[  1074.390] (II) systemd-logind: got fd for /dev/input/event2 13:66 fd 13 paused 1
[  1074.390] (II) systemd-logind: releasing fd for 13:66
[  1074.391] (EE) systemd-logind: failed to release device: Message did not receive a reply (timeout by message bus)
[  1074.433] (II) systemd-logind: got fd for /dev/input/event0 13:64 fd 13 paused 1
[  1074.433] (II) systemd-logind: releasing fd for 13:64
[  1074.433] (EE) systemd-logind: failed to release device: Message did not receive a reply (timeout by message bus)
[  1074.477] (II) systemd-logind: got fd for /dev/input/event1 13:65 fd 13 paused 1
[  1074.477] (II) systemd-logind: releasing fd for 13:65
[  1074.478] (EE) systemd-logind: failed to release device: Message did not receive a reply (timeout by message bus)
[  1074.511] (EE) systemd-logind disappeared (stopped/restarted?)

To me, this looks a bit like this thing is crashing and restarting all the time.
Still investigating...

(In reply to Dominique Leuenberger from comment #11)
> Or a DUP of bug 936028

OK, then this looks like a problem of the latest GNOME.

Actually, I could reproduce the problem on Tumbleweed, too.  A fresh installation of the latest Tumbleweed on  KVM showed the very same buggy behavior.

Also, I tested to install systemd-219 on Leap, and the problem was still present.

Now I checked through gdm package changes, and it seems that the regression was introduced between 3.14.1 and 3.16.0 (o:F/gdm revision 173 and 174).

Created attachment 642197 [details]
strace log of systemd-logind.

My systemd-logind dies with SIGABRT:

open("/dev/input/event3", O_RDWR|O_NOCTTY|O_NONBLOCK|O_CLOEXEC) = 20
ioctl(20, 0x40044591, 0)                = 0
fcntl(20, F_DUPFD_CLOEXEC, 3)           = 21
sendmsg(12, {msg_name(0)=NULL, msg_iov(2)=[{"l\2\1\1\10\0\0\0\30\0\0\0(\0\0\0\5\1u\0\5\0\0\0\6\1s\0\5\0\0\0"..., 56}, {"\0\0\0\0\1\0\0\0", 8}], msg_controllen=20, {cmsg_len=20, cmsg_level=SOL_SOCKET, cmsg_type=SCM_RIGHTS, {21}}, msg_flags=0}, MSG_DONTWAIT|MSG_NOSIGNAL) = 64
close(21)                               = -1 ENODEV (No such device)
sendmsg(3, {msg_name(0)=NULL, msg_iov(4)=[{"PRIORITY=2\nSYSLOG_FACILITY=4\nCOD"..., 138}, {"MESSAGE=", 8}, {"Assertion 'close_nointr(fd) == 0"..., 108}, {"\n", 1}], msg_controllen=0, msg_flags=0}, MSG_NOSIGNAL) = 255
rt_sigprocmask(SIG_UNBLOCK, [ABRT], NULL, 8) = 0
tgkill(2282, 2282, SIGABRT)             = 0
--- SIGABRT {si_signo=SIGABRT, si_code=SI_TKILL, si_pid=2282, si_uid=0} ---
+++ killed by SIGABRT +++

On the Xserver side, this is the corresponding output:
[   530.619] (II) systemd-logind: got fd for /dev/input/event3 13:67 fd 13 paused 1
[   530.620] (II) systemd-logind: releasing fd for 13:67
[   530.621] (EE) systemd-logind: failed to release device: Message did not receive a reply (timeout by message bus)

This is not related to gdm though, it happens when I start the Xserver from a root login at the console.
Everything works when starting the Xserver remotely from an ssh session as root: As systemd-logind isn't involved here, the fallback to normal open/close operations is used.

Takashi, could you please check your Xserver log file (grep for 'systemd-logind')?

(In reply to Egbert Eich from comment #15)

Hmmm ... the message

  "Assertion 'close_nointr(fd) == 0"

belongs to

  close_nointr_nofail()

of src/shared/util.c as this uses the macro

  assert_se()

from src/shared/macro.h (indeed this does write out a log message and call abort())

The question rises why a dup() of fd=20 of "/dev/input/event3" returns
ENODEV if closed?

I can reproduce your problem by a manual start of X.  But gdm issue is a bit different.  The similar log is found in Olaf's bug entry.  (there is no X log but included in journal).

(In reply to Takashi Iwai from comment #18)

Does this also happen with original SLES-12 kernel?  Why it is not possible to close a duplicated file descriptor of an already open descriptor of /dev/input/event3

(In reply to Dr. Werner Fink from comment #19)
> (In reply to Takashi Iwai from comment #18)
> 
> Does this also happen with original SLES-12 kernel?

The gdm problem appears with SLE12 kernel, yes.

>  Why it is not possible
> to close a duplicated file descriptor of an already open descriptor of
> /dev/input/event3

I haven't checked the problem of X manual start with SLE12 kernel yet, though.

(In reply to Takashi Iwai from comment #18)
> I can reproduce your problem by a manual start of X.  But gdm issue is a bit
> different.  The similar log is found in Olaf's bug entry.  (there is no X
> log but included in journal).

To be clear: systemd-logind crash doesn't happen via gdm.  I see it only with the manual start of X.

(In reply to Dr. Werner Fink from comment #19)

Strange ...

 exec 20<>/dev/input/event3
 exec 21>&20
 l /proc/$$/fd
 total 0
 lrwx------ 1 root root 64 Jul 28 17:28 0 -> /dev/ttyS0
 lrwx------ 1 root root 64 Jul 28 17:28 1 -> /dev/ttyS0
 lrwx------ 1 root root 64 Jul 28 17:28 2 -> /dev/ttyS0
 lrwx------ 1 root root 64 Jul 28 17:28 20 -> /dev/input/event3
 lrwx------ 1 root root 64 Jul 28 17:28 21 -> /dev/input/event3
 lrwx------ 1 root root 64 Jul 28 17:28 255 -> /dev/ttyS0
 exec 21>&- 
 ll /proc/$$/fd
 total 0
 lrwx------ 1 root root 64 Jul 28 17:28 0 -> /dev/ttyS0
 lrwx------ 1 root root 64 Jul 28 17:28 1 -> /dev/ttyS0
 lrwx------ 1 root root 64 Jul 28 17:28 2 -> /dev/ttyS0
 lrwx------ 1 root root 64 Jul 28 17:28 20 -> /dev/input/event3
 lrwx------ 1 root root 64 Jul 28 17:28 255 -> /dev/ttyS0

... what does sendmsg() or better the process which receive the message do with the file descriptor 21?

(In reply to Takashi Iwai from comment #21)

Does this mean that this might destroy/disable the device below /dev/input/event3?

I'd like to see a backtrace of this SIGABRT to be able to identify the function where the close_nointr_nofail() function has been called

Could be in pam_sm_open_session() of src/login/pam-module.c:


 if (session_fd >= 0) {
        session_fd = fcntl(session_fd, F_DUPFD_CLOEXEC, 3);
        if (session_fd < 0) {
                pam_syslog(handle, LOG_ERR, "Failed to dup session fd: %m");
                return PAM_SESSION_ERR;
        }

        r = pam_set_data(handle, "systemd.session-fd", INT_TO_PTR(session_fd+1), NULL);
        if (r != PAM_SUCCESS) {
                pam_syslog(handle, LOG_ERR, "Failed to install session fd.");
                close_nointr_nofail(session_fd);
                return r;
        }
 }

(In reply to Dr. Werner Fink from comment #23)
> (In reply to Takashi Iwai from comment #21)
> 
> Does this mean that this might destroy/disable the device below
> /dev/input/event3?

I doubt this. The Xserver dies however when the systemd-logind which has opened a device is gone. The Xserver starts if systemd-logind fails on all instances (or all but the last) as then the fallback is used all the time (or in the latter case systemd-logind isn't killed on a consecutive device open operation).

(In reply to Dr. Werner Fink from comment #24)
> I'd like to see a backtrace of this SIGABRT to be able to identify the
> function where the close_nointr_nofail() function has been called

Will see if I can attack gdb.

This might also happen with latest systemd as here safe_close() is used inpam_sm_open_session() which does similar use abort_se()

(In reply to Egbert Eich from comment #26)
> 
> Will see if I can attach gdb.

It works however the output is pretty useless due to:

# zypper install systemd-logind-debug
[..]
Repository 'openSUSE-Leap-Debug' is invalid.
[repo-debug|http://download.opensuse.org/debug/distribution/leap/42.1/repo/oss/] Valid metadata not found at specified URL

therefore I won't bother to attach it.

Which pam version is used for openSUSE:42? Is this the same version as used for SLES-12?  Maybe the function  pam_set_data() does something strange with the file descriptor.

FWIW, X can't be started manually on Tumbleweed, too.  It hangs at some point.  systemd-logind doesn't abort unlike Leap, though.

On Tumbleweed, gdm is broken, and X manual start is also broken.  Hmm...

The systemcall close() should not return with ENODEV ... IMHO the only valid error codes are EBADF, EIO, and maybe EINTR.

Indeed:

  http://pubs.opengroup.org/onlinepubs/009695399/functions/close.html

 ERRORS

    The close() function shall fail if:
    [EBADF]
        The fildes argument is not a valid file descriptor.
    [EINTR]
        The close() function was interrupted by a signal.
    The close() function may fail if:
    [EIO]
        An I/O error occurred while reading from or writing to the file system.


... IMHO this is a driver bug.  Beside this:  What does happen if close() does
return with ENODEV: is this file descriptor closed or is it leaking now?

Hmm ... wild guess ... in drivers/input/evdev.c I found with  evdev_flush()

        if (!evdev->exist || client->revoked)
                retval = -ENODEV;
        else
                retval = input_flush_device(&evdev->handle, file);

... could it be that close() does trigger flushing the device and the client has no permission anymore for doing that?(!)  Normally close(2) does not trigger a flush but I've no idea how this is handled for this kind of devices?  Maybe the is a pending I/O handler triggered to late.

IMHO this is more a kernel issue. I can work around this in the pam systemd module, nevertheless it is not clear if the file descriptor becomes leaked after the system call close(2) had failed with ENODEV.

(In reply to Dr. Werner Fink from comment #33)
> Hmm ... wild guess ... in drivers/input/evdev.c I found with  evdev_flush()
> 
>         if (!evdev->exist || client->revoked)
>                 retval = -ENODEV;
>         else
>                 retval = input_flush_device(&evdev->handle, file);
> 
> ... could it be that close() does trigger flushing the device and the client
> has no permission anymore for doing that?(!)  Normally close(2) does not
> trigger a flush but I've no idea how this is handled for this kind of
> devices?  Maybe the is a pending I/O handler triggered to late.

A good catch.  The flush is always called at close internally in filp_close(), and this is taken as a return code.  The file itself is closed no matter which error is returned.

(In reply to Dr. Werner Fink from comment #34)
> IMHO this is more a kernel issue. I can work around this in the pam systemd
> module, nevertheless it is not clear if the file descriptor becomes leaked
> after the system call close(2) had failed with ENODEV.

The file is closed no matter flush returns an error, so there should be no leak.  It's just an unexpected return code.  I'll bring the error code problem to upstream, but let's keep working and see whether this is really the culprit of the whole problem.

My guess is that the close() error is rather a red herring.  It brings logind assert on systemd-210.  But the problem persists with systemd-219 on Tumbleweed that doesn't kill logind, too.

Very likely this upstream bug: https://bugzilla.gnome.org/show_bug.cgi?id=749418

(In reply to Dominique Leuenberger from comment #36)
> Very likely this upstream bug:
> https://bugzilla.gnome.org/show_bug.cgi?id=749418

Yep.  I checked gdm git commits and tried a few bisection steps.  The regression was introduced between 3.15.3 and 3.15.90.1.  There have been lots of changes regarding gdm daemon session management (e.g. whether REUSE_VT or NEW_VT), and my bet is that hits the problem.  Further bisection is difficult because of other errors...  (And I guess there are multiple breakages there.)

Let's track that one as GNOME (update triggered) issue.

(In reply to Stefan Dirsch from comment #38)
> Let's track that one as GNOME (update triggered) issue.

Agreed.  Maybe we should open another bug report for the breakage of X manual start?

Just commited a version of systemd-210 to project Base:System:Legacy package systemd on OBS which includes a workaround for the unexpected error code of the close(2) for the input envent device.  This avoids the abort(3) seen in comment #15 and may let systemd-logind running or at least let it die with an other error.  Please test out.

(In reply to Dr. Werner Fink from comment #40)
> Just commited a version of systemd-210 to project Base:System:Legacy package
> systemd on OBS which includes a workaround for the unexpected error code of
> the close(2) for the input envent device.  This avoids the abort(3) seen in
> comment #15 and may let systemd-logind running or at least let it die with
> an other error.  Please test out.

I tried it quickly, and this seems avoiding the crash of logind.  Thanks!

(In reply to Takashi Iwai from comment #41)
> (In reply to Dr. Werner Fink from comment #40)
> > Just commited a version of systemd-210 to project Base:System:Legacy package
> > systemd on OBS which includes a workaround for the unexpected error code of
> > the close(2) for the input envent device.  This avoids the abort(3) seen in
> > comment #15 and may let systemd-logind running or at least let it die with
> > an other error.  Please test out.
> 
> I tried it quickly, and this seems avoiding the crash of logind.  Thanks!

For avoid misunderstanding: this does *not* fix the original gdm problem.
It just works around the sudden death of systemd-logind, but the gdm problem remains.

I've looked into this some more:
The evdev driver returns -ENODEV on close() when access to the device has been revoked. The revocation was done by systemd-logind itself - it happens whenever the session is not 'active'. The session is considered 'active' if there is no seat or the current seat is identical to the session.
Therefore this fix prevents systemd-logind from dying, thus the Xserver is starting when started directly from the text console - however, since any input device is opened thru systemd-logind, it still cannot receive mouse or keyboard input - even if started as root.

(In reply to Egbert Eich from comment #43)

Does this mean that autologin feature of gdm misses the active flag? Is there a special pam module for gdm autologin or is the normal pam module for gdm not used at all for autologin?

/etc/pam.d/gdm-autologin

 #%PAM-1.0
 # GDM PAM configuration for autologin
 auth     required       pam_permit.so
 account  include        common-account
 password include        common-password
 session  required       pam_loginuid.so
 session  include        common-session

man:pam_permit(8)

DESCRIPTION
       pam_permit is a PAM module that always permit access. It does nothing
       else.

       In the case of authentication, the user's name will be set to nobody
       if the application didn't set one. Many applications and PAM modules
       become confused if this name is unknown.

       This module is very dangerous. It should be used with extreme caution.

(In reply to Egbert Eich from comment #43)
> I've looked into this some more:
> The evdev driver returns -ENODEV on close() when access to the device has
> been revoked. The revocation was done by systemd-logind itself - it happens
> whenever the session is not 'active'. The session is considered 'active' if
> there is no seat or the current seat is identical to the session.
> Therefore this fix prevents systemd-logind from dying, thus the Xserver is
> starting when started directly from the text console - however, since any
> input device is opened thru systemd-logind, it still cannot receive mouse or
> keyboard input - even if started as root.

X starts working after the upstream fixes in xorg-x11-server.  It essentially disables logind support when started without -keeptty.

The gdm problem is a bit different, though.  By some reason, the new session isn't started after logout.

As already mentioned, the gdm problem happens by the changes in gdm itself.  I could track that the culprit is between commits db484708396d6a60ecad6534ba49b08f3157bf97 and 35719a79adfb0a47894f1bc304bab665aaefcd49.  But the further bisection is very hard because they bring too many bugs in the series.  (I already had to apply 10 fix patches to get the last good commit actually working!)

Maybe I should check rather gdm 3.17.x development...

(In reply to Takashi Iwai from comment #37)
> (In reply to Dominique Leuenberger from comment #36)
> > Very likely this upstream bug:
> > https://bugzilla.gnome.org/show_bug.cgi?id=749418
> 
> Yep.

... and I guess the upstream bugzilla entry is in a wrong category.  The problem is more likely in gdm, not int gnome-session.  You should add Ray Strode to Cc, as his changes seem triggering the problem.

Dominique, could you update the upstream bugzilla?

This is an autogenerated message for OBS integration:
This bug (939571) was mentioned in
https://build.opensuse.org/request/show/323095 Factory / systemd

Confirmed on build 0142.  I'll look into this tomorrow.

Here is the journal from a no-autologin session, which logs out fine, and an autologin one, which doesn't get back to the login screen.

Created attachment 646453 [details]
gdm-no-autologin.log

Created attachment 646454 [details]
gdm-autologin.log

Created attachment 646575 [details]
Anotated gdm-no-autologin.log

Grep for 'not appear' in this file.

Created attachment 646576 [details]
Annotated gdm-autologin.log

I've updated the attachments of the two logs, with some annotations.

Grep for 'not appear' in gdm-no-autologin.log:

* The no-autologin case switches back to VT-7 after logout, but the autologin case doesn't.

* There are these in gdm-no-autologin after switching back to VT-7, but no corresponding entries in the autologin case:

Sep 07 14:10:54 taquito.chez-mppoy /usr/lib/gdm/gdm-x-session[1393]: (II) systemd-logind: got resume for 226:0
Sep 07 14:10:54 taquito.chez-mppoy /usr/lib/gdm/gdm-x-session[1393]: (II) AIGLX: Resuming AIGLX clients after VT switch
Sep 07 14:10:54 taquito.chez-mppoy /usr/lib/gdm/gdm-x-session[1393]: (II) intel(0): switch to mode 1366x768@60.0 on LVDS1 using pipe 0, position (0, 0), rotation normal, reflection none
Sep 07 14:10:54 taquito.chez-mppoy /usr/lib/gdm/gdm-x-session[1393]: (II) systemd-logind: got resume for 13:69

The only thing that can cause the VT switch not to happen is in gdm/daemon/gdm-session-worker.c:gdm_session_worker_uninitialize_pam():

        if (worker->priv->login_vt != worker->priv->session_vt) {
                jump_to_vt (worker, worker->priv->login_vt);
        }

There is also a bunch of logging from gnome-session in the GsmSystemd domain that does not appear in the autologin case:

 Sep 07 14:10:41 taquito.chez-mppoy gnome-session[1421]: DEBUG(+): GsmSystemd: received logind signal: SessionNew

Created attachment 646579 [details]
Annotated gdm-no-autologin.log

This appears in no-autologin, but not in autologin:

Sep 07 13:36:28 taquito.chez-mppoy gnome-session[1421]: DEBUG(+): Using systemd for session tracking

There isn't the following in the autologin case, either:

Sep 07 14:10:41 taquito.chez-mppoy gnome-session[1421]: DEBUG(+): GsmSystemd: received logind signal: SessionNew

Which makes me think gnome-session isn't acknowledging systemd properly in the autologin case.

Thanks for taking caring of this.

One material that interests you: on autologin, GNOME session appears on VT7.
On no autologin, GNOME session is on VT2 while GDM keeps running on VT7.

Aha, thanks for confirming that.  I did see VT 2 in the log for no-autologin, but didn't confirm it afterwards.

From https://bugzilla.gnome.org/show_bug.cgi?id=749418#c19 :

> there could be two separate issues, but right now gdm doesn't have code 
> written to start a login screen after log out from an autologin session.

So, yeah, there's a problem :) :) :)

Ray Strode has provided a little bunch of patches upstream; I'm putting them into our gdm to see what happens.

Created attachment 647383 [details]
gdm-bnc939571-bgo749418-autologin-logout.patch

This is a backport of the upstream commits that fix this.  These are also in the gnome-3-16 branch upstream.  I'll submit this.

Submitted gdm to openSUSE:Leap:42.1 with id 331106.

openSUSE-RU-2015:1669-1: An update that has 28 recommended fixes can now be installed.

Category: recommended (moderate)
Bug References: 900558,904214,906900,909358,912334,913517,916420,918118,920195,921831,921898,926169,927457,928265,931388,932284,933365,933512,933521,933533,934077,937512,937900,938908,939571,940264,941576,944132
CVE References: 
Sources used:
openSUSE 13.2 (src):    systemd-210-25.19.1, systemd-mini-210-25.19.1

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

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

SUSE-RU-2015:1954-1: An update that has 24 recommended fixes can now be installed.

Category: recommended (moderate)
Bug References: 900558,904214,912334,913517,932284,933521,933533,934901,937512,937900,938908,939571,940264,941576,942946,944132,944799,945282,947212,948705,950510,951265,951663,953241
CVE References: 
Sources used:
SUSE Linux Enterprise Software Development Kit 12 (src):    systemd-210-70.25.1
SUSE Linux Enterprise Server 12 (src):    systemd-210-70.25.1
SUSE Linux Enterprise Desktop 12 (src):    systemd-210-70.25.1

openSUSE-RU-2016:0320-1: An update that has 146 recommended fixes can now be installed.

Category: recommended (moderate)
Bug References: 737690,742774,750845,818044,838475,841544,849870,852015,852021,852232,853293,854884,856389,856392,856858,857204,858864,859072,859365,860574,860937,861316,861489,863217,864745,864904,865834,866732,866933,867128,867663,867664,867840,868019,868230,868439,868931,869142,869603,872929,873432,873444,874665,875502,876587,876694,877021,877674,878525,880438,880732,881125,881559,881942,882393,882714,883565,884271,884403,885232,885288,886211,886599,886852,888178,888215,888612,889297,889357,890977,892096,892162,892300,893797,895087,896664,897799,897801,897803,898233,898240,898432,900558,901481,902240,902901,903009,903963,904214,904517,904828,905550,906709,906900,907318,907393,908476,909358,910643,911347,912030,912334,913517,916420,918118,919095,920195,921831,921898,921920,926169,927250,927457,928265,931388,932284,933365,933512,933521,933533,934077,934901,937512,937900,938908,939571,940264,941576,944132,944799,945282,947212,948458,948555,948705,949574,949683,949739,950510,951265,951663,953241,954336,954781,955635,961576
CVE References: 
Sources used:
openSUSE 13.1 (src):    systemd-210-40.1, systemd-mini-210-40.1