Audit not recording the correct syscall return value in Fedora 10?

Audit not recording the correct syscall return value in Fedora 10?

[Paul Moore]

While doing some testing on Fedora 10 using the 2.6.27.5-117.fc10.x86_64 
kernel I stumbled across a rather odd problem: somewhere between the end of 
sys_sendto() and audit_syscall_exit() the syscall's return value was changing 
resulting in incorrect audit records (similar problems with sys_sendmsg()).  
After some head scratching and debugging I determined that the %rax register 
was being altered at some point and if we reloaded the syscall's return value 
from the stack before calling audit_syscall_exit() we could avoid the problem 
(see patch below).

I also tried to reproduce the problem with a vanilla 2.6.29.1 kernel and after 
several hours of testing I have yet to see the problem using the newer, 
upstream kernel.  Taking a look at the entry_64.S files of the two kernels 
there appear to be a number of changes, the most significant are the tracing 
changes but I'm not familiar enough with this chunk of code to identify the 
definitive root cause (although, tracing changes does sound reasonable).

Does anyone have any thoughts?

diff --git a/arch/x86/kernel/entry_64.S b/arch/x86/kernel/entry_64.S
index a331ec3..16db517 100644
--- a/arch/x86/kernel/entry_64.S
+++ b/arch/x86/kernel/entry_64.S
@@ -589,8 +589,8 @@ auditsys:
         * masked off.
         */
 sysret_audit:
-       movq %rax,%rsi          /* second arg, syscall return value */
-       cmpq $0,%rax            /* is it < 0? */
+       movq RAX-ARGOFFSET(%rsp),%rsi   /* second arg, syscall return value */
+       cmpq $0,%rsi                    /* is it < 0? */
        setl %al                /* 1 if so, 0 if not */
        movzbl %al,%edi         /* zero-extend that into %edi */
        inc %edi /* first arg, 0->1(AUDITSC_SUCCESS), 1->2(AUDITSC_FAILURE) */

-- 
paul moore
linux @ hp

Re: Audit not recording the correct syscall return value in Fedora 10?

[Klaus Heinrich Kiwi]

On Tue, 2009-04-07 at 11:34 -0400, Paul Moore wrote:
> Does anyone have any thoughts?

I remember debugging an issue with the incorrect return value being
audited for a syscall. It was s390[x] specific and only occurred with
successful execve() syscalls. This behavior was pointed out with the
open-source common-criteria testsuite that checked each
security-relevant syscalls for parameters, return values, args etc..

I didn't give much important to those since execve() return value is
really not that important if the call succeeds ;-)

But now I'm curious to what other problems related to syscalls return
values you've found, and how those weren't caught by the same set of
tests (hmm, maybe they are x86-specific?)

Can you give us some examples?

Thanks,

 -Klaus
-- 
Klaus Heinrich Kiwi <klausk@linux.vnet.ibm.com>
Linux Security Development, IBM Linux Technology Center

Re: Audit not recording the correct syscall return value in Fedora 10?

[Paul Moore]

On Tuesday 07 April 2009 10:44:09 pm Klaus Heinrich Kiwi wrote:
> On Tue, 2009-04-07 at 11:34 -0400, Paul Moore wrote:
> > Does anyone have any thoughts?
>
> I remember debugging an issue with the incorrect return value being
> audited for a syscall. It was s390[x] specific and only occurred with
> successful execve() syscalls. This behavior was pointed out with the
> open-source common-criteria testsuite that checked each
> security-relevant syscalls for parameters, return values, args etc..
>
> I didn't give much important to those since execve() return value is
> really not that important if the call succeeds ;-)
>
> But now I'm curious to what other problems related to syscalls return
> values you've found, and how those weren't caught by the same set of
> tests (hmm, maybe they are x86-specific?)

Well, I'm not certain about the exact root cause (I was hoping others with 
more audit experience would be able to take a look) but I do know that my 
fix/workaround was arch specific.  My hunch is that the problem does lie in 
the arch specific code but it may be that the same problem exists on multiple 
architectures.

