Anybody know who user-65534 is?

568 views
Skip to first unread message

Joe

unread,
Aug 15, 2014, 2:40:01 PM8/15/14
to

Apart from 'nobody', according to /etc/passwd. He seems to login most
sessions, and when he does, he causes the dreaded two-minute shutdown.

Here's what I can find in journalctl:

>sudo journalctl | grep user-65534

Aug 06 07:56:20 jresid systemd[1]: Starting user-65534.slice.
Aug 06 07:56:20 jresid systemd[1]: Created slice user-65534.slice.
Aug 06 20:05:54 jresid systemd[1]: Stopping user-65534.slice.
Aug 06 20:05:54 jresid systemd[1]: Removed slice user-65534.slice.
Aug 07 07:58:40 jresid systemd[1]: Starting user-65534.slice.
Aug 07 07:58:40 jresid systemd[1]: Created slice user-65534.slice.
Aug 07 20:57:31 jresid systemd[1]: Stopping user-65534.slice.
Aug 07 20:57:31 jresid systemd[1]: Removed slice user-65534.slice.
Aug 11 08:27:34 jresid systemd[1]: Starting user-65534.slice.
Aug 11 08:27:34 jresid systemd[1]: Created slice user-65534.slice.
Aug 11 09:10:25 jresid systemd[1]: Stopping user-65534.slice.
Aug 11 09:10:25 jresid systemd[1]: Removed slice user-65534.slice.
Aug 12 08:32:09 jresid systemd[1]: Starting user-65534.slice.
Aug 12 08:32:09 jresid systemd[1]: Created slice user-65534.slice.
Aug 12 22:17:40 jresid systemd[1]: Stopping user-65534.slice.
Aug 12 22:17:40 jresid systemd[1]: Removed slice user-65534.slice.
Aug 13 15:16:24 jresid systemd[1]: Starting user-65534.slice.
Aug 13 15:16:24 jresid systemd[1]: Created slice user-65534.slice.
Aug 13 21:51:37 jresid systemd[1]: Stopping user-65534.slice.
Aug 13 21:51:37 jresid systemd[1]: Removed slice user-65534.slice.
Aug 14 08:23:02 jresid systemd[1]: Starting user-65534.slice.
Aug 14 08:23:02 jresid systemd[1]: Created slice user-65534.slice.
Aug 14 20:39:35 jresid systemd[1]: Stopping user-65534.slice.
Aug 14 20:39:35 jresid systemd[1]: Removed slice user-65534.slice.
Aug 15 07:09:41 jresid systemd[1]: Starting user-65534.slice.
Aug 15 07:09:41 jresid systemd[1]: Created slice user-65534.slice.
Aug 15 07:27:28 jresid systemd[1]: Stopping user-65534.slice.
Aug 15 07:27:28 jresid systemd[1]: Removed slice user-65534.slice.

>sudo journalctl | grep user@65534

Aug 06 20:05:54 jresid systemd[1]: us...@65534.service stopping timed
out. Killing.
Aug 06 20:05:54 jresid systemd[1]: Unit us...@65534.service entered
failed state.
Aug 07 20:57:31 jresid systemd[1]: us...@65534.service stopping timed
out. Killing.
Aug 07 20:57:31 jresid systemd[1]: Unit us...@65534.service entered
failed state.
Aug 11 09:10:25 jresid systemd[1]: us...@65534.service stopping timed
out. Killing.
Aug 11 09:10:25 jresid systemd[1]: Unit us...@65534.service entered
failed state.
Aug 12 22:17:40 jresid systemd[1]: us...@65534.service stopping timed
out. Killing.
Aug 12 22:17:40 jresid systemd[1]: Unit us...@65534.service entered
failed state.
Aug 13 21:51:37 jresid systemd[1]: us...@65534.service stopping timed
out. Killing.
Aug 13 21:51:37 jresid systemd[1]: Unit us...@65534.service entered
failed state.
Aug 14 20:39:35 jresid systemd[1]: us...@65534.service stopping timed
out. Killing.
Aug 14 20:39:35 jresid systemd[1]: Unit us...@65534.service entered
failed state.
Aug 15 07:27:28 jresid systemd[1]: us...@65534.service stopping timed
out. Killing.
Aug 15 07:27:28 jresid systemd[1]: Unit us...@65534.service entered
failed state.

