Why does light-locker keep the screen black after unlock?

Question

A Xubuntu 16.04 fully patched machine with a freshly created user wont let me unlock after using light-locker to lock my screen (regardless if lock was activated manually or via timeout). The screen remains black (but powered) on correct password entry

Killing light-locker from tty1 will reveal the desktop then (and consequently prevents further locking).

Steps attempted:

• enabled/disabled lock in light-locker settings & in power settings (no change)
• used xscreensaver instead of light-locker (works)
• tested if issue is related to suspend or closing lid (it is not)
  • however, after suspend the black screen reveals the This session is locked: You will be redirected to the unlock dialog automatically in a few seconds message - without any redirection taking place
• purged+reinstalled lightdm, light-locker and xubuntu-default-settings
• using loginctl unlock-session has no effect
• systemctl status lightdm only reveals (harmless, expected) messages about kwallet pam module missing
• examined dpkg log for upgrades between "it worked" and "it doesn't work any more" (none suspicious) and booted previous kernel (issue persists)
• Compared behaviour between session-initiated light-locker and manually started one (no difference)
• added user to group nopasswdlogin group (black screen then occurs right after locking, not only after entering password)

What additional steps could prove useful in figuring out how to fix this?

Debugging log:

$ export LC_ALL=C; light-locker --debug & ( sleep 5; echo "## Locking now"; light-locker-command --lock; sleep 10; echo "### 10 seconds have passed - entering password now"; sleep 10; echo "### 10 more seconds have passwd - Killing"; killall light-locker; sleep 5; echo "### Killed now" )  
[1] 23463
[gs_debug_init] gs-debug.c:106 (00:08:32):   Debugging enabled
[main] light-locker.c:142 (00:08:32):    initializing light-locker 1.7.0
[main] light-locker.c:144 (00:08:32):    lock after screensaver 10
[main] light-locker.c:145 (00:08:32):    late locking 0
[main] light-locker.c:146 (00:08:32):    lock on suspend 1
[main] light-locker.c:147 (00:08:32):    lock on lid 0
[main] light-locker.c:148 (00:08:32):    idle hint 1
[query_session_id] gs-listener-dbus.c:2088 (00:08:32):   org.freedesktop.login1.NoSessionForPID raised:
 PID 23463 does not belong to any known session


