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

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?

index a331ec3..16db517 100644
@@ -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

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 <[email protected]>
Linux Security Development, IBM Linux Technology Center

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.

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

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

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

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

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

Thanks

Tony

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

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

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

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

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 :)

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

[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