The machine runs every day, so user-65534 skived off on the 8th, 9th
and 10th, and the shutdown was no slower than before systemd. I could
find no obvious service start failures on those days, though the boot
logs were missing on two of them (but not the third).

This is on a newly cloned (--set-selections) sid. The old system also
has a two minute shutdown, but I've no idea if it's the same thing, as
the journal hasn't been persistent since August 3rd, though it was
before that. I can find no explanation, and of course, no journald
logs. The live journals appear in /var/log/journal, but disappear
softly and silently on shutdown. As far as I can see, configuration is
default on both systems, and permissions are the same. Both are fully
updated to yesterday.

Any ideas?

--
Joe


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/20140815193...@jresid.jretrading.com

Michael Biebl

unread,
Aug 15, 2014, 3:30:02 PM8/15/14
to
Those might be cron jobs which start a new PAM session.

Could you check the dates when cron is running?


--
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

signature.asc

Joe

unread,
Aug 15, 2014, 4:40:01 PM8/15/14
to
On Fri, 15 Aug 2014 21:24:38 +0200
Michael Biebl <bi...@debian.org> wrote:

> Am 15.08.2014 20:34, schrieb Joe:
> >
> > Apart from 'nobody', according to /etc/passwd. He seems to login
> > most sessions, and when he does, he causes the dreaded two-minute
> > shutdown.
> >
> > Here's what I can find in journalctl:
> >
> >> sudo journalctl | grep user-65534
> >
> > Aug 06 07:56:20 jresid systemd[1]: Starting user-65534.slice.
> > Aug 06 07:56:20 jresid systemd[1]: Created slice user-65534.slice.
> > Aug 06 20:05:54 jresid systemd[1]: Stopping user-65534.slice.
> > Aug 06 20:05:54 jresid systemd[1]: Removed slice user-65534.slice.

<snip>>


> Those might be cron jobs which start a new PAM session.
>
> Could you check the dates when cron is running?
>
>
There are no custom cron jobs, it's all defaults. This doesn't fit
weekly + monthly, and nearly everything is daily.

Ah, a bit further. I've become dependent on the journald logs very
quickly... looking further afield, I've found this in daemon.log:

Aug 12 08:32:09 jresid systemd[1]: Starting user-65534.slice.
Aug 12 08:32:09 jresid systemd[1]: Created slice user-65534.slice.
Aug 12 08:32:09 jresid systemd[1]: Starting User Manager for 65534...
Aug 12 08:32:09 jresid systemd[1]: Starting Session c1 of user nobody.
Aug 12 08:32:09 jresid systemd[1]: Started Session c1 of user nobody.
Aug 12 08:32:09 jresid systemd[2582]: Failed to open private bus
connection: Failed to connect to socket /run/user/65534/dbus/user_bus_socket: No such file or directory
Aug 12 08:32:09 jresid systemd[2582]: Starting Default.
Aug 12 08:32:09 jresid systemd[2582]: Reached target Default.
Aug 12 08:32:09 jresid systemd[2582]: Startup finished in 16ms.
Aug 12 08:32:09 jresid systemd[1]: Started User Manager for 65534.
Aug 12 08:32:09 jresid systemd[1]: Starting Session c2 of user nobody.
Aug 12 08:32:09 jresid systemd[1]: Started Session c2 of user nobody.
Aug 12 08:32:09 jresid systemd[1]: Starting Session c3 of user nobody.
Aug 12 08:32:09 jresid systemd[1]: Started Session c3 of user nobody.
Aug 12 08:32:09 jresid console-kit-daemon[2103]: GLib-CRITICAL: Source
ID 27 was not found when attempting to remove it
Aug 12 08:32:09 jresid console-kit-daemon[2103]: GLib-CRITICAL: Source
ID 42 was not found when attempting to remove it
Aug 12 08:32:09 jresid console-kit-daemon[2103]:
console-kit-daemon[2103]: GLib-CRITICAL: Source ID 27 was not found when attempting to remove it
Aug 12 08:32:09 jresid console-kit-daemon[2103]:
console-kit-daemon[2103]: GLib-CRITICAL: Source ID 42 was not found
when attempting to remove it

I take it the 'c' in the session number is connected to 'console', and
the two failed attempts are the reason for a shutdown problem. The
trouble is, the Glib error seems fairly generic, and nobody seems to
have seen exactly what I'm seeing. There is a Ubuntu bug, but it
doesn't look relevant here. The 'failed to open private bus' happens
with my user as well, and doesn't seem to stop my session working.

No, a red herring here, daemon.log has the same entries for the 'good'
days, when journalctl wasn't showing me any 65534 entries at all. I can
see entries in daemon.log which should have turned up in my grep of
journalctl and didn't.

This is a can of worms, and I hereby abandon it. This is sid, I'll just
put up with the shutdown problem until the worst bugs are weeded out of
systemd and friends. If journald isn't logging and reporting
everything, there's practically no chance of fixing this, and I don't
have enough information to make a bug report.

Thanks anyway, Michael.

--
Joe


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/20140815213...@jresid.jretrading.com

david

unread,
Aug 15, 2014, 7:40:01 PM8/15/14
to

I have been bothered by this too.

 

KUser shows this user as "nobody" whose home directory is "/nonexistent" and whose login shell is /usr/sbin/nologin.

 

The account on one machine is set as disabled but both my current machines (#3 failed to turn on today :-( ) suffer the shut down delay - most times but not always.

 

The interesting bit (I think) is that this user is a member of only the lp, lpadmin and nogroup groups.

 

So something to do with printing? I wonder if I can safely kick this user off the system.

 

davcefai

 

 

---------------------------

Sent from a computer.

 

John Hasler

unread,
Aug 15, 2014, 8:10:02 PM8/15/14
to
The purpose of the "nobody" account is to allow daemons to run with
minimum privileges. Getting rid of it would be a bad idea.
--
John Hasler
jha...@newsguy.com
Elmwood, WI USA


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/87lhqpg...@thumper.dhh.gt.org

Reco

unread,
Aug 16, 2014, 2:10:02 AM8/16/14
to
Hi.

On Sat, 16 Aug 2014 00:44:31 +0200
david <davc...@keyworld.net> wrote:

> I have been bothered by this too.
>
> KUser shows this user as "nobody" whose home directory is
> "/nonexistent" and whose login shell is /usr/sbin/nologin.
>
> The account on one machine is set as disabled but both my current
> machines (#3 failed to turn on today :-( ) suffer the shut down delay -
> most times but not always.
>
> The interesting bit (I think) is that this user is a member of only the lp,
> lpadmin and nogroup groups.

This appears wrong to me. You see, stock Debian's nobody is:

$ getent passwd nobody
nobody:x:65534:65534:nobody:/nonexistent:/bin/sh

$ id nobody
uid=65534(nobody) gid=65534(nogroup) groups=65534(nogroup)

So, you have custom shell for nobody, which can be the source of your
problem, and you have custom groups for nobody, which is asking for
trouble (see /usr/share/doc/base-passwd/users-and-groups.txt.gz).

Reco


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/20140816100008.6a5b...@gmail.com

Joe

unread,
Aug 16, 2014, 3:20:01 AM8/16/14
to
On Sat, 16 Aug 2014 10:00:08 +0400
Reco <recov...@gmail.com> wrote:

> Hi.
>
> On Sat, 16 Aug 2014 00:44:31 +0200
> david <davc...@keyworld.net> wrote:
>
> > I have been bothered by this too.
> >
> > KUser shows this user as "nobody" whose home directory is
> > "/nonexistent" and whose login shell is /usr/sbin/nologin.
> >
> > The account on one machine is set as disabled but both my current
> > machines (#3 failed to turn on today :-( ) suffer the shut down
> > delay - most times but not always.
> >
> > The interesting bit (I think) is that this user is a member of only
> > the lp, lpadmin and nogroup groups.
>
> This appears wrong to me. You see, stock Debian's nobody is:
>
> $ getent passwd nobody
> nobody:x:65534:65534:nobody:/nonexistent:/bin/sh
>
> $ id nobody
> uid=65534(nobody) gid=65534(nogroup) groups=65534(nogroup)
>
> So, you have custom shell for nobody, which can be the source of your
> problem, and you have custom groups for nobody, which is asking for
> trouble (see /usr/share/doc/base-passwd/users-and-groups.txt.gz).
>
I have /usr/sbin/nologin also. This is up-to-date sid with systemd,
which may not have the same defaults as previous distributions.

--
Joe


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/20140816081...@jresid.jretrading.com

Reco

unread,
Aug 16, 2014, 5:40:02 AM8/16/14
to
On Sat, 16 Aug 2014 08:17:50 +0100
Joe <j...@jretrading.com> wrote:

> I have /usr/sbin/nologin also. This is up-to-date sid with systemd,
> which may not have the same defaults as previous distributions.

Curious. And what shell do they set now for users with uid < 100?

I've checked more-or-less fresh testing with systemd, and it says to me:

# getent passwd nobody
nobody:x:65534:65534:nobody:/nonexistent:/bin/sh

Anyway, changing nobody's shell to /bin/sh is worth trying IMO.
/usr/sbin/nologin as a shell is the RedHat way, not a Debian one.

Reco


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/20140816133632.72d7...@gmail.com

Michael Biebl

unread,
Aug 16, 2014, 6:00:01 AM8/16/14
to
Am 16.08.2014 11:36, schrieb Reco:
> On Sat, 16 Aug 2014 08:17:50 +0100
> Joe <j...@jretrading.com> wrote:
>
>> I have /usr/sbin/nologin also. This is up-to-date sid with systemd,
>> which may not have the same defaults as previous distributions.
>
> Curious. And what shell do they set now for users with uid < 100?
>
> I've checked more-or-less fresh testing with systemd, and it says to me:
>
> # getent passwd nobody
> nobody:x:65534:65534:nobody:/nonexistent:/bin/sh
>
> Anyway, changing nobody's shell to /bin/sh is worth trying IMO.
> /usr/sbin/nologin as a shell is the RedHat way, not a Debian one.
>

base-passwd (3.5.30) unstable; urgency=medium

[ Colin Watson ]
..
* Change the shell of all global static users other than root (which
retains /bin/sh) and sync (as /bin/sync is rather harmless) to
/usr/sbin/nologin (closes: #274229; LP: #216813, #248844).
...

-- Colin Watson <cjwa...@debian.org> Tue, 07 Jan 2014 15:41:06 +0000
signature.asc

Joel Rees

unread,
Aug 16, 2014, 6:30:01 AM8/16/14
to
On Sat, Aug 16, 2014 at 6:51 PM, Michael Biebl <bi...@debian.org> wrote:
> Am 16.08.2014 11:36, schrieb Reco:
>> On Sat, 16 Aug 2014 08:17:50 +0100
>> Joe <j...@jretrading.com> wrote:
>>
>>> I have /usr/sbin/nologin also. This is up-to-date sid with systemd,
>>> which may not have the same defaults as previous distributions.
>>
>> Curious. And what shell do they set now for users with uid < 100?
>>
>> I've checked more-or-less fresh testing with systemd, and it says to me:
>>
>> # getent passwd nobody
>> nobody:x:65534:65534:nobody:/nonexistent:/bin/sh
>>
>> Anyway, changing nobody's shell to /bin/sh is worth trying IMO.
>> /usr/sbin/nologin as a shell is the RedHat way, not a Debian one.
>>
>
> base-passwd (3.5.30) unstable; urgency=medium
>
> [ Colin Watson ]
> ..
> * Change the shell of all global static users other than root (which
> retains /bin/sh) and sync (as /bin/sync is rather harmless) to
> /usr/sbin/nologin (closes: #274229; LP: #216813, #248844).
> ...
>
> -- Colin Watson <cjwa...@debian.org> Tue, 07 Jan 2014 15:41:06 +0000

https://www.google.co.jp/search?q=%22%2Fusr%2Fsbin%2Fnologin+%28closes%3A+%23274229%3B+LP%3A+%23216813%2C+%23248844%29.%22

in particular,

https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=581899

--
Joel Rees

Be careful where you see conspiracy.
Look first in your own heart.


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/CAAr43iPksYozA9HeA85j=Ub4Xundbhand4z...@mail.gmail.com

Reco

unread,
Aug 16, 2014, 6:30:01 AM8/16/14
to
On Sat, 16 Aug 2014 11:51:28 +0200
Michael Biebl <bi...@debian.org> wrote:

> base-passwd (3.5.30) unstable; urgency=medium
>
> [ Colin Watson ]
> ..
> * Change the shell of all global static users other than root (which
> retains /bin/sh) and sync (as /bin/sync is rather harmless) to
> /usr/sbin/nologin (closes: #274229; LP: #216813, #248844).
> ...
>
> -- Colin Watson <cjwa...@debian.org> Tue, 07 Jan 2014 15:41:06 +0000

And testing still has base-passwd 3.5.28. My mistake then.

Reco


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/20140816142056.e05c...@gmail.com

david

unread,
Aug 16, 2014, 7:20:01 AM8/16/14
to

I.m starting to get the picture but we have moved away from what I think was the prime motive for this trhead to be started.

 

User 65534 is causing a frustrating 90 - 120 second delay during shutdown. That's 6 to 9 hrs a year!

 

Can this delay be eliminated? After all it did not used to happen before systemd was implemented.

 

Cheers to all

 

David

Joel Rees

unread,
Aug 16, 2014, 8:20:02 AM8/16/14
to
On Sat, Aug 16, 2014 at 6:36 PM, Reco <recov...@gmail.com> wrote:
> On Sat, 16 Aug 2014 08:17:50 +0100
> Joe <j...@jretrading.com> wrote:
>
>> I have /usr/sbin/nologin also. This is up-to-date sid with systemd,
>> which may not have the same defaults as previous distributions.
>
> Curious. And what shell do they set now for users with uid < 100?
>
> I've checked more-or-less fresh testing with systemd, and it says to me:
>
> # getent passwd nobody
> nobody:x:65534:65534:nobody:/nonexistent:/bin/sh

Up-to-date Wheezy:

nobody:x:65534:65534:nobody:/nonexistent:/bin/sh

nogroup:x:65534:

also

sshd:x:108:65534::/var/run/sshd:/usr/sbin/nologin

> Anyway, changing nobody's shell to /bin/sh is worth trying IMO.
> /usr/sbin/nologin as a shell is the RedHat way, not a Debian one.
>
> Reco

You might compare with

grep false /etc/passwd

--
Joel Rees

Be careful where you see conspiracy.
Look first in your own heart.


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/CAAr43iOBSPF_naNK9crk1-B8...@mail.gmail.com

John Hasler

unread,
Aug 16, 2014, 8:50:01 AM8/16/14
to
david writes:
> User 65534 is causing a frustrating 90 - 120 second delay during
> shutdown.

Some process that happens to be running as "nobody" is failing to exit
when instructed to do so. Systemd is waiting patiently for 90 seconds
before sending it a "kill -9". You need to either find that process and
fix it or change that timeout to a smaller value.
--
John Hasler
jha...@newsguy.com
Elmwood, WI USA


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/87ha1ch...@thumper.dhh.gt.org

AW

unread,
Aug 16, 2014, 9:00:02 AM8/16/14
to
On Sat, 16 Aug 2014 12:59:24 +0200
david <davc...@keyworld.net> wrote:

> Can this delay be eliminated? After all it did not used to happen before
> systemd was implemented.

OP is running Sid. So there are problems with stability in the unstable
version of Debian... and? ...

Oh well.

ps -u 65534

will show any random processes that 'nobody' may be running.

Then poke around /etc/systemd and /lib/systemd for a bit. Explore the newness.
Smell the fresh code smell... and enjoy...

--Andrew


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/20140816085328.ec91...@1024bits.com

Joel Rees

unread,
Aug 16, 2014, 11:20:02 AM8/16/14
to
On Sat, Aug 16, 2014 at 7:59 PM, david <davc...@keyworld.net> wrote:
> I.m starting to get the picture but we have moved away from what I think was
> the prime motive for this trhead to be started.
>
> User 65534 is causing a frustrating 90 - 120 second delay during shutdown.
> That's 6 to 9 hrs a year!
>
> Can this delay be eliminated? After all it did not used to happen before
> systemd was implemented.

Is there no message about a process that won't die gracefully, or
something similar, in the logs?

If not, the following may help:
------------------pfind.c----------------------
//* findps.c,
// a Q&D program to repeatedly look for something in the output of ps wwaux.
// Written by and copyright Joel Rees, Amagasaki, Japan, August 2014.
//
// Permission to use granted if the following three conditions are all met:
// Don't try to steal my copyrights.
// Don't blame me if it gets stuck or goes boom.
// Do use it for good purposes, by your definition of good.
*/


#include <stdio.h>
#include <stdlib.h>
#include <string.h>

#include <unistd.h>

/*
# Compile it like this:

cc -Wall -o findps findps.c

# ----------
# Test it like this:

./findps nobody

# ----------
# Install it something like this:

chmod o-rwx findps
sudo cp -i findps /usr/local/bin/
sudo chown root:root /usr/local/bin/findps
sudo touch /var/log/foundps.log

# To catch the culprit running as nobody
# and holding up your shutdown processes,
# call it in your shutdown script something like this:

findps nobody 100 > /var/log/foundps.log &

# See also
man ps
# and look for where to find the numeric process id.
# If it gets out of control,
# getting another terminal session should help. Then
man kill
# Also, the return key and
# ctrl-s
# may be useful. But
# ctrl-z
# might not be so useful. But
man bg
# anyway. Or, I mean,
man sh
# and remember to search with the "/" command:
# /bg
# /job
# and so forth.

# An equivalent shell script, without parameter checks, etc. might
look like this:
# ------------
#! /bin/bash
lim=$2
for (( ct = 0; ct < lim; ++ct )) ; do ps wwaux | grep $1; sleep 1; done
# ------------
*/


#define BIGCOMMANDSZ 1024


int main( int argc, char * argv[] )
{
char cmdbuff[ BIGCOMMANDSZ + 1];
int limit = 10; /* Maximum times through the loop. */

if ( argc < 2 )
{ fprintf( stderr, "Usage: %s <search-term> [<limit-count>]\n",
argv[ 0 ] );
fprintf( stderr, "\tDefault limit count is %d\n", limit );
return EXIT_FAILURE;
}
if ( argc > 2 )
{ limit = (int) strtol( argv[ 2 ], NULL, 10 );
}
cmdbuff[ BIGCOMMANDSZ ] = '\0';
strncpy( cmdbuff, "ps wwaux | grep ", BIGCOMMANDSZ );
strncat( cmdbuff, argv[ 1 ], BIGCOMMANDSZ );
for ( ;limit > 0; --limit )
{ system( cmdbuff );
sleep( 1 ); /* So it doesn't run away too fast. */
}
return EXIT_SUCCESS;
}

--------------------------------------------------

I'm sure I could do that in a shell script if I took the time to
refresh my memory.

--
Joel Rees

Be careful where you see conspiracy.
Look first in your own heart.


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/CAAr43iNKxOKnnP=c8QYts+j+ZcX_i_=2ZKgcNCz+...@mail.gmail.com

Joe

unread,
Aug 16, 2014, 6:00:02 PM8/16/14
to
On Fri, 15 Aug 2014 21:39:03 +0100
Joe <j...@jretrading.com> wrote:


>
> This is a can of worms, and I hereby abandon it.

OK, I lied. I was bored...

A little further on... journald *has* been keeping persistent journals,
but with different user permissions, now root:systemd-journal 640.

journalctl still shows entries up to August 3rd, but journalctl --user
shows all entries to date. If I change the permissions of the files
back to 755, this behaviour stays the same, except that I no longer
need to be a group member of systemd-journal, as expected. Something
changed on August 3rd, and I think it was the switch to systemd at pid
1. The cloned system had systemd at pid 1 from the beginning, or at
least as soon as systemd was installed. That system shows all entries
with just journalctl, it doesn't need --user.

I've persuaded journalctl to show me the logs for user 65534
(journalctl -u user-65534.slice as root) and they give little away.
Beyond doubt, this is the 90-second culprit, but it still isn't clear
why.

Aug 16 00:02:02 jresid systemd[26220]: pam_unix(systemd-user:session):
session opened for user nobody by (uid=0)
Aug 16 00:02:03 jresid systemd[26220]:
pam_ck_connector(systemd-user:session): cannot determine display-device
Aug 16 00:02:03 jresid systemd[2913]: Stopping Default.
Aug 16 00:02:03 jresid systemd[2913]: Stopped target Default.
Aug 16 00:02:03 jresid systemd[2913]: Starting Shutdown.
Aug 16 00:02:03 jresid systemd[2913]: Reached target Shutdown.
Aug 16 00:02:03 jresid systemd[2913]: Starting Exit the Session...
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.
Aug 16 00:02:03 jresid systemd[2913]: Dependency failed for Exit the
Session.
Aug 16 00:02:03 jresid systemd[2913]: Unit systemd-exit.service entered
failed state.
Aug 16 00:03:33 jresid systemd[1]: Stopping user-65534.slice.
Aug 16 00:03:33 jresid systemd[1]: Removed slice user-65534.slice. --
Reboot --


What I need to know now is what dependency is failing. How do I find
out?

Here is systemd-exit.service:

# This file is part of systemd.
#
# systemd is free software; you can redistribute it and/or modify it
# under the terms of the GNU Lesser General Public License as
published by
# the Free Software Foundation; either version 2.1 of the License, or
# (at your option) any later version.

[Unit]
Description=Exit the Session
Documentation=man:systemd.special(7)
DefaultDependencies=no
Requires=shutdown.target
After=shutdown.target

[Service]
Type=oneshot
ExecStart=/bin/kill -s 58 $MANAGERPID

Target shutdown had run, and /bin/kill exists. What other dependency
might there be? If the relevant PID wasn't found, would this cause a
'dependency' fault?

--
Joe


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/20140816225...@jretrading.com

Michael Biebl

unread,
Aug 16, 2014, 6:30:02 PM8/16/14
to
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
signature.asc

Joe

unread,
Aug 19, 2014, 5:20:03 PM8/19/14
to
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
└─us...@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-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/20140819221...@jresid.jretrading.com

Michael Biebl

unread,
Aug 19, 2014, 9:10:02 PM8/19/14
to
Am 19.08.2014 23:11, schrieb Joe:

> 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.

As I wrote in my first email, I suspect this is a cron job which runs as
the nobody user.

Have you tried grep nobody /etc/cron* -R

This e.g. turns up

/etc/cron.daily/popularity-contest: su -s /bin/sh -c
"/usr/sbin/popularity-contest" nobody


here. You might check the dates of the /var/log/popularity-contest*
files, if they match with the session starts you get in your journal.
signature.asc

Michael Biebl

unread,
Aug 19, 2014, 9:20:02 PM8/19/14
to
Am 20.08.2014 03:05, schrieb Michael Biebl:

> /etc/cron.daily/popularity-contest: su -s /bin/sh -c
> "/usr/sbin/popularity-contest" nobody
>
>
> here. You might check the dates of the /var/log/popularity-contest*
> files, if they match with the session starts you get in your journal.

Looking at the popcon cron job, it seems to be triggered daily, but the
popularity-contest binary is actually run only every week.

That would explain why you don't experience this issue every day.
signature.asc
Reply all
Reply to author
Forward
0 new messages