Nixpkgs: LightDM logs to /var/log rather than journal

[lheckemann]

Issue description

When using lightdm, the X server log goes to /var/log/X.0.log and /var/log/x-0.log (the former is with timestamps, the latter without) and the display manager log goes to /var/log/lightdm.log. All of this should instead go to the journal. This seems to be hard-coded behaviour in lightdm (X server, lightdm). This makes debugging errors more difficult and inconsistent with other display managers.

Steps to reproduce

Enable and start lightdm.

Technical details

• System: 17.03.1203.58e227052d (Gorilla)
• Nix version: nix-env (Nix) 1.11.8
• Nixpkgs version: "17.03.1203.58e227052d"
• Sandboxing enabled: true

[pbogdan]

There is a --debug flag for lightdm which if I'm reading correctly duplicates all log messages on stderr, with that passed in I get:

$ journalctl -u display-manager
May 29 13:27:59 laptop display-manager[1171]: [+0.00s] DEBUG: Logging to /var/log/lightdm.log
May 29 13:27:59 laptop display-manager[1171]: [+0.00s] DEBUG: Starting Light Display Manager 1.22.0, UID=0 PID=1171
May 29 13:27:59 laptop display-manager[1171]: [+0.00s] DEBUG: Loading configuration dirs from /usr/share/lightdm/lightd
May 29 13:27:59 laptop display-manager[1171]: [+0.00s] DEBUG: Loading configuration dirs from /usr/local/share/lightdm/
May 29 13:27:59 laptop display-manager[1171]: [+0.00s] DEBUG: Loading configuration dirs from /etc/xdg/lightdm/lightdm.
May 29 13:27:59 laptop display-manager[1171]: [+0.00s] DEBUG: Loading configuration from /etc/lightdm/lightdm.conf
May 29 13:27:59 laptop display-manager[1171]: [+0.00s] DEBUG: Registered seat module local
May 29 13:27:59 laptop display-manager[1171]: [+0.00s] DEBUG: Registered seat module xremote
May 29 13:27:59 laptop display-manager[1171]: [+0.00s] DEBUG: Registered seat module unity
May 29 13:27:59 laptop display-manager[1171]: [+0.00s] DEBUG: Using D-Bus name org.freedesktop.DisplayManager
May 29 13:27:59 laptop display-manager[1171]: [+0.01s] DEBUG: Monitoring logind for seats
May 29 13:27:59 laptop display-manager[1171]: [+0.01s] DEBUG: New seat added from logind: seat0
May 29 13:27:59 laptop display-manager[1171]: [+0.01s] DEBUG: Seat seat0: Loading properties from config section Seat:*
May 29 13:27:59 laptop display-manager[1171]: [+0.01s] DEBUG: Seat seat0: Starting
May 29 13:27:59 laptop display-manager[1171]: [+0.01s] DEBUG: Seat seat0: Creating greeter session
May 29 13:27:59 laptop display-manager[1171]: [+0.01s] DEBUG: Seat seat0: Creating display server of type x
May 29 13:27:59 laptop display-manager[1171]: [+0.01s] DEBUG: Could not run plymouth --ping: Failed to execute child pr
May 29 13:27:59 laptop display-manager[1171]: [+0.01s] DEBUG: Using VT 7
May 29 13:27:59 laptop display-manager[1171]: [+0.01s] DEBUG: Seat seat0: Starting local X display on VT 7
May 29 13:27:59 laptop display-manager[1171]: [+0.01s] DEBUG: XServer 0: Logging to /var/log/x-0.log
May 29 13:27:59 laptop display-manager[1171]: [+0.01s] DEBUG: XServer 0: Writing X server authority to /run/root/:0
May 29 13:27:59 laptop display-manager[1171]: [+0.01s] DEBUG: XServer 0: Launching X Server
May 29 13:27:59 laptop display-manager[1171]: [+0.01s] DEBUG: Launching process 1179: /nix/store/f5pmddlpdya382wr3pfafd
May 29 13:27:59 laptop display-manager[1171]: [+0.01s] DEBUG: XServer 0: Waiting for ready signal from X server :0
May 29 13:27:59 laptop display-manager[1171]: [+0.01s] DEBUG: Acquired bus name org.freedesktop.DisplayManager
May 29 13:27:59 laptop display-manager[1171]: [+0.01s] DEBUG: Registering seat with bus path /org/freedesktop/DisplayMa
May 29 13:27:59 laptop display-manager[1171]: [+0.09s] DEBUG: Loading users from org.freedesktop.Accounts
May 29 13:27:59 laptop display-manager[1171]: [+0.10s] DEBUG: User /org/freedesktop/Accounts/User1000 added
May 29 13:27:59 laptop display-manager[1171]: [+0.10s] WARNING: Could not delete unused user data directory /var/lib/li
May 29 13:27:59 laptop display-manager[1171]: [+0.10s] WARNING: Could not delete unused user data directory /var/lib/li
May 29 13:27:59 laptop display-manager[1171]: [+0.11s] WARNING: Could not delete unused user data directory /var/lib/li
May 29 13:27:59 laptop display-manager[1171]: [+0.11s] WARNING: Could not delete unused user data directory /var/lib/li
May 29 13:27:59 laptop display-manager[1171]: [+0.11s] WARNING: Could not delete unused user data directory /var/lib/li
May 29 13:27:59 laptop display-manager[1171]: [+0.11s] WARNING: Could not delete unused user data directory /var/lib/li
May 29 13:27:59 laptop display-manager[1171]: [+0.11s] WARNING: Could not delete unused user data directory /var/lib/li
May 29 13:27:59 laptop display-manager[1171]: [+0.58s] DEBUG: Got signal 10 from process 1179
May 29 13:27:59 laptop display-manager[1171]: [+0.58s] DEBUG: XServer 0: Got signal from X server :0
May 29 13:27:59 laptop display-manager[1171]: [+0.58s] DEBUG: XServer 0: Connecting to XServer :0
May 29 13:27:59 laptop display-manager[1171]: [+0.58s] CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' faile
May 29 13:27:59 laptop display-manager[1171]: [+0.58s] DEBUG: Seat seat0: Display server ready, starting session authen
May 29 13:27:59 laptop display-manager[1171]: [+0.58s] DEBUG: Session pid=1397: Started with service 'lightdm-greeter',
May 29 13:27:59 laptop display-manager[1171]: [+0.60s] DEBUG: Session pid=1397: Authentication complete with return val
May 29 13:27:59 laptop display-manager[1171]: [+0.60s] DEBUG: Seat seat0: Session authenticated, running command
May 29 13:27:59 laptop display-manager[1171]: [+0.60s] DEBUG: Session pid=1397: Running command /nix/store/li3kfdv3yfsp
May 29 13:27:59 laptop display-manager[1171]: [+0.60s] DEBUG: Creating shared data directory /var/lib/lightdm-data/ligh
May 29 13:27:59 laptop display-manager[1171]: [+0.60s] DEBUG: Session pid=1397: Logging to /var/log/seat0-greeter.log
May 29 13:27:59 laptop lightdm[1397]: pam_unix(lightdm-greeter:session): session opened for user lightdm by (uid=0)
May 29 13:28:00 laptop display-manager[1171]: [+0.91s] DEBUG: Activating VT 7
May 29 13:28:00 laptop display-manager[1171]: [+0.91s] DEBUG: Activating login1 session c1
May 29 13:28:00 laptop display-manager[1171]: [+1.08s] DEBUG: Greeter connected version=1.22.0 api=1 resettable=false
May 29 13:28:01 laptop display-manager[1171]: [+1.87s] DEBUG: Greeter start authentication for pbogdan
May 29 13:28:01 laptop display-manager[1171]: [+1.87s] DEBUG: Session pid=1621: Started with service 'lightdm', usernam
May 29 13:28:01 laptop display-manager[1171]: [+1.88s] DEBUG: Session pid=1621: Got 1 message(s) from PAM
May 29 13:28:01 laptop display-manager[1171]: [+1.88s] DEBUG: Prompt greeter with 1 message(s)
May 29 13:28:02 laptop display-manager[1171]: [+3.42s] DEBUG: Continue authentication
May 29 13:28:02 laptop display-manager[1171]: [+3.44s] DEBUG: Session pid=1621: Authentication complete with return val
May 29 13:28:02 laptop display-manager[1171]: [+3.44s] DEBUG: Authenticate result for user pbogdan: Success
May 29 13:28:02 laptop display-manager[1171]: [+3.44s] DEBUG: User pbogdan authorized
May 29 13:28:02 laptop display-manager[1171]: [+3.46s] DEBUG: Greeter sets language en_GB.utf8
May 29 13:28:02 laptop display-manager[1171]: [+3.56s] DEBUG: Greeter requests session none+xmonad
May 29 13:28:02 laptop display-manager[1171]: [+3.56s] DEBUG: Seat seat0: Stopping greeter; display server will be re-u
May 29 13:28:02 laptop display-manager[1171]: [+3.56s] DEBUG: Terminating login1 session c1
May 29 13:28:02 laptop display-manager[1171]: [+3.56s] DEBUG: Session pid=1397: Sending SIGTERM
May 29 13:28:02 laptop display-manager[1171]: [+3.58s] DEBUG: Greeter closed communication channel
May 29 13:28:02 laptop display-manager[1171]: [+3.58s] DEBUG: Session pid=1397: Exited with return value 0
May 29 13:28:02 laptop display-manager[1171]: [+3.58s] DEBUG: Seat seat0: Session stopped
May 29 13:28:02 laptop display-manager[1171]: [+3.58s] DEBUG: Seat seat0: Greeter stopped, running session
May 29 13:28:02 laptop display-manager[1171]: [+3.58s] DEBUG: Registering session with bus path /org/freedesktop/Displa
May 29 13:28:02 laptop display-manager[1171]: [+3.58s] CRITICAL: g_object_unref: assertion 'G_IS_OBJECT (object)' faile
May 29 13:28:02 laptop display-manager[1171]: [+3.58s] DEBUG: Session pid=1621: Running command /nix/store/bywkls5bii13
May 29 13:28:02 laptop display-manager[1171]: [+3.58s] DEBUG: Creating shared data directory /var/lib/lightdm-data/pbog
May 29 13:28:02 laptop display-manager[1171]: [+3.58s] DEBUG: Session pid=1621: Logging to .xsession-errors
May 29 13:28:02 laptop lightdm[1621]: pam_unix(lightdm:session): session opened for user pbogdan by (uid=0)
May 29 13:28:04 laptop display-manager[1171]: [+5.38s] DEBUG: Activating VT 7
May 29 13:28:04 laptop display-manager[1171]: [+5.38s] DEBUG: Activating login1 session 2

