2:37 p.m.
Hi,
I was looking into a problem from the test team and ran across this comment in
the kernel code:
http://lxr.linux.no/source/kernel/auditsc.c#L652
It basically says that audit records may be emitted as event records are
generated as opposed to syscall exit. The problem shows up during stress
testing. The records that get sent from the kernel are no where close to each
other and are hard to correlate.
The comment says that if the current technique isn't suitable, maybe we can
keep formatted records off of the context and then send them all at syscall
exit.
Can anyone see any problems with changing this?
-Steve
2:42 p.m.
On Thu, 2005-05-05 at 15:37 -0400, Steve Grubb wrote:
Hi,
I was looking into a problem from the test team and ran across this comment in
the kernel code:
http://lxr.linux.no/source/kernel/auditsc.c#L652
It basically says that audit records may be emitted as event records are
generated as opposed to syscall exit. The problem shows up during stress
testing. The records that get sent from the kernel are no where close to each
other and are hard to correlate.
The comment says that if the current technique isn't suitable, maybe we can
keep formatted records off of the context and then send them all at syscall
exit.
Can anyone see any problems with changing this?
The comment is primarily addressed to other users of the audit
subsystem, like SELinux, which immediately generate audit records of
their own rather than saving their data in the current audit context for
later processing by audit_log_exit. For all other audit generation, it
should all occur from audit_log_exit IIUC. However, audit_log_exit()
presently uses several audit_log_start()...audit_log_end() sequences
rather than a single one, which does split up the syscall audit record
information. I'm not entirely sure why it doesn't just bracket the
entire body of audit_log_exit() with a single audit_log_start
();....audit_log_end(); sequence.
--
Stephen Smalley <sds(a)tycho.nsa.gov>
National Security Agency
3:02 p.m.
On Thursday 05 May 2005 15:42, Stephen Smalley wrote:
For all other audit generation, it should all occur from
audit_log_exit
IIUC.
That's kind of what I'm counting on.
However, audit_log_exit() presently uses several
audit_log_start()...audit_log_end() sequences rather than a single one,
which does split up the syscall audit record information.
I don't think this explains what we saw in the records. The records seemed
like they had multiple parts, were intertwined, and separated by a long
distance. Here is a sample:
type=KERNEL msg=audit(1114290222.457:10672815): syscall=83 arch=c000003e
success=yes exit=0 a0=7fbffffb80 a1=1ff a2=402136 a3=0 items=1 pid=22754
loginuid=500 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0
comm="stress1_test"
exe=/rhcc/eal4/tests/LTP/ltp-full/testcases/audit/stress/stress1_test
type=KERNEL msg=audit(1114290222.582:10674541): item=0 name="stress2_dir"
inode=3440760 dev=fd:00 mode=040755 uid=0 gid=0 rdev=00:00
type=KERNEL msg=audit(1114290222.581:10674530): item=0 name="stress2_dir"
type=KERNEL msg=audit(1114290222.579:10674506): syscall=90 arch=c000003e
success=no exit=-2 a0=7fbffffc30 a1=0 a2=ffffffffffffffc0 a3=7 items=1
pid=22791 loginuid=500 uid=500 gid=500 euid=500 suid=500 fsuid=500 egid=500
sgid=500 fsgid=500 comm="stress2_test"
exe=/rhcc/eal4/tests/LTP/ltp-full/testcases/audit/stress/stress2_test
type=KERNEL msg=audit(1114290222.559:10673854): item=0 name="stress1_dir"
inode=3441012 dev=fd:00 mode=040755 uid=0 gid=0 rdev=00:00
type=KERNEL msg=audit(1114290222.558:10673842): item=0 name="stress1_dir"
inode=3441012 dev=fd:00 mode=040755 uid=0 gid=0 rdev=00:00
type=KERNEL msg=audit(1114290222.557:10673830): item=0 name="stress1_dir"
inode=3441012 dev=fd:00 mode=040755 uid=0 gid=0 rdev=00:00
type=KERNEL msg=audit(1114290222.556:10673818): item=0 name="stress1_dir"
inode=3441012 dev=fd:00 mode=040755 uid=0 gid=0 rdev=00:00
type=KERNEL msg=audit(1114290222.555:10673807): syscall=84 arch=c000003e
success=yes exit=0 a0=7fbffffb80 a1=3a834c1d99 a2=3a834c1d99
a3=5f31737365727473 items=1 pid=22754 loginuid=500 uid=0 gid=0 euid=0 suid=0
fsuid=0 egid=0 sgid=0 fsgid=0 comm="stress1_test"
exe=/rhcc/eal4/tests/LTP/ltp-full/testcases/audit/stress/stress1_test
type=KERNEL msg=audit(1114290222.543:10673805): item=0 name="stress1_dir"
inode=3440760 dev=fd:00 mode=040755 uid=0 gid=0 rdev=00:00
type=KERNEL msg=audit(1114290222.542:10673795): item=0 name="stress1_dir"
inode=3440760 dev=fd:00 mode=040755 uid=0 gid=0 rdev=00:00
type=KERNEL msg=audit(1114290222.541:10673794): item=0 name="stress1_dir"
inode=3441012 dev=fd:00 mode=040755 uid=0 gid=0 rdev=00:00
type=KERNEL msg=audit(1114290222.541:10673783): syscall=84 arch=c000003e
success=yes exit=0 a0=7fbffffb80 a1=3a834c1d99 a2=3a834c1d99
a3=5f31737365727473 items=1 pid=22754 loginuid=500 uid=0 gid=0 euid=0 suid=0
fsuid=0 egid=0 sgid=0 fsgid=0 comm="stress1_test"
exe=/rhcc/eal4/tests/LTP/ltp-full/testcases/audit/stress/stress1_test
The second record has a serial of 10674541. Where's the rest of it? Kris has a
stress test that generated these records.
-Steve
3:39 p.m.
* Steve Grubb (sgrubb(a)redhat.com) wrote:
On Thursday 05 May 2005 15:42, Stephen Smalley wrote:
> For all other audit generation, it should all occur from audit_log_exit
> IIUC.
That's kind of what I'm counting on.
> However, audit_log_exit() presently uses several
>audit_log_start()...audit_log_end() sequences rather than a single one,
> which does split up the syscall audit record information.
I don't think this explains what we saw in the records. The records seemed
like they had multiple parts, were intertwined, and separated by a long
distance. Here is a sample:
This is partly possible because a single message (i.e. a single
audit_log_start...audit_log_end sequence) can span skb's. There's no
serialization so skb's can easily become interleaved. And, auditd will
drop subsequent skb's because the netlink header is bogus. I'll send
out the updates I have to this area shortly. I'm interested if it helps.
type=KERNEL msg=audit(1114290222.457:10672815): syscall=83
arch=c000003e
success=yes exit=0 a0=7fbffffb80 a1=1ff a2=402136 a3=0 items=1 pid=22754
loginuid=500 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0
comm="stress1_test"
exe=/rhcc/eal4/tests/LTP/ltp-full/testcases/audit/stress/stress1_test
type=KERNEL msg=audit(1114290222.582:10674541): item=0 name="stress2_dir"
inode=3440760 dev=fd:00 mode=040755 uid=0 gid=0 rdev=00:00
type=KERNEL msg=audit(1114290222.581:10674530): item=0 name="stress2_dir"
type=KERNEL msg=audit(1114290222.579:10674506): syscall=90 arch=c000003e
success=no exit=-2 a0=7fbffffc30 a1=0 a2=ffffffffffffffc0 a3=7 items=1
pid=22791 loginuid=500 uid=500 gid=500 euid=500 suid=500 fsuid=500 egid=500
sgid=500 fsgid=500 comm="stress2_test"
exe=/rhcc/eal4/tests/LTP/ltp-full/testcases/audit/stress/stress2_test
type=KERNEL msg=audit(1114290222.559:10673854): item=0 name="stress1_dir"
inode=3441012 dev=fd:00 mode=040755 uid=0 gid=0 rdev=00:00
type=KERNEL msg=audit(1114290222.558:10673842): item=0 name="stress1_dir"
inode=3441012 dev=fd:00 mode=040755 uid=0 gid=0 rdev=00:00
type=KERNEL msg=audit(1114290222.557:10673830): item=0 name="stress1_dir"
inode=3441012 dev=fd:00 mode=040755 uid=0 gid=0 rdev=00:00
type=KERNEL msg=audit(1114290222.556:10673818): item=0 name="stress1_dir"
inode=3441012 dev=fd:00 mode=040755 uid=0 gid=0 rdev=00:00
type=KERNEL msg=audit(1114290222.555:10673807): syscall=84 arch=c000003e
success=yes exit=0 a0=7fbffffb80 a1=3a834c1d99 a2=3a834c1d99
a3=5f31737365727473 items=1 pid=22754 loginuid=500 uid=0 gid=0 euid=0 suid=0
fsuid=0 egid=0 sgid=0 fsgid=0 comm="stress1_test"
exe=/rhcc/eal4/tests/LTP/ltp-full/testcases/audit/stress/stress1_test
type=KERNEL msg=audit(1114290222.543:10673805): item=0 name="stress1_dir"
inode=3440760 dev=fd:00 mode=040755 uid=0 gid=0 rdev=00:00
type=KERNEL msg=audit(1114290222.542:10673795): item=0 name="stress1_dir"
inode=3440760 dev=fd:00 mode=040755 uid=0 gid=0 rdev=00:00
type=KERNEL msg=audit(1114290222.541:10673794): item=0 name="stress1_dir"
inode=3441012 dev=fd:00 mode=040755 uid=0 gid=0 rdev=00:00
type=KERNEL msg=audit(1114290222.541:10673783): syscall=84 arch=c000003e
success=yes exit=0 a0=7fbffffb80 a1=3a834c1d99 a2=3a834c1d99
a3=5f31737365727473 items=1 pid=22754 loginuid=500 uid=0 gid=0 euid=0 suid=0
fsuid=0 egid=0 sgid=0 fsgid=0 comm="stress1_test"
exe=/rhcc/eal4/tests/LTP/ltp-full/testcases/audit/stress/stress1_test
The second record has a serial of 10674541. Where's the rest of it? Kris has a
stress test that generated these records.
-Steve
--
Linux-audit mailing list
Linux-audit(a)redhat.com
http://www.redhat.com/mailman/listinfo/linux-audit
--
Linux Security Modules http://lsm.immunix.org http://lsm.bkbits.net
2:52 p.m.
Steve Grubb wrote:
It basically says that audit records may be emitted as event records
are
generated as opposed to syscall exit. The problem shows up during stress
testing. The records that get sent from the kernel are no where close to each
other and are hard to correlate.
I've been using ausearch to find things and it seems to do a nice
job of putting the pieces together. Maybe we need an option to
dump everything, or maybe have an aucat command? Or are you finding
that under the stress testing, the ausearch command doesn't work well
because the records are so far apart?
-- ljk
3:04 p.m.
On Thursday 05 May 2005 15:52, Linda Knippers wrote:
I've been using ausearch to find things and it seems to do a
nice
job of putting the pieces together.
That kind of counts on records being dumped together.
Maybe we need an option to dump everything, or maybe have an aucat
command?
We are only having one utility to do this.
Or are you finding that under the stress testing, the ausearch
command
doesn't work well because the records are so far apart?
Its more a question of what is the kernel doing? I sent a sample in another
reply.
-Steve
7171
days inactive
7171
days old
linux-audit@lists.linux-audit.osci.io
5 comments
4 participants
participants (4)
-
Chris Wright -
Linda Knippers -
Stephen Smalley -
Steve Grubb