> Can you give us some examples?

Of the tests?  Sure, I used the audit-test suite which can be found on 
SourceForge, the tests that trigger the error on my test system are the 
sendto() and sendmsg() syscall tests which are run as part of the network 
tests.

http://sourceforge.net/project/showfiles.php?group_id=167060
http://audit-test.svn.sforge.net/viewvc/audit- 
       test/trunk/tests/audit/utils/bin/do_sendto.c?revision=2019&view=markup
http://audit-test.svn.sourceforge.net/viewvc/audit-
       test/trunk/tests/audit/utils/bin/do_sendmsg.c?view=markup

-- 
paul moore
linux @ hp

Re: Audit not recording the correct syscall return value in Fedora 10?

[Tony Jones]

On Tue, Apr 07, 2009 at 11:34:35AM -0400, Paul Moore wrote:
> While doing some testing on Fedora 10 using the 2.6.27.5-117.fc10.x86_64 
> kernel I stumbled across a rather odd problem: somewhere between the end of 
> sys_sendto() and audit_syscall_exit() the syscall's return value was changing 
> resulting in incorrect audit records (similar problems with sys_sendmsg()).  
> After some head scratching and debugging I determined that the %rax register 
> was being altered at some point and if we reloaded the syscall's return value 
> from the stack before calling audit_syscall_exit() we could avoid the problem 
> (see patch below).
> 
> I also tried to reproduce the problem with a vanilla 2.6.29.1 kernel and after 
> several hours of testing I have yet to see the problem using the newer, 
> upstream kernel.  Taking a look at the entry_64.S files of the two kernels 
> there appear to be a number of changes, the most significant are the tracing 
> changes but I'm not familiar enough with this chunk of code to identify the 
> definitive root cause (although, tracing changes does sound reasonable).
> 
> Does anyone have any thoughts?

I have seen a similar issue with the init_module syscall on x86_64.  I have an 
open bug on it.

for i in `seq 1 100`; do cat /dev/null > /var/log/audit/audit.log ; rmmod dummy
; rcauditd restart ; auditctl -a entry,always -S init_module ; modprobe dummy ;
ausearch -c modprobe; done

Randomly you'll get a bogus return code in audit, on a DL375 needed 1000 iter
to reproduce.

type=SYSCALL msg=audit(1235061247.598:22697): arch=c000003e syscall=175
success=no exit=1490771928 a0=7fe11dc61000 a1=1e08 a2=61a1e0 a3=61a1e0 items=0
ppid=31342 pid=8313 auid=1001 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0
fsgid=0 tty=pts3 ses=2 comm="modprobe" exe="/sbin/modprobe" key=(null)

I keep meaning to get back to debugging it.

Tony

Re: Audit not recording the correct syscall return value in Fedora 10?

[Tony Jones]

On Tue, Apr 07, 2009 at 11:44:09PM -0300, Klaus Heinrich Kiwi wrote:
> On Tue, 2009-04-07 at 11:34 -0400, Paul Moore wrote:
> > Does anyone have any thoughts?
> 
> I remember debugging an issue with the incorrect return value being
> audited for a syscall. It was s390[x] specific and only occurred with
> successful execve() syscalls. This behavior was pointed out with the
> open-source common-criteria testsuite that checked each
> security-relevant syscalls for parameters, return values, args etc..
> 
> I didn't give much important to those since execve() return value is
> really not that important if the call succeeds ;-)
> 
> But now I'm curious to what other problems related to syscalls return
> values you've found, and how those weren't caught by the same set of
> tests (hmm, maybe they are x86-specific?)
> 
> Can you give us some examples?

Klaus.  I need to kick this bug upstream.  I'll do so today. I thought I'd 
tracked it down to some specific execve code in the entry sequence, that was a 
while ago, I got back to looking at it and I can't find that code anymore :-( 
but it still fails.

For S390[x] you'll get audit events of the form:

type=SYSCALL msg=audit(1179421699.058:39809): arch=80000016 syscall=11
success=yes exit=11 a0=3ffff91ce50 a1=3ffff91e240 a2=3ffff91e250 a3=20000162a58
items=2 ppid=13131 pid=13132 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0
egid=0 sgid=0 fsgid=0 tty=pts1 comm="true" exe="/bin/true" subj=unconstrained 
key=(null)

strace shows that the syscall succeeded.

My S390 assembler knowledge is non-existant but appears that the syscall value 
is somehow in gprs[2] rather than the return value when the codepath enters 
s390/kernel/ptrace.c::do_syscall_trace_exit.  Only for the execve syscall.

Tony

Re: Audit not recording the correct syscall return value in Fedora 10?

[Paul Moore]

On Tuesday 05 May 2009 02:08:45 pm Tony Jones wrote:
> On Tue, Apr 07, 2009 at 11:34:35AM -0400, Paul Moore wrote:
> > While doing some testing on Fedora 10 using the 2.6.27.5-117.fc10.x86_64
> > kernel I stumbled across a rather odd problem: somewhere between the end
> > of sys_sendto() and audit_syscall_exit() the syscall's return value was
> > changing resulting in incorrect audit records (similar problems with
> > sys_sendmsg()). After some head scratching and debugging I determined
> > that the %rax register was being altered at some point and if we reloaded
> > the syscall's return value from the stack before calling
> > audit_syscall_exit() we could avoid the problem (see patch below).
> >
> > I also tried to reproduce the problem with a vanilla 2.6.29.1 kernel and
> > after several hours of testing I have yet to see the problem using the
> > newer, upstream kernel.  Taking a look at the entry_64.S files of the two
> > kernels there appear to be a number of changes, the most significant are
> > the tracing changes but I'm not familiar enough with this chunk of code
> > to identify the definitive root cause (although, tracing changes does
> > sound reasonable).
> >
> > Does anyone have any thoughts?
>
> I have seen a similar issue with the init_module syscall on x86_64.  I have
> an open bug on it.
>
> for i in `seq 1 100`; do cat /dev/null > /var/log/audit/audit.log ; rmmod
> dummy ; rcauditd restart ; auditctl -a entry,always -S init_module ;
> modprobe dummy ; ausearch -c modprobe; done
>
> Randomly you'll get a bogus return code in audit, on a DL375 needed 1000
> iter to reproduce.
>
> type=SYSCALL msg=audit(1235061247.598:22697): arch=c000003e syscall=175
> success=no exit=1490771928 a0=7fe11dc61000 a1=1e08 a2=61a1e0 a3=61a1e0
> items=0 ppid=31342 pid=8313 auid=1001 uid=0 gid=0 euid=0 suid=0 fsuid=0
> egid=0 sgid=0 fsgid=0 tty=pts3 ses=2 comm="modprobe" exe="/sbin/modprobe"
> key=(null)
>
> I keep meaning to get back to debugging it.