I don't however see what can be done about the output of the X server :-(.

[pbogdan]

It ain't pretty but hey it works :smile:

diff --git a/nixos/modules/services/x11/display-managers/lightdm.nix b/nixos/modules/services/x11/display-managers/lightdm.nix
index 256bfb9ce3..57a6de5e3c 100644
--- a/nixos/modules/services/x11/display-managers/lightdm.nix
+++ b/nixos/modules/services/x11/display-managers/lightdm.nix
@@ -19,11 +19,11 @@ let

       display=$(echo "$@" | xargs -n 1 | grep -P ^:\\d\$ | head -n 1 | sed s/^://)
       if [ -z "$display" ]
-      then additionalArgs=":0 -logfile /var/log/X.0.log"
-      else additionalArgs="-logfile /var/log/X.$display.log"
+      then additionalArgs=":0 -logfile /dev/null"
+      else additionalArgs="-logfile /dev/null"
       fi

-      exec ${dmcfg.xserverBin} ${toString dmcfg.xserverArgs} $additionalArgs "$@"
+      exec systemd-cat ${dmcfg.xserverBin} ${toString dmcfg.xserverArgs} $additionalArgs "$@"
     '';

   usersConf = writeText "users.conf"
@@ -195,7 +195,7 @@ in
       # lightdm relaunches itself via just `lightdm`, so needs to be on the PATH
       execCmd = ''
         export PATH=${lightdm}/sbin:$PATH
-        exec ${lightdm}/sbin/lightdm --log-dir=/var/log --run-dir=/run
+        exec ${lightdm}/sbin/lightdm --log-dir=/var/log --run-dir=/run --debug
       '';
     };