[init_session_id] gs-listener-dbus.c:2180 (00:08:32):    Got session-id: (null)
[query_sd_session_id] gs-listener-dbus.c:2164 (00:08:32):    Couldn't determine our own sd session id: No such process
[init_session_id] gs-listener-dbus.c:2185 (00:08:32):    Got sd-session-id: (null)
[init_seat_path] gs-listener-dbus.c:2262 (00:08:32):     Got seat: /org/freedesktop/DisplayManager/Seat0
[gs_listener_delay_suspend] gs-listener-dbus.c:449 (00:08:32):   Delay suspend
[gs_listener_x11_acquire] gs-listener-x11.c:172 (00:08:32):  ScreenSaver Registered
[listener_dbus_handle_system_message] gs-listener-dbus.c:1330 (00:08:32):    obj_path=/org/freedesktop/DBus interface=org.freedesktop.DBus method=NameAcquired destination=:1.316
## Locking now
[gs_grab_grab_root] gs-grab-x11.c:647 (00:08:37):    Grabbing the root window
[gs_grab_get_keyboard] gs-grab-x11.c:153 (00:08:37):     Grabbing keyboard widget=E3
[gs_grab_get_mouse] gs-grab-x11.c:213 (00:08:37):    Grabbing mouse widget=E3
[gs_manager_create_windows_for_screen] gs-manager.c:548 (00:08:37):  Creating 1 windows for screen 0
[gs_manager_create_window_for_monitor] gs-manager.c:324 (00:08:37):  Creating window for monitor 0 [0,0] (1600x900)
[update_geometry] gs-window-x11.c:197 (00:08:37):    got geometry for monitor 0: x=0 y=0 w=1600 h=900
[update_geometry] gs-window-x11.c:210 (00:08:37):    using geometry for monitor 0: x=0 y=0 w=1600 h=900
[update_geometry] gs-window-x11.c:197 (00:08:37):    got geometry for monitor 0: x=0 y=0 w=1600 h=900
[update_geometry] gs-window-x11.c:210 (00:08:37):    using geometry for monitor 0: x=0 y=0 w=1600 h=900
[gs_window_move_resize_window] gs-window-x11.c:243 (00:08:37):   Move and/or resize window on monitor 0: x=0 y=0 w=1600 h=900
[update_geometry] gs-window-x11.c:197 (00:08:37):    got geometry for monitor 0: x=0 y=0 w=1600 h=900
[update_geometry] gs-window-x11.c:210 (00:08:37):    using geometry for monitor 0: x=0 y=0 w=1600 h=900
[gs_window_move_resize_window] gs-window-x11.c:243 (00:08:37):   Move and/or resize window on monitor 0: x=0 y=0 w=1600 h=900
[update_geometry] gs-window-x11.c:197 (00:08:37):    got geometry for monitor 0: x=0 y=0 w=1600 h=900
[update_geometry] gs-window-x11.c:210 (00:08:37):    using geometry for monitor 0: x=0 y=0 w=1600 h=900
[gs_window_move_resize_window] gs-window-x11.c:243 (00:08:37):   Move and/or resize window on monitor 0: x=0 y=0 w=1600 h=900
[gs_manager_timed_switch] gs-manager.c:445 (00:08:37):   Start switch to greeter timer
[gs_window_xevent] gs-window-x11.c:369 (00:08:37):   not raising our windows
[window_map_event_cb] gs-manager.c:233 (00:08:37):   Handling window map_event event
[gs_listener_resume_suspend] gs-listener-dbus.c:513 (00:08:37):  Resume suspend: fd=14
[manager_maybe_grab_window] gs-manager.c:204 (00:08:37):     Moving grab to 0x5595f8d5a290
[gs_grab_move_keyboard] gs-grab-x11.c:450 (00:08:37):    Moving keyboard grab from E3 to 3A0000C
[gs_grab_move_keyboard] gs-grab-x11.c:457 (00:08:37):    *** doing X server grab
[gs_grab_release_keyboard] gs-grab-x11.c:279 (00:08:37):     Ungrabbing keyboard
[gs_grab_get_keyboard] gs-grab-x11.c:153 (00:08:37):     Grabbing keyboard widget=3A0000C
[gs_grab_move_keyboard] gs-grab-x11.c:479 (00:08:37):    *** releasing X server grab
[gs_grab_move_mouse] gs-grab-x11.c:395 (00:08:37):   Moving pointer grab from E3 to 3A0000C
[gs_grab_move_mouse] gs-grab-x11.c:402 (00:08:37):   *** doing X server grab
[gs_grab_release_mouse] gs-grab-x11.c:320 (00:08:37):    Ungrabbing pointer
[gs_grab_get_mouse] gs-grab-x11.c:213 (00:08:37):    Grabbing mouse widget=3A0000C
[gs_grab_move_mouse] gs-grab-x11.c:425 (00:08:37):   *** releasing X server grab
[listener_dbus_handle_system_message] gs-listener-dbus.c:1330 (00:08:37):    obj_path=/org/freedesktop/login1 interface=org.freedesktop.DBus.Properties method=PropertiesChanged destination=(null)
[update_geometry] gs-window-x11.c:197 (00:08:37):    got geometry for monitor 0: x=0 y=0 w=1600 h=900
[update_geometry] gs-window-x11.c:210 (00:08:37):    using geometry for monitor 0: x=0 y=0 w=1600 h=900
[gs_window_move_resize_window] gs-window-x11.c:243 (00:08:37):   Move and/or resize window on monitor 0: x=0 y=0 w=1600 h=900
[update_geometry] gs-window-x11.c:197 (00:08:37):    got geometry for monitor 0: x=0 y=0 w=1600 h=900
[update_geometry] gs-window-x11.c:210 (00:08:37):    using geometry for monitor 0: x=0 y=0 w=1600 h=900
[gs_window_move_resize_window] gs-window-x11.c:243 (00:08:37):   Move and/or resize window on monitor 0: x=0 y=0 w=1600 h=900
[gs_listener_send_lock_session] gs-listener-dbus.c:180 (00:08:38):   Send lock session
[listener_dbus_handle_system_message] gs-listener-dbus.c:1330 (00:08:38):    obj_path=(null) interface=(null) method=(null) destination=:1.316
[listener_dbus_handle_system_message] gs-listener-dbus.c:1330 (00:08:39):    obj_path=/org/freedesktop/login1/session/c5 interface=org.freedesktop.DBus.Properties method=PropertiesChanged destination=(null)
[listener_dbus_handle_system_message] gs-listener-dbus.c:1330 (00:08:39):    obj_path=/org/freedesktop/login1/session/c12 interface=org.freedesktop.DBus.Properties method=PropertiesChanged destination=(null)
[listener_dbus_handle_system_message] gs-listener-dbus.c:1330 (00:08:39):    obj_path=/org/freedesktop/login1/seat/seat0 interface=org.freedesktop.DBus.Properties method=PropertiesChanged destination=(null)
process 23463: arguments to dbus_message_new_method_call() were incorrect, assertion "path != NULL" failed in file ../../dbus/dbus-message.c line 1340.
This is normally a bug in some application using the D-Bus library.
[query_session_active] gs-listener-dbus.c:1124 (00:08:39):   Couldn't allocate the dbus message
[listener_dbus_handle_system_message] gs-listener-dbus.c:1361 (00:08:39):    systemd notified ActiveSession 0
[listener_session_switched_cb] gs-monitor.c:298 (00:08:39):  Session switched: 0
[gs_manager_stop_switch] gs-manager.c:456 (00:08:39):    Stop switch to greeter timer
[listener_dbus_handle_system_message] gs-listener-dbus.c:1330 (00:08:39):    obj_path=/org/freedesktop/login1/seat/seat0 interface=org.freedesktop.DBus.Properties method=PropertiesChanged destination=(null)
[listener_dbus_handle_system_message] gs-listener-dbus.c:1330 (00:08:39):    obj_path=/org/freedesktop/login1/session/c12 interface=org.freedesktop.DBus.Properties method=PropertiesChanged destination=(null)
[listener_dbus_handle_system_message] gs-listener-dbus.c:1330 (00:08:39):    obj_path=/org/freedesktop/login1/user/_108 interface=org.freedesktop.DBus.Properties method=PropertiesChanged destination=(null)
[listener_dbus_handle_system_message] gs-listener-dbus.c:1330 (00:08:39):    obj_path=/org/freedesktop/login1/seat/seat0 interface=org.freedesktop.DBus.Properties method=PropertiesChanged destination=(null)
process 23463: arguments to dbus_message_new_method_call() were incorrect, assertion "path != NULL" failed in file ../../dbus/dbus-message.c line 1340.
This is normally a bug in some application using the D-Bus library.
[query_session_active] gs-listener-dbus.c:1124 (00:08:39):   Couldn't allocate the dbus message
[listener_dbus_handle_system_message] gs-listener-dbus.c:1361 (00:08:39):    systemd notified ActiveSession 0
[listener_session_switched_cb] gs-monitor.c:298 (00:08:39):  Session switched: 0
[listener_dbus_handle_system_message] gs-listener-dbus.c:1330 (00:08:39):    obj_path=/org/freedesktop/login1/session/c5 interface=org.freedesktop.login1.Session method=Lock destination=(null)
### 10 seconds have passed - entering password now
[listener_dbus_handle_system_message] gs-listener-dbus.c:1330 (00:08:51):    obj_path=/org/freedesktop/login1/session/c5 interface=org.freedesktop.login1.Session method=Unlock destination=(null)
[listener_dbus_handle_system_message] gs-listener-dbus.c:1330 (00:08:51):    obj_path=/org/freedesktop/login1/session/c13 interface=org.freedesktop.DBus.Properties method=PropertiesChanged destination=(null)
[listener_dbus_handle_system_message] gs-listener-dbus.c:1330 (00:08:51):    obj_path=/org/freedesktop/login1/session/c5 interface=org.freedesktop.DBus.Properties method=PropertiesChanged destination=(null)
[listener_dbus_handle_system_message] gs-listener-dbus.c:1330 (00:08:51):    obj_path=/org/freedesktop/login1/seat/seat0 interface=org.freedesktop.DBus.Properties method=PropertiesChanged destination=(null)
process 23463: arguments to dbus_message_new_method_call() were incorrect, assertion "path != NULL" failed in file ../../dbus/dbus-message.c line 1340.
This is normally a bug in some application using the D-Bus library.
[query_session_active] gs-listener-dbus.c:1124 (00:08:51):   Couldn't allocate the dbus message
[listener_dbus_handle_system_message] gs-listener-dbus.c:1361 (00:08:51):    systemd notified ActiveSession 0
[listener_session_switched_cb] gs-monitor.c:298 (00:08:51):  Session switched: 0
[xroot_filter] gs-listener-x11.c:124 (00:08:52):     ScreenSaver stopped
### 10 more seconds have passwd - Killing
### Killed now

Diffing this to a known-good system yields:

$ comm -3 <(grep -iv grab good | sed 's/[0-9:]\+/[NN]/g;s/[ \t]\+/ /g' | sort) <(grep -iv grab bad | sed 's/[0-9:]\+/[NN]/g;s/[ \t]\+/ /g' | sort) | head -n2
[init_session_id] gs-listener-dbus.c[NN] ([NN])[NN] Got session-id[NN] (null)
[init_session_id] gs-listener-dbus.c[NN] ([NN])[NN] Got session-id[NN] /org/freedesktop/login[NN]/session/c[NN]

And indeed, something appears to be very awkward about session setup:

$ loginctl session-status
Could not get properties: No such process

Solution

TL;DR: light-locker keeps the screen black if systemd cannot read /proc

• light-locker depends on dbus providing IPC.
• dbus depends on systemd-logind providing session information.
• systemd-logind depends on /proc providing process information.

Meaning this will not work very well together:

$ file /sbin/init
/sbin/init: symbolic link to /lib/systemd/systemd
$ mount | grep proc
proc on /proc type proc (rw,nosuid,nodev,noexec,relatime,hidepid=2,gid=1337)

And neither can be expected to:

hidepid isn't really compatible with systemd. sorry. [..] Anyway, closing as this was not caused by systemd. -- Lennart Poettering