I believe Matt Anderson (CC'd) reported the bug you are referring to and the 
workaround I posted seemed to fix the issue for him.  I've stopped looking 
into this for the time being (I'm not much of an assembly level guy anyway) 
but I'd be very curious to hear about the root cause if you get an opportunity 
to narrow it down.

-- 
paul moore
linux @ hp

Re: Audit not recording the correct syscall return value in Fedora 10?

[Tony Jones]

On Tue, May 05, 2009 at 02:22:04PM -0400, Paul Moore wrote:
> I believe Matt Anderson (CC'd) reported the bug you are referring to and the 
> workaround I posted seemed to fix the issue for him.  I've stopped looking 

I'll check it out, I see the commit: 6d208da89aabee8502debe842832ca0ab298d16d

Thanks

Tony

Re: Audit not recording the correct syscall return value in Fedora 10?

[Paul Moore]

On Tuesday 05 May 2009 03:07:36 pm Tony Jones wrote:
> On Tue, May 05, 2009 at 02:22:04PM -0400, Paul Moore wrote:
> > I believe Matt Anderson (CC'd) reported the bug you are referring to and
> > the workaround I posted seemed to fix the issue for him.  I've stopped
> > looking
>
> I'll check it out, I see the commit:
> 6d208da89aabee8502debe842832ca0ab298d16d

Well, that commit does solve a return value problem on 64 bit systems but it 
isn't the workaround I was referring to ... the mail which I sent that started 
this thread (April 7, 2009) has a small patch to arch/x86/kernel/entry_64.S to 
load the return value directly from the stack and not %rax to workaround the 
corruption issue.

-- 
paul moore
linux @ hp

Re: Audit not recording the correct syscall return value in Fedora 10?

[Tony Jones]

On Tue, May 05, 2009 at 03:20:52PM -0400, Paul Moore wrote:
> On Tuesday 05 May 2009 03:07:36 pm Tony Jones wrote:
> > On Tue, May 05, 2009 at 02:22:04PM -0400, Paul Moore wrote:
> > > I believe Matt Anderson (CC'd) reported the bug you are referring to and
> > > the workaround I posted seemed to fix the issue for him.  I've stopped
> > > looking
> >
> > I'll check it out, I see the commit:
> > 6d208da89aabee8502debe842832ca0ab298d16d
> 
> Well, that commit does solve a return value problem on 64 bit systems but it 
> isn't the workaround I was referring to ... the mail which I sent that started 
> this thread (April 7, 2009) has a small patch to arch/x86/kernel/entry_64.S to 
> load the return value directly from the stack and not %rax to workaround the 
> corruption issue.

Sorry, my bad. I went back to grab the code snippet to check if it was in git
put pulled it from your earlier (Apr 1) thread by mistake. That said, I think 
it's the issue I'm seeing on x86_64 but I'll try the calling sequence fix also.

So what is the status of the entry_64.S fix? Did discussion go beyond this list?

Apologies for the confusion.

Tony

Re: Audit not recording the correct syscall return value in Fedora 10?

[Paul Moore]

On Tuesday 05 May 2009 03:34:43 pm Tony Jones wrote:
> On Tue, May 05, 2009 at 03:20:52PM -0400, Paul Moore wrote:
> > On Tuesday 05 May 2009 03:07:36 pm Tony Jones wrote:
> > > On Tue, May 05, 2009 at 02:22:04PM -0400, Paul Moore wrote:
> > > > I believe Matt Anderson (CC'd) reported the bug you are referring to
> > > > and the workaround I posted seemed to fix the issue for him.  I've
> > > > stopped looking
> > >
> > > I'll check it out, I see the commit:
> > > 6d208da89aabee8502debe842832ca0ab298d16d
> >
> > Well, that commit does solve a return value problem on 64 bit systems but
> > it isn't the workaround I was referring to ... the mail which I sent that
> > started this thread (April 7, 2009) has a small patch to
> > arch/x86/kernel/entry_64.S to load the return value directly from the
> > stack and not %rax to workaround the corruption issue.
>
> Sorry, my bad. I went back to grab the code snippet to check if it was in
> git put pulled it from your earlier (Apr 1) thread by mistake. That said, I
> think it's the issue I'm seeing on x86_64 but I'll try the calling sequence
> fix also.
>
> So what is the status of the entry_64.S fix? Did discussion go beyond this
> list?
>
> Apologies for the confusion.

No problem.  As far as I'm aware the discussion never went beyond this thread 
as I was unable to recreate the problem with the (then) current kernels but it 
may not be a bad idea to get the arch folks and perhaps lkml involved if we 
can narrow this down a little.

-- 
paul moore
linux @ hp

Re: Audit not recording the correct syscall return value in Fedora 10?

[Tony Jones]

On Tue, May 05, 2009 at 03:50:01PM -0400, Paul Moore wrote:

> No problem.  As far as I'm aware the discussion never went beyond this thread 
> as I was unable to recreate the problem with the (then) current kernels but it 
> may not be a bad idea to get the arch folks and perhaps lkml involved if we 
> can narrow this down a little.

Doesn't reproduce for me with 2.6.30-rc4-git1.

For our SLES11 kernel (2.6.27+patches) I needed your entry_64.S change to fix
the problem.

With just commit 6d208da89aabee8502debe842832ca0ab298d16d I get:

[snippet]

Starting auditd                                                      done
----
time->Thu May  7 12:51:46 2009
type=SYSCALL msg=audit(1241725906.513:121): arch=c000003e syscall=175 success=yes exit=0 a0=7f95478e2000 a1=1e18 a2=61a240 a3=61a240 items=0 ppid=4382 pid=4425 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=ttyS0 ses=1 comm="modprobe" exe="/sbin/modprobe" key=(null)
Shutting down auditd                                                 done
Starting auditd                                                      done
----
time->Thu May  7 12:51:46 2009
type=SYSCALL msg=audit(1241725906.768:128): arch=c000003e syscall=175 success=yes exit=0 a0=7f2425e10000 a1=1e18 a2=61a240 a3=61a240 items=0 ppid=4382 pid=4488 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=ttyS0 ses=1 comm="modprobe" exe="/sbin/modprobe" key=(null)
Shutting down auditd                                                 done
Starting auditd                                                      done
----
time->Thu May  7 12:51:47 2009
type=SYSCALL msg=audit(1241725907.024:135): arch=c000003e syscall=175 success=no exit=-131939334922280 a0=7f9901b9a000 a1=1e18 a2=61a240 a3=61a240 items=0 ppid=4382 pid=4551 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=ttyS0 ses=1 comm="modprobe" exe="/sbin/modprobe" key=(null)
Shutting down auditd                                                 done
Starting auditd                                                      done
----
time->Thu May  7 12:51:47 2009
type=SYSCALL msg=audit(1241725907.288:142): arch=c000003e syscall=175 success=no exit=-131939285508136 a0=7f0807b15000 a1=1e18 a2=61a240 a3=61a240 items=0 ppid=4382 pid=4614 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=ttyS0 ses=1 comm="modprobe" exe="/sbin/modprobe" key=(null)
Shutting down auditd                                                 done
Starting auditd                                                      done
----
time->Thu May  7 12:51:47 2009
type=SYSCALL msg=audit(1241725907.544:149): arch=c000003e syscall=175 success=yes exit=0 a0=7f053f482000 a1=1e18 a2=61a240 a3=61a240 items=0 ppid=4382 pid=4677 auid=0 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=ttyS0 ses=1 comm="modprobe" exe="/sbin/modprobe" key=(null)
Shutting down auditd 


test case:

for i in `seq 1 100`; do cat /dev/null > /var/log/audit/audit.log;  rmmod dummy; rcauditd restart; auditctl -a entry,always -S init_module; modprobe dummy; ausearch -c modprobe; done

This is on a Core2Duo.

Tony

Re: Audit not recording the correct syscall return value in Fedora 10?

[Paul Moore]

On Thursday 07 May 2009 07:05:00 pm Tony Jones wrote:
> On Tue, May 05, 2009 at 03:50:01PM -0400, Paul Moore wrote:
> > No problem.  As far as I'm aware the discussion never went beyond this
> > thread as I was unable to recreate the problem with the (then) current
> > kernels but it may not be a bad idea to get the arch folks and perhaps
> > lkml involved if we can narrow this down a little.
>
> Doesn't reproduce for me with 2.6.30-rc4-git1.

Well, since neither one of us can reproduce it on recent kernels it looks like 
the root cause either went away, the problem was resolved or we are just 
getting lucky with a timing windows somewhere.  Sigh.

I guess I should just be happy it is no longer happening :)

> For our SLES11 kernel (2.6.27+patches) I needed your entry_64.S change to
> fix the problem.

I also wonder about other arches, heck, even 32 bit x86.

> With just commit 6d208da89aabee8502debe842832ca0ab298d16d I get:
>
> [snippet]

[snippet snipped]

Yes, I wouldn't expect the above commit to resolve the modprobe issue that 
Matt reported since init_module returns an int.  The commit above should only 
matter when the syscall returns a 64 bit value (long, etc.) on a 64 bit 
system.

-- 
paul moore
linux @ hp