On Sun, 17 Aug 2014 00:19:48 +0200 Michael Biebl <bi...@debian.org> wrote:
> Am 16.08.2014 23:54, schrieb Joe: > > Aug 16 00:02:03 jresid systemd[2913]: systemd-exit.service: main > > process exited, code=exited, status=200/CHDIR > > Aug 16 00:02:03 jresid systemd[2913]: Failed to start Exit the > > Session. > > Apparently that service failed with exit code 200 / CHDIR. > > src/core/execute.c [1] indicates that this might be due to failing to > change the working directory. > As the home directory for user nobody is set to /nonexistent (which > suprisingly is nonexistent), that might explain the above error. > > It doesn't explain though, why you have processes under user nobody or > why they are not killed on shutdown. > > > [1] > http://sources.debian.net/src/systemd/208-7/src/core/execute.c/?hl=1384#L1384 > No idea why it's happening, but the problem correlates with a pair of PIDs created at start-up, persisting during the session. I assume something went wrong and prevented them from closing down. If they're not present in a PID listing, shutdown is fairly quick. $ loginctl user-status nobody nobody (65534) Since: Tue 2014-08-19 07:59:45 BST; 12h ago State: closing Unit: user-65534.slice └─user@65534.service ├─2593 /lib/systemd/systemd --user └─2594 (sd-pam) Again, this seems to confirm that nobody is invoked to do a particular job and then not logged out for some reason. This seems to be the area, when PID 2593 appears. As all entries show the same time, I assume logs are interleaved and this may not be the actual order of entries. The session on PID 2592 is explicitly closed, successfully, but not 2593. sudo journalctl -b | grep nobody: Aug 19 07:59:45 jresid su[2592]: Successful su for nobody by root Aug 19 07:59:45 jresid su[2592]: + ??? root:nobody Aug 19 07:59:45 jresid su[2592]: pam_unix(su:session): session opened for user nobody by (uid=0) Aug 19 07:59:45 jresid systemd[1]: Starting Session c1 of user nobody. Aug 19 07:59:45 jresid systemd[1]: Started Session c1 of user nobody. Aug 19 07:59:45 jresid systemd-logind[986]: New session c1 of user nobody. Aug 19 07:59:45 jresid systemd[1]: Starting Session c2 of user nobody. Aug 19 07:59:45 jresid systemd[1]: Started Session c2 of user nobody. Aug 19 07:59:45 jresid systemd-logind[986]: New session c2 of user nobody. Aug 19 07:59:45 jresid systemd[1]: Starting Session c3 of user nobody. Aug 19 07:59:45 jresid systemd[1]: Started Session c3 of user nobody. Aug 19 07:59:45 jresid systemd-logind[986]: New session c3 of user nobody. Aug 19 07:59:45 jresid systemd[2593]: pam_unix(systemd-user:session): session opened for user nobody by (uid=0) Aug 19 07:59:45 jresid su[2592]: pam_unix(su:session): session closed for user nobody Aug 19 07:59:45 jresid su[2604]: Successful su for nobody by root Aug 19 07:59:45 jresid su[2604]: + ??? root:nobody Aug 19 07:59:45 jresid su[2604]: pam_unix(su:session): session opened for user nobody by (uid=0) Aug 19 07:59:45 jresid su[2604]: pam_unix(su:session): session closed for user nobody Aug 19 07:59:45 jresid su[2620]: Successful su for nobody by root Aug 19 07:59:45 jresid su[2620]: + ??? root:nobody Aug 19 07:59:45 jresid su[2620]: pam_unix(su:session): session opened for user nobody by (uid=0) Aug 19 08:06:17 jresid su[2620]: pam_unix(su:session): session closed for user nobody sudo journalctl -u user-65534.slice: Aug 19 07:59:45 jresid systemd[1]: Starting user-65534.slice. Aug 19 07:59:45 jresid systemd[1]: Created slice user-65534.slice. Aug 19 07:59:45 jresid systemd[2593]: Failed to open private bus connection: Failed to connect to socket /run/user/65534/d Aug 19 07:59:45 jresid systemd[2593]: Starting Default. Aug 19 07:59:45 jresid systemd[2593]: Reached target Default. Aug 19 07:59:45 jresid systemd[2593]: Startup finished in 16ms. Aug 19 07:59:45 jresid systemd[2593]: pam_unix(systemd-user:session): session opened for user nobody by (uid=0) Aug 19 07:59:45 jresid systemd[2593]: pam_ck_connector(systemd-user:session): cannot determine display-device Aug 19 07:59:45 jresid su[2620]: Successful su for nobody by root Aug 19 07:59:45 jresid su[2620]: + ??? root:nobody Aug 19 07:59:45 jresid su[2620]: pam_unix(su:session): session opened for user nobody by (uid=0) Aug 19 08:06:17 jresid su[2620]: pam_unix(su:session): session closed for user nobody The "Failed to open private bus..." error seems to be significant. On days when this machine is booted more than once, it only appears on the first boot of the day, and the eventual "Dependency failed.." message ties up with those boots. The full message is: Failed to open private bus connection: Failed to connect to socket /run/user/65534/dbus/user_bus_socket: No such file or directory which possibly correlates with the CHDIR error. The current contents of /run/user/65534 is only a systemd directory with nobody:nogroup permissions, which contains =private, which I assume is a socket. ********************************************************* I've rebooted, sure enough there was a 90-second delay, and now neither of the commands: sudo journalctl -b | grep nobody sudo journalctl -u user-65534.slice return anything at all from the new session. user-65534.slice was never created, there is no /run/user/65534. So for some reason, the first boot of the day involves several privilege-drop logins, but no later boots do. Is this about log creation or rotation? I cannot see anything under /var/log with a timestamp at around today's first boot, and I'm certain no log file should be writeable by nobody. This reboot was cold, the machine was actually powered off before it. Are we back to /etc/cron.daily? Again, I can't see cron tasks being run as nobody, they are normally administrative. Any other ideas? Does systemd itself do some kind of daily chores? It seems to be systemd itself which opens the session. -- Joe -- To UNSUBSCRIBE, email to debian-user-requ...@lists.debian.org with a subject of "unsubscribe". Trouble? Contact listmas...@lists.debian.org Archive: https://lists.debian.org/20140819221148.23bb7...@jresid.jretrading.com