$ journalctl -u display-manager
May 29 13:46:50 laptop X[1176]: X.Org X Server 1.19.3
May 29 13:46:50 laptop X[1176]: Release Date: 2017-03-15
May 29 13:46:50 laptop X[1176]: X Protocol Version 11, Revision 0
May 29 13:46:50 laptop X[1176]: Build Operating System: Linux 4.4.45 x86_64
May 29 13:46:50 laptop X[1176]: Current Operating System: Linux laptop 4.11.2 #1-NixOS SMP Sat May 20 12:50:04 UTC 2017 x86_64
May 29 13:46:50 laptop X[1176]: Kernel command line: BOOT_IMAGE=(lvm/vg-nixos--root)/nix/store/m1wqc9rnhkradhqf40z8b747a8b12xgc-linux-4.11.2/bzImage systemConfig=/nix/store/29ws2dpqlp0n2iizknnjqzfm4vrs7nhp-nixos-system-laptop-17.09.git.8f43
May 29 13:46:50 laptop X[1176]: Build Date: 11 May 2017  12:22:22AM
May 29 13:46:50 laptop X[1176]:  
May 29 13:46:50 laptop X[1176]: Current version of pixman: 0.34.0
May 29 13:46:50 laptop X[1176]:         Before reporting problems, check http://wiki.x.org
May 29 13:46:50 laptop X[1176]:         to make sure that you have the latest version.
May 29 13:46:50 laptop X[1176]: Markers: (--) probed, (**) from config file, (==) default setting,
May 29 13:46:50 laptop X[1176]:         (++) from command line, (!!) notice, (II) informational,
May 29 13:46:50 laptop X[1176]:         (WW) warning, (EE) error, (NI) not implemented, (??) unknown.
May 29 13:46:50 laptop X[1176]: (++) Log file: "/dev/null", Time: Mon May 29 13:46:50 2017
May 29 13:46:50 laptop X[1176]: (++) Using config file: "/nix/store/q4l7na13mz5gbplrsyzy607kcb18fa8w-xserver.conf"
May 29 13:46:50 laptop X[1176]: (==) Using config directory: "/etc/X11/xorg.conf.d"
May 29 13:46:50 laptop X[1176]: (==) Using system config directory "/nix/store/1xwbymcx0kcrbcbw32rh7mjphg6qic5x-xorg-server-1.19.3/share/X11/xorg.conf.d"
May 29 13:46:50 laptop X[1176]: (==) ServerLayout "Layout[all]"
May 29 13:46:50 laptop X[1176]: (**) |-->Screen "Screen-intel[0]" (0)
May 29 13:46:50 laptop X[1176]: (**) |   |-->Monitor "<default monitor>"
May 29 13:46:50 laptop X[1176]: (**) |   |-->Device "Device-intel[0]"
May 29 13:46:50 laptop X[1176]: (==) No monitor specified for screen "Screen-intel[0]".
May 29 13:46:50 laptop X[1176]:         Using a default monitor configuration.                                                                                                                                                                 
May 29 13:46:50 laptop X[1176]: (**) Option "DontZap" "on"                                                                                                                                                                                     
May 29 13:46:50 laptop X[1176]: (**) Option "AllowMouseOpenFail" "on"
May 29 13:46:50 laptop X[1176]: (==) Automatically adding devices
May 29 13:46:50 laptop X[1176]: (==) Automatically enabling devices
May 29 13:46:50 laptop X[1176]: (==) Automatically adding GPU devices
May 29 13:46:50 laptop X[1176]: (==) Max clients allowed: 256, resource mask: 0x1fffff