Partial Solution 1

Partial solution, because it comes with information disclosure.

Allow unprivileged programs (such as systemd, after dropping privileges) to access other users process info in /proc.

$ sudo mount -o remount,hidepid=0 /proc
 # and fix /etc/fstab accordingly

Partial Solution 2

Partial solution, because systemd might break in other places, not just logind.

Add systemd-logind to the appropriate group, most conveniently achieved by adding a service Drop-In.

$ addgroup showpid
$ adduser myuser showpid
$ sudo mount -o remount,hidepid=2,gid=showpid /proc
 # and fix /etc/fstab accordingly
$ echo -e '[Service]\nSupplementaryGroups=showpid' | sudo tee /etc/systemd/system/systemd-logind.service.d/10-showpid.conf
$ sudo systemctl daemon-reload
$ sudo systemctl restart systemd-logind

After either solution, the Got session-id: (null) message should look more like Got session-id: /org/freedesktop/login1/c7 and light-locker will be able to communicate properly via dbus.

---

What should i have done do figure this out way faster?

• If something changed, and you cannot quickly figure out what changed, just grab the backup already and diff -ruiN the whole system.
• Document the first time an issue occured more precisely, so sorting logfiles/IDS reports by time will quickly reveal the relevant cause.
• File more bug reports. Applications silently failing under conditions that will later cause headache and/or system lockup is unacceptable.

Comments

[Fabby]

Hah! You'll find that the only solution is mine and that is to use xscreensaver and delete light-locker

[Elder Geek]

Have you by any chance attempted to launch light-locker utilizing the debug option mentioned in the man page? manpages.ubuntu.com/manpages/xenial/man1/light-locker.1.html

[Fabby]

@anx your bounty will be lost in 5 hours... want me to write a repeat of my original answer? It's not what you want, but I had the same problem at the time, lost many hours and just went to xscreensaver (and had fun with it)

[Fabby]

well, you've got 15 of your bounty already back! Your answer is better than mine, so is your question, so upvoted both!

[jarno]

So did you file some bug report(s) about this?