10:34 a.m.
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
9:44 p.m.
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(a)linux.vnet.ibm.com>
Linux Security Development, IBM Linux Technology Center
4:38 p.m.
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
1:15 p.m.
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
1:08 p.m.
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
1:22 p.m.
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
2:07 p.m.
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
2:20 p.m.
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
2:34 p.m.
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
2:50 p.m.
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
6:05 p.m.
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
8:22 a.m.
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
5706
days inactive
5737
days old
linux-audit@lists.linux-audit.osci.io
11 comments
3 participants
participants (3)
-
Klaus Heinrich Kiwi -
Paul Moore -
Tony Jones