[dezgeg]

Maybe -logfile /dev/stderr works.

[pbogdan]

@dezgeg -logfile /dev/stderr didn't work on its own to capture output of X. With -logfile /dev/null + systemd-cat for X and --debug for lightdm output of both is captured (in the journal that is). Or did I misunderstand what you are saying?

[dezgeg]

Aha, indeed lightdm captures the stderr of the X server for its own purposes. How about -logfile /proc/$$/fd/2 (which should resolve to the bash script's stderr)?

[pbogdan]

Alas..

(EE) Cannot move old log file "/proc/1171/fd/2" to "/proc/1171/fd/2.old"

[pbogdan]

And annoyingly there doesn't seem to be a way to capture the output of the greeter process :/.

[dezgeg]

I guess patching is needed then... Fortunately, I think all that's needed to remove the calls to process_set_log_file().

[pbogdan]

I'm coming to a conclusion that capturing the output of the greeter as part of display-manager may not be possible. While I managed to get its output captured in the journal the greeter runs in a new user session and is no longer considered to be a part of display-manager and I believe there is no way to associate the greeter with it. So it seems that the output of lightdm and X is best that can be done, unless anyone has any other ideas.

[jtojnar]

I opened an issue about this upstream: https://github.com/CanonicalLtd/lightdm/issues/34

[stale[bot]]

Thank you for your contributions.

This has been automatically marked as stale because it has had no activity for 180 days.

If this is still important to you, we ask that you leave a comment below. Your comment can be as simple as "still important to me". This lets people see that at least one person still cares about this. Someone will have to do this at most twice a year if there is no other activity.

Here are suggestions that might help resolve this more quickly:

1. Search for maintainers and people that previously touched the related code and @ mention them in a comment.
2. Ask on the NixOS Discourse.
3. Ask on the #nixos channel on irc.freenode.net.

[lheckemann]

Yes