pam_systemd.so and su

[Canek Peláez Valdés]

Hi; I'm using systemd 43 in Gentoo, and I usally have this line at the
end of /etc/pam.d/system-auth:

-session optional pam_systemd.so

When I use su to become root, after logout the following message appears:

...killed.

Not always, but most of the time. Without the line with
pam_systemd.so, the message never appears.

So, two questions:

1. Why is my session being killed at logout time?

2. The pam_systemd.so is really necessary? The "...killed." message
appears after two or three seconds, and it's slightly annoying.

Regards.

[Kok, Auke-jan H]

Post by Canek Peláez Valdés
Hi; I'm using systemd 43 in Gentoo, and I usally have this line at the
-session        optional        pam_systemd.so
 ...killed.
Not always, but most of the time. Without the line with
pam_systemd.so, the message never appears.
1. Why is my session being killed at logout time?
2. The pam_systemd.so is really necessary? The "...killed." message
appears after two or three seconds, and it's slightly annoying.

please read `man pam_systemd`...

Cheers,

Auke

[Canek Peláez Valdés]

On Sun, Mar 18, 2012 at 5:43 PM, Kok, Auke-jan H

Post by Kok, Auke-jan H

Post by Canek Peláez Valdés
Hi; I'm using systemd 43 in Gentoo, and I usally have this line at the
-session        optional        pam_systemd.so
 ...killed.
Not always, but most of the time. Without the line with
pam_systemd.so, the message never appears.
1. Why is my session being killed at logout time?
2. The pam_systemd.so is really necessary? The "...killed." message
appears after two or three seconds, and it's slightly annoying.

please read `man pam_systemd`...

OK, done. Still doesn't understand. The kill-session-processes option
is not set, so it should default to "no", right? Also, my
/etc/systemd/systemd-logind.conf has no options set, in particular
KillOnlyUsers is not set, and therefore is should default to "no",
right? So, again, if both options are no, what is killing my session
at logout time?

Regards.

[Mike Kazantsev]

On Sun, 18 Mar 2012 18:26:53 -0600

Post by Canek Peláez Valdés
On Sun, Mar 18, 2012 at 5:43 PM, Kok, Auke-jan H

Post by Kok, Auke-jan H

Post by Canek Peláez Valdés
...killed.

I can't recall ever facing that "message", so maybe you can explain
what does it mean?
Are the long-running processes you've started from "su" get killed?
...along with su itself, which produces that message?

Also, maybe that is similar to the past logind issue?
http://thread.gmane.org/gmane.comp.sysutils.systemd.devel/4370/

Post by Canek Peláez Valdés

Post by Kok, Auke-jan H

Post by Canek Peláez Valdés
1. Why is my session being killed at logout time?
2. The pam_systemd.so is really necessary? The "...killed." message
appears after two or three seconds, and it's slightly annoying.

please read `man pam_systemd`...

OK, done. Still doesn't understand. The kill-session-processes option
is not set, so it should default to "no", right? Also, my
/etc/systemd/systemd-logind.conf has no options set, in particular
KillOnlyUsers is not set, and therefore is should default to "no",
right? So, again, if both options are no, what is killing my session
at logout time?

I can suggest to check what exactly kills the processes by connecting
strace to:

a) systemd itself ("strace -s65535 -f -p 1 2>&1 | grep kill")
b) systemd-logind
c) su process (*after* it was started)

I'm suggesting this because systemd can kill leftover pids when
cleaning up controller hierarchies, logind can kill the session,
pam_systemd seem to have a kill-parameter and probably can do it by
itself as well.

When debugging somewhat similar issue in the past, I've wasted a lot of
time mistakingly assuming that it's either logind or pam_systemd that
does the killing, while in fact it was totally unrelated to
kill-switches in both of them (more details can be found here:
http://goo.gl/S5ZLO).

[Mike Kazantsev]

It's probably my fault that MUAs try to answer to me directly, since
I'm reading list from gmane but posting thru mail, but please be sure
tocheck the "To:" line next time, otherwise I might be the only one to
read the message.


On Mon, 19 Mar 2012 02:40:24 -0600

Post by Mike Kazantsev
On Sun, 18 Mar 2012 18:26:53 -0600

Post by Canek Peláez Valdés
On Sun, Mar 18, 2012 at 5:43 PM, Kok, Auke-jan H

Post by Kok, Auke-jan H

Post by Canek Peláez Valdés
...killed.

I can't recall ever facing that "message", so maybe you can explain
what does it mean?
Are the long-running processes you've started from "su" get killed?
...along with su itself, which produces that message?

No, my su session works flawlessly, but when I logout the su session,
the console gets unresponsive for two or three minutes, and then the
"...killed." message appears.

Hm, ok, if I'm reading that right, shell that invokes su gets killed
along with the su itself.

Post by Mike Kazantsev
Also, maybe that is similar to the past logind issue?
http://thread.gmane.org/gmane.comp.sysutils.systemd.devel/4370/

It sounds similar to the second to last message in the thread.

Maybe it'd be a good idea to join discussion there.
Judging by the number of posts, there's probably a bug opened
somewhere, and maybe even some patches floating around.

Post by Mike Kazantsev

Post by Canek Peláez Valdés

Post by Kok, Auke-jan H

Post by Canek Peláez Valdés
1. Why is my session being killed at logout time?
2. The pam_systemd.so is really necessary? The "...killed." message
appears after two or three seconds, and it's slightly annoying.

please read `man pam_systemd`...

OK, done. Still doesn't understand. The kill-session-processes option
is not set, so it should default to "no", right? Also, my
/etc/systemd/systemd-logind.conf has no options set, in particular
KillOnlyUsers is not set, and therefore is should default to "no",
right? So, again, if both options are no, what is killing my session
at logout time?

I can suggest to check what exactly kills the processes by connecting
 a) systemd itself ("strace -s65535 -f -p 1 2>&1 | grep kill")
 b) systemd-logind
 c) su process (*after* it was started)
I'm suggesting this because systemd can kill leftover pids when
cleaning up controller hierarchies, logind can kill the session,
pam_systemd seem to have a kill-parameter and probably can do it by
itself as well.
When debugging somewhat similar issue in the past, I've wasted a lot of
time mistakingly assuming that it's either logind or pam_systemd that
does the killing, while in fact it was totally unrelated to
http://goo.gl/S5ZLO).

I did a "su -", and run strace on the pid of the su process. Then I
# strace -p5207
Process 5207 attached - interrupt to quit
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WSTOPPED, NULL) = 5208
getuid() = 0
time([1332145846]) = 1332145846
socket(PF_FILE, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 3
connect(3, {sa_family=AF_FILE, path="/dev/log"}, 110) = 0
sendto(3, "<86>Mar 19 02:30:46 su[5207]: pa"..., 80, MSG_NOSIGNAL, NULL, 0) = 80

Is it some error printed to syslog?
"-s65535" strace flag suggested above would've shown the full message.

close(6) = 0
munmap(0x7f078e6ac000, 2101296) = 0
--- {si_signo=SIGTERM, si_code=SI_USER, si_pid=124, si_uid=0,
si_value={int=238059712, ptr=0xe3080c0}} (Terminated) ---

That's the pid of su receiving SIGTERM, so obviously something else
(systemd or systemd-logind) sends it, so I suggest you trace these.

rt_sigreturn(0xf) = 0
munmap(0x7f078e4a9000, 2105456) = 0
munmap(0x7f078e2a5000, 2109640) = 0
munmap(0x7f078e08d000, 2192064) = 0
munmap(0x7f078de56000, 2318784) = 0
munmap(0x7f078dc54000, 2101296) = 0
munmap(0x7f078da4f000, 2113840) = 0
munmap(0x7f078d843000, 2144968) = 0
munmap(0x7f078d63e000, 2114088) = 0
munmap(0x7f078d43b000, 2105528) = 0
munmap(0x7f078d201000, 2333032) = 0
munmap(0x7f078cbd7000, 2113872) = 0
munmap(0x7f078c9d2000, 2114008) = 0
munmap(0x7f078c7d0000, 2101280) = 0
rt_sigprocmask(SIG_BLOCK, [CHLD], ~[KILL ALRM TERM STOP RTMIN RT_1], 8) = 0
nanosleep({2, 0}, 0x7fff1a115aa0) = 0
kill(5208, SIGKILL) = -1 ESRCH (No such process)

You can probably check what that pid is, but I bet it's the shell that
su runs (especially since it's pid is su+1), so that's su terminating
whatever runs under it, but you've already logged out, hence "No such
process".

write(2, " ...killed.\n", 12) = 12

Probably su telling that something has terminated it and it killed
whatever command you ran there.

exit_group(-1) = ?
Process 5207 detached
That's the message all right, the "...killed.\n" one. I don't know how
to read strace's output. Any light shed on this will be really
appreciated.
Regards.

I'd say it looks consistent with what's discussed in
http://thread.gmane.org/gmane.comp.sysutils.systemd.devel/4370/ thread,
but to be extra sure, I'd suggest confirming that it's logind that
kills su (same strace tool should help) and iirc the fact that stuff
like sudo closed pam session too early turned out to be a bug in sudo
itself, so maybe there are fixed versions or bugs opened for su as well.

Also, if logind tries to kill session leader process when session ends,
and that turns out to be the origin of that SIGTERM, maybe there's some
way to disable that behavior as a workaround?

[Lennart Poettering]

Post by Canek Peláez Valdés
Hi; I'm using systemd 43 in Gentoo, and I usally have this line at the
-session optional pam_systemd.so
...killed.
Not always, but most of the time. Without the line with
pam_systemd.so, the message never appears.
1. Why is my session being killed at logout time?
2. The pam_systemd.so is really necessary? The "...killed." message
appears after two or three seconds, and it's slightly annoying.

Which version of systemd is this? (If it isnt 44, please upgrade first,
then try to reproduce this)

Do you have audit enabled in the kernel and are using pam_loginuid?

Normally, when the pam session close hooks are called logind responds to
this by killing the main process of the session if it still
exists. This is probably the source of the problem here.

I understood correctly that besides the "su killed" message everything
behaves correctly? i.e. the commands within the su are fully executed,
only su itself is called, right?

Lennart

[Lennart Poettering]

Post by Lennart Poettering

Post by Canek Peláez Valdés
Hi; I'm using systemd 43 in Gentoo, and I usally have this line at the
-session optional pam_systemd.so
...killed.
Not always, but most of the time. Without the line with
pam_systemd.so, the message never appears.
1. Why is my session being killed at logout time?
2. The pam_systemd.so is really necessary? The "...killed." message
appears after two or three seconds, and it's slightly annoying.

Which version of systemd is this? (If it isnt 44, please upgrade first,
then try to reproduce this)
Do you have audit enabled in the kernel and are using pam_loginuid?
Normally, when the pam session close hooks are called logind responds to
this by killing the main process of the session if it still
exists. This is probably the source of the problem here.

I have now commited a patch to git that might fix your issue. Please
test:

http://cgit.freedesktop.org/systemd/systemd/commit/?id=75c8e3cffd7da8eede614cf61384957af2c82a29

I assume this fixes your problem, but since our kernels actually have
audit enabled I am a bit too lazy trying to reproduce the issue here, so
I'd be very thankful if you could test this!

Lennart

[Christian Hesse]

Post by Lennart Poettering

Post by Lennart Poettering

Post by Canek Peláez Valdés
Hi; I'm using systemd 43 in Gentoo, and I usally have this line at the
-session optional pam_systemd.so
...killed.
Not always, but most of the time. Without the line with
pam_systemd.so, the message never appears.
1. Why is my session being killed at logout time?
2. The pam_systemd.so is really necessary? The "...killed." message
appears after two or three seconds, and it's slightly annoying.

Which version of systemd is this? (If it isnt 44, please upgrade first,
then try to reproduce this)
Do you have audit enabled in the kernel and are using pam_loginuid?
Normally, when the pam session close hooks are called logind responds to
this by killing the main process of the session if it still
exists. This is probably the source of the problem here.

I have now commited a patch to git that might fix your issue. Please
http://cgit.freedesktop.org/systemd/systemd/commit/?id=75c8e3cffd7da8eede614cf61384957af2c82a29
I assume this fixes your problem, but since our kernels actually have
audit enabled I am a bit too lazy trying to reproduce the issue here, so
I'd be very thankful if you could test this!

This fixes it for me. Thanks a lot!

Though this brings another problem: I have tmux with pam support (don't know
the original link but have a copy of the patch on my personal webserver [0]).
I used to have an alias

alias tmux="tmux attach || tmux"

which tries to attach to a session and opens a new one if it fails. I had to
change this to

alias tmux "tmux attach || sleep 0.1 && tmux"

to make it work again. So maybe there's a race condition anywhere? However I
am happy with that workaround.

[0] http://www.eworm.de/download/linux/tmux-pam.patch

[Lennart Poettering]

Post by Christian Hesse

Post by Lennart Poettering

Post by Lennart Poettering
Do you have audit enabled in the kernel and are using pam_loginuid?
Normally, when the pam session close hooks are called logind responds to
this by killing the main process of the session if it still
exists. This is probably the source of the problem here.

I have now commited a patch to git that might fix your issue. Please
http://cgit.freedesktop.org/systemd/systemd/commit/?id=75c8e3cffd7da8eede614cf61384957af2c82a29
I assume this fixes your problem, but since our kernels actually have
audit enabled I am a bit too lazy trying to reproduce the issue here, so
I'd be very thankful if you could test this!

This fixes it for me. Thanks a lot!
Though this brings another problem: I have tmux with pam support (don't know
the original link but have a copy of the patch on my personal webserver [0]).
I used to have an alias
alias tmux="tmux attach || tmux"
which tries to attach to a session and opens a new one if it fails. I had to
change this to

"it fails"? How precisely?

No clue what tmux is though (some screen reimplementation?).

Lennart

[Christian Hesse]

Post by Lennart Poettering

Post by Christian Hesse

Post by Lennart Poettering

Post by Lennart Poettering
Do you have audit enabled in the kernel and are using pam_loginuid?
Normally, when the pam session close hooks are called logind responds
to this by killing the main process of the session if it still
exists. This is probably the source of the problem here.

I have now commited a patch to git that might fix your issue. Please
http://cgit.freedesktop.org/systemd/systemd/commit/?id=75c8e3cffd7da8eede614cf61384957af2c82a29
I assume this fixes your problem, but since our kernels actually have
audit enabled I am a bit too lazy trying to reproduce the issue here, so
I'd be very thankful if you could test this!

This fixes it for me. Thanks a lot!
Though this brings another problem: I have tmux with pam support (don't
know the original link but have a copy of the patch on my personal
webserver [0]). I used to have an alias
alias tmux="tmux attach || tmux"
which tries to attach to a session and opens a new one if it fails. I had
to change this to

"it fails"? How precisely?

It exits with error code 1, nothing more. No error messages, nothing.
Probably the patch is everything but verbose.

What I have found so far: If I add pam_unix in session directive (just for
logging) in /etc/pam.d/tmux I get logs for the first tmux process only, not
for the failing one.
If I sleep for a moment before starting the second tmux process it works as
expected and I git pam logs from both processes.

Post by Lennart Poettering
No clue what tmux is though (some screen reimplementation?).

Basically, yes.

[Koen Kooi]

Post by Lennart Poettering

Post by Lennart Poettering

Post by Canek Peláez Valdés
Hi; I'm using systemd 43 in Gentoo, and I usally have this line at the
-session optional pam_systemd.so
...killed.
Not always, but most of the time. Without the line with
pam_systemd.so, the message never appears.
1. Why is my session being killed at logout time?
2. The pam_systemd.so is really necessary? The "...killed." message
appears after two or three seconds, and it's slightly annoying.

Which version of systemd is this? (If it isnt 44, please upgrade first,
then try to reproduce this)
Do you have audit enabled in the kernel and are using pam_loginuid?
Normally, when the pam session close hooks are called logind responds to
this by killing the main process of the session if it still
exists. This is probably the source of the problem here.

I have now commited a patch to git that might fix your issue. Please
http://cgit.freedesktop.org/systemd/systemd/commit/?id=75c8e3cffd7da8eede614cf61384957af2c82a29
I assume this fixes your problem, but since our kernels actually have
audit enabled I am a bit too lazy trying to reproduce the issue here, so
I'd be very thankful if you could test this!

On the CONFIG_AUDIT front, I just found out that CONFIG_AUDITSYSCALL is not supported on ARM and MIPS:

depends on AUDIT && (X86 || PPC || S390 || IA64 || UML || SPARC64 || SUPERH)

There's a patch for ARM that might make it into a recent kernel: http://git.kernel.org/?p=linux/kernel/git/viro/audit.git;a=patch;h=29ef73b7a823b77a7cd0bdd7d7cded3fb6c2587b



regards,

Koen

[Lennart Poettering]

Post by Koen Kooi

Post by Lennart Poettering
I have now commited a patch to git that might fix your issue. Please
http://cgit.freedesktop.org/systemd/systemd/commit/?id=75c8e3cffd7da8eede614cf61384957af2c82a29
I assume this fixes your problem, but since our kernels actually have
audit enabled I am a bit too lazy trying to reproduce the issue here, so
I'd be very thankful if you could test this!

depends on AUDIT && (X86 || PPC || S390 || IA64 || UML || SPARC64 || SUPERH)
There's a patch for ARM that might make it into a recent kernel: http://git.kernel.org/?p=linux/kernel/git/viro/audit.git;a=patch;h=29ef73b7a823b77a7cd0bdd7d7cded3fb6c2587b

systemd won't take advantage of CONFIG_AUDITSYSCALL hence you can leave
that disabled anyway.

Lennart

[Frederic Crozat]

Post by Lennart Poettering

Post by Lennart Poettering

Post by Canek Peláez Valdés
Hi; I'm using systemd 43 in Gentoo, and I usally have this line at the
-session optional pam_systemd.so
...killed.
Not always, but most of the time. Without the line with
pam_systemd.so, the message never appears.
1. Why is my session being killed at logout time?
2. The pam_systemd.so is really necessary? The "...killed." message
appears after two or three seconds, and it's slightly annoying.

Which version of systemd is this? (If it isnt 44, please upgrade first,
then try to reproduce this)
Do you have audit enabled in the kernel and are using pam_loginuid?
Normally, when the pam session close hooks are called logind responds to
this by killing the main process of the session if it still
exists. This is probably the source of the problem here.

I have now commited a patch to git that might fix your issue. Please
http://cgit.freedesktop.org/systemd/systemd/commit/?id=75c8e3cffd7da8eede614cf61384957af2c82a29
I assume this fixes your problem, but since our kernels actually have
audit enabled I am a bit too lazy trying to reproduce the issue here, so
I'd be very thankful if you could test this!

I was hoping it would also fix
https://bugs.freedesktop.org/show_bug.cgi?id=45670 /
https://bugzilla.novell.com/show_bug.cgi?id=746704 but it doesn't :(

[Lennart Poettering]

Post by Frederic Crozat

Post by Lennart Poettering

Post by Lennart Poettering
Normally, when the pam session close hooks are called logind responds to
this by killing the main process of the session if it still
exists. This is probably the source of the problem here.

I have now commited a patch to git that might fix your issue. Please
http://cgit.freedesktop.org/systemd/systemd/commit/?id=75c8e3cffd7da8eede614cf61384957af2c82a29
I assume this fixes your problem, but since our kernels actually have
audit enabled I am a bit too lazy trying to reproduce the issue here, so
I'd be very thankful if you could test this!

I was hoping it would also fix
https://bugs.freedesktop.org/show_bug.cgi?id=45670 /
https://bugzilla.novell.com/show_bug.cgi?id=746704 but it doesn't :(

This only happens in kdm and the SUSE implementation of sudo, right?

My guess is still that for some reason those PAm clients invoke the PAM
session end handler way too early. Would be good to trace that
down. Just place some debug messages in pam_systemd and check when they
are printed.

Lennart

[Frederic Crozat]

Post by Lennart Poettering

Post by Lennart Poettering

Post by Canek Peláez Valdés
Hi; I'm using systemd 43 in Gentoo, and I usally have this line at the
-session optional pam_systemd.so
...killed.
Not always, but most of the time. Without the line with
pam_systemd.so, the message never appears.
1. Why is my session being killed at logout time?
2. The pam_systemd.so is really necessary? The "...killed." message
appears after two or three seconds, and it's slightly annoying.

Which version of systemd is this? (If it isnt 44, please upgrade first,
then try to reproduce this)
Do you have audit enabled in the kernel and are using pam_loginuid?
Normally, when the pam session close hooks are called logind responds to
this by killing the main process of the session if it still
exists. This is probably the source of the problem here.

I have now commited a patch to git that might fix your issue. Please
http://cgit.freedesktop.org/systemd/systemd/commit/?id=75c8e3cffd7da8eede614cf61384957af2c82a29
I assume this fixes your problem, but since our kernels actually have
audit enabled I am a bit too lazy trying to reproduce the issue here, so
I'd be very thankful if you could test this!

Well, I'm able to reproduce this problem with a kernel with audit
enabled and configured, unfortunately.

Our patch seems to improve the situation a little bit, but not entirely,
when running inside a previously detached screen session:
- su -l calls aren't killed when exiting them
- but sudo calls are being terminated before being started, after the
second sudo call. You need to call one time "su -l", and the, sudo will
work one time.

(we are calling pam_systemd in a common-session file which is including
in a lot of pam configuration, including sudo and su-l).