Bug 334559

Could you please add strace of sshd running into this problem?

(In reply to comment #1 from Anna Bernathova)
> Could you please add strace of sshd running into this problem?
> 
Can't reproduse it now, but can see this message not only on one host + it is repeated.

I am sorry but I also cannot reproduce it. If you show me strace, I might be at least able to determine what is wrong. I probably cannot fix it without your input, at least not without a great chance to encounter this bug too.

If you can, just wait for the bug to start appearing and strace sshd then, please.

(In reply to comment #3 from Anna Bernathova)
> I am sorry but I also cannot reproduce it. If you show me strace, I might be at
> least able to determine what is wrong. I probably cannot fix it without your
> input, at least not without a great chance to encounter this bug too.
> 
> If you can, just wait for the bug to start appearing and strace sshd then,
> please.
> 
Got such situation:
root     25659  3540  0 21:41 ?        00:00:00 sshd: moovieu [priv]
moovieu  25662 25659  0 21:41 ?        00:00:00 sshd: moovieu@pts/11
moovieu  25663 25662  2 21:41 pts/11   00:00:00 -bash

strace'd both 25659 and 25662

syslog entries:
Oct 18 21:41:57 moovid sshd[25659]: Accepted keyboard-interactive/pam for moovieu from AAA.BBB.CCC.DDD port 55806 ssh2
Oct 18 21:43:03 moovid sshd[25662]: PAM audit_log_acct_message() failed: Operation not permitted

strace outputs in attached files.

Created attachment 179299 [details]
starce pid 25659

Created attachment 179300 [details]
starce pid 25662

I have managed to reproduce the bug, going to take a look at it. Thanks.

Actually the bug seems to appear on most of 10.3 installations, so reproducing it is no big issue.

Anyway, audit_log_acct_message() is coming from audit package. Although it is called from pam and pam does also logging, pam relies only on its return code. Reassigning to audit maintainer, adding pam maintainer and myself to CC.

JFYI: It happens if you logout from a ssh session.

Found the Fedora patch for this problem and a short test shows, that the message does not appear anymore.

Thorsten: This patch is not upstream. Please take care.

(I will attach the patch) 

Created attachment 187621 [details]
pam-0.99.8.1-audit-no-log.patch

(In reply to comment #13 from Michael Calmer)
> Found the Fedora patch for this problem and a short test shows, that the
> message does not appear anymore.
> 
> Thorsten: This patch is not upstream. Please take care.

The patch is not upstream because it is wrong. And I think Fedora had good reasons why they did not submit it with their latest audit fixes.

The problem is, that Fedora uses a special configuration, where this will work. But this is not the upstream default and will break audit logging on other distributions (like openSUSE).

The problem is: Why does ssh call PAM with wrong permissions?

I don't get this message on my openSUSE installations.

So to fix the problem correct, we need to find out why ssh closes the session with user rights, not root. And fix that problem. Because if ssh does not close the session with correct user privilegs, not only auditing, but also some other PAM modules will fail.

I set "UsePrivilegeSeparation no" in sshd_config and the messages was gone.
I aggree with Thorsten that PrivilegeSeparation in sshd is broken and should be fixed.

Assigning back to ssh maintainer. 

(In reply to comment #17 from Thorsten Kukuk)
> The problem is: Why does ssh call PAM with wrong permissions?
> 
I see the same problem with imapd.  Being a software engineer I find it hard to believe that two separate projects would end up causing the same error at the same time on the same library without it having something to do with a change in the library.  Did the audit library change around this call, perhaps get more strict about how it's to be called since 10.2?  Neither sshd nor imapd logged this message in 10.2, but they both log it in 10.3.

(In reply to comment #19 from Jon Schewe)
> (In reply to comment #17 from Thorsten Kukuk)
> > The problem is: Why does ssh call PAM with wrong permissions?
> > 
> I see the same problem with imapd.  Being a software engineer I find it hard to
> believe that two separate projects would end up causing the same error at the
> same time on the same library without it having something to do with a change
> in the library. 

I don't find it hard to belive. ssh is well known to introduce this bug again and again with a new release, they do this since several years. And to call PAM functions with wrong privilegs is a common mistake in a lot of projects. I wonder that it are this time only two projects which did it wrong.

At the end, this is quite funny bug. Not only closing the session, but also opening is done in the wrong process. Opening works just because it is done immediately after the fork and before dropping the privileges. Ooops :-)

Fortunately, upstream is already aware about this issue. Although they have not released their fix yet, their bugzilla contains the patch that looks to fix the bug properly. (I got it here: https://bugzilla.mindrot.org/attachment.cgi?id=1216.)
I have ported it for our openssh in stable and tested. 

Submitted for stable.

Hasn't this fix been integrated into the stable rpm's yet?
I just installed the latest openssh for 10.3 (openssh-4.6p1-58.6)
But still see the "PAM audit_log_acct_message() failed:" messages in the logs...

It was fixed just for the factory distribution, we have not done a maintenance update for 10.3 that was already released at the time of fix.

But it looks that there is even package with openssh 5.1 for 10.3 available in openSUSE buildservice, you might find a help there.