Re: Anybody know who user-65534 is?
On Sun, 17 Aug 2014 00:19:48 +0200
Michael Biebl <biebl@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
Reply to: