4:23 p.m.
Running the Fedora devel tree as of a few days ago, and a 2.6.16-rc5-mm3 kernel.
Several times today, my laptop has seized up, with the 'disk activity' light
on solid. After 30 to 120 seconds, it returns. Some poking around after
the last hit finds this:
# ls -l /var/log/audit/
total 25423
-rw-r----- 1 root root 1799972 Mar 14 17:11 audit.log
-r--r----- 1 root root 5242905 Mar 14 17:06 audit.log.1
-r--r----- 1 root root 5242919 Mar 14 17:05 audit.log.2
-r--r----- 1 root root 5242943 Mar 14 15:11 audit.log.3
-r--r----- 1 root root 8388705 Oct 3 14:59 audit.log.4
Wow, something happened at 17:06 or so that caused it to roll through 5 meg of
audit in a minute. So let's take a look at it:
# ausearch -if /var/log/audit/audit.log.1 | uniq -c | more
1 ----
1 time->Wed Dec 31 19:00:00 1969
1526 type=SOCKETCALL msg=audit(0.000:267): nargs=3 a0=4 a1=bfb7a4f8 a2=bfb7a4a0
1 ----
1 time->Wed Dec 31 19:00:00 1969
2 type=SOCKETCALL msg=audit(0.000:272): nargs=3 a0=2 a1=2 a2=0
1 type=SYSCALL_PARTIAL msg=audit(0.000:272): success=yes exit=14 items=0 pid=9616
auid=967 uid=967 gid=967 euid=967 suid=967 fsuid=967 egid=967 sgid=967 fsgid=967
tty=(none) comm="gkrellm" exe="/usr/bin/gkrellm"
subj=user_u:user_r:user_t:s0
1 type=AVC msg=audit(0.000:272): avc: denied { create } for pid=9616
comm="gkrellm" scontext=user_u:user_r:user_t:s0 tcontext=user_u:user_r:user_t:s0
tclass=udp_socket
1 ----
1 time->Wed Dec 31 19:00:00 1969
94 type=SOCKETCALL msg=audit(0.000:267): nargs=3 a0=4 a1=bfb7a4f8 a2=bfb7a4a0
1 ----
1 time->Wed Dec 31 19:00:00 1969
190 type=SOCKETCALL msg=audit(0.000:272): nargs=3 a0=2 a1=2 a2=0
1 ----
1 time->Wed Dec 31 19:00:00 1969
294 type=SOCKETCALL msg=audit(0.000:267): nargs=3 a0=4 a1=bfb7a4f8 a2=bfb7a4a0
1 ----
1 time->Wed Dec 31 19:00:00 1969
157 type=SOCKETCALL msg=audit(0.000:272): nargs=3 a0=2 a1=2 a2=0
1 ----
1 time->Wed Dec 31 19:00:00 1969
205 type=SOCKETCALL msg=audit(0.000:267): nargs=3 a0=4 a1=bfb7a4f8 a2=bfb7a4a0
1 ----
1 time->Wed Dec 31 19:00:00 1969
149 type=SOCKETCALL msg=audit(0.000:272): nargs=3 a0=2 a1=2 a2=0
1 ----
1 time->Wed Dec 31 19:00:00 1969
39 type=SOCKETCALL msg=audit(0.000:267): nargs=3 a0=4 a1=bfb7a4f8 a2=bfb7a4a0
1 ----
1 time->Wed Dec 31 19:00:00 1969
147 type=SOCKETCALL msg=audit(0.000:272): nargs=3 a0=2 a1=2 a2=0
1 ----
1 time->Wed Dec 31 19:00:00 1969
189 type=SOCKETCALL msg=audit(0.000:267): nargs=3 a0=4 a1=bfb7a4f8 a2=bfb7a4a0
1 ----
1 time->Wed Dec 31 19:00:00 1969
248 type=SOCKETCALL msg=audit(0.000:272): nargs=3 a0=2 a1=2 a2=0
<here we skip several hundred more of these>
1 ----
1 time->Wed Dec 31 19:00:00 1969
296 type=SOCKETCALL msg=audit(0.000:267): nargs=3 a0=4 a1=bfb7a4f8 a2=bfb7a4a0
1 ----
1 time->Wed Dec 31 19:00:00 1969
1 type=AVC_PATH msg=audit(0.000:272): path="socket:[782960]"
1 type=SYSCALL_PARTIAL msg=audit(0.000:272): success=yes exit=0 items=0 pid=9616
auid=967 uid=967 gid=967 euid=967 suid=967 fsuid=967 egid=967 sgid=967 fsgid=967
tty=(none) comm="gkrellm" exe="/usr/bin/gkrellm"
subj=user_u:user_r:user_t:s0
1 type=AVC msg=audit(0.000:272): avc: denied { ioctl } for pid=9616
comm="gkrellm" name="[782960]" dev=sockfs ino=782960
scontext=user_u:user_r:user_t:s0 tcontext=user_u:user_r:user_t:s0 tclass=udp_socket
1 ----
1 time->Wed Dec 31 19:00:00 1969
42 type=SOCKETCALL msg=audit(0.000:267): nargs=3 a0=4 a1=bfb7a4f8 a2=bfb7a4a0
1 type=SOCKETCALL msg=audit(0.000:267): nargs=5 a0=b a1=1 a2=7 a3=bfb7a408 a4=4
1 type=SOCKETCALL msg=audit(0.000:267): nargs=5 a0=b a1=1 a2=8 a3=bfb7a408 a4=4
198 type=SOCKETCALL msg=audit(0.000:267): nargs=3 a0=4 a1=bfb7a4f8 a2=bfb7a4a0
1 type=SOCKETCALL msg=audit(0.000:267): nargs=3 a0=1 a1=1 a2=0
1 type=SOCKETCALL msg=audit(0.000:267): nargs=3 a0=7 a1=bfb79c90 a2=27
1 type=SOCKADDR msg=audit(0.000:267):
saddr=01002F746D702F616C73612D646D69782D393632352D313134323337313131372D373837303635
1 type=SOCKETCALL msg=audit(0.000:267): nargs=2 a0=7 a1=4
194 type=SOCKETCALL msg=audit(0.000:267): nargs=3 a0=4 a1=bfb7a4f8 a2=bfb7a4a0
1 type=SOCKETCALL msg=audit(0.000:267): nargs=5 a0=7 a1=1 a2=7 a3=bfb7a468 a4=4
1 type=SOCKETCALL msg=audit(0.000:267): nargs=5 a0=7 a1=1 a2=8 a3=bfb7a468 a4=4
3 type=SOCKETCALL msg=audit(0.000:267): nargs=3 a0=4 a1=bfb7a4f8 a2=bfb7a4a0
1 type=SOCKETCALL msg=audit(0.000:267): nargs=5 a0=7 a1=1 a2=7 a3=bfb7a408 a4=4
1 type=SOCKETCALL msg=audit(0.000:267): nargs=5 a0=7 a1=1 a2=8 a3=bfb7a408 a4=4
1 type=SOCKETCALL msg=audit(0.000:267): nargs=3 a0=1 a1=1 a2=0
1 type=SOCKETCALL msg=audit(0.000:267): nargs=3 a0=8 a1=bfb79c90 a2=27
1 type=SOCKADDR msg=audit(0.000:267):
saddr=01002F746D702F616C73612D646D69782D393632352D313134323337313133322D383030303731
1 type=SOCKETCALL msg=audit(0.000:267): nargs=2 a0=8 a1=4
852 type=SOCKETCALL msg=audit(0.000:267): nargs=3 a0=4 a1=bfb7a4f8 a2=bfb7a4a0
Obviously looks like something is getting seriously stuck and replicating messages.
Plus, it looks like there's some basic info missing on the 'type=SOCKETCALL',
like the issuing process ID, etc....
4:37 p.m.
On Tuesday 14 March 2006 17:23, Valdis.Kletnieks(a)vt.edu wrote:
Obviously looks like something is getting seriously stuck and
replicating
messages.
Plus, it looks like there's some basic info missing on the
'type=SOCKETCALL', like the issuing process ID, etc....
Hmm. I wonder who's guilty. Its either kernel or userspace. One way to cut the
problem in half is to let messages go to syslog, but still load the audit
rules. I'd alter the initscript to not start it.
I wonder if this has anything to do with the mutex conversion...or something
entirely different. I also notice that you have some things out of order.
events 267 & 272 get intertwined.
-Steve
5:02 p.m.
On Tue, 14 Mar 2006 17:37:48 EST, Steve Grubb said:
Hmm. I wonder who's guilty. Its either kernel or userspace. One
way to cut the
problem in half is to let messages go to syslog, but still load the audit
rules. I'd alter the initscript to not start it.
I've managed to trigger it every few hours (3 times since I got to work today,
and several times yesterday), so I'll give that a try.
I wonder if this has anything to do with the mutex conversion...or
something
entirely different. I also notice that you have some things out of order.
events 267 & 272 get intertwined.
Yes, if it hadn't intertwined them, we'd just have gotten about 3,000 copies of
event 267, and then 3,000 or so of 272. But I suspect the intertwining and the
duplicating are both symptoms of the same root fault....
And the "time->Wed Dec 31 19:00:00 1969" parts are odd, too, considering
that
the machine in question is NTP-synced and has a sane clock....
5:06 p.m.
On Tue, 14 Mar 2006 17:37:48 EST, Steve Grubb said:
On Tuesday 14 March 2006 17:23, Valdis.Kletnieks(a)vt.edu wrote:
> Obviously looks like something is getting seriously stuck and replicating
> messages.
>
> Plus, it looks like there's some basic info missing on the
> 'type=SOCKETCALL', like the issuing process ID, etc....
Hmm. I wonder who's guilty. Its either kernel or userspace. One way to cut th
e
problem in half is to let messages go to syslog, but still load the
audit
rules. I'd alter the initscript to not start it.
Yee. Hah. Didn't take but a little time, and suddenly the disk lit up
again - this time it was syslogd scribbling, so it looks like a 2.6.15-rc5-mm3
issue:
Mar 14 18:02:09 turing-police kernel: [21744.040000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
Mar 14 18:02:10 turing-police last message repeated 16 times
Mar 14 18:02:10 turing-police kernel: [21744.044000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
Mar 14 18:02:10 turing-police last message repeated 91 times
Mar 14 18:02:10 turing-police kernel: [21744.048000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
Mar 14 18:02:10 turing-police last message repeated 107 times
Mar 14 18:02:10 turing-police kernel: [21744.052000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
Mar 14 18:02:10 turing-police last message repeated 94 times
Mar 14 18:02:10 turing-police kernel: [21744.056000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
Mar 14 18:02:10 turing-police last message repeated 108 times
Mar 14 18:02:10 turing-police kernel: [21744.060000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
Mar 14 18:02:10 turing-police last message repeated 87 times
Mar 14 18:02:10 turing-police kernel: [21744.060000] audit(0.000:267): nargs=2 a0=7 a1=4
Mar 14 18:02:10 turing-police kernel: [21744.060000] audit(0.000:267):
saddr=01002F746D702F616C73612D646D69782D393632352D313134323337373332322D363335303934
Mar 14 18:02:10 turing-police kernel: [21744.060000] audit(0.000:267): nargs=3 a0=7
a1=bfb79c90 a2=27
Mar 14 18:02:10 turing-police kernel: [21744.060000] audit(0.000:267): nargs=3 a0=1 a1=1
a2=0
Mar 14 18:02:10 turing-police kernel: [21744.064000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
Mar 14 18:02:10 turing-police last message repeated 108 times
Mar 14 18:02:10 turing-police kernel: [21744.068000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
Mar 14 18:02:10 turing-police last message repeated 97 times
Mar 14 18:02:10 turing-police kernel: [21744.072000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
Mar 14 18:02:10 turing-police last message repeated 64 times
Mar 14 18:02:10 turing-police kernel: [21744.072000] audit(0.000:267): nargs=3 a0=7
a1=bfb79cd4 a2=0
Mar 14 18:02:10 turing-police kernel: [21744.072000] audit(0.000:267): nargs=3 a0=7
a1=bfb79cd4 a2=0
Mar 14 18:02:10 turing-police kernel: [21744.072000] audit(0.000:267):
saddr=01002F746D702F616C73612D646D69782D393632352D313134323337373234352D323032303434
Mar 14 18:02:10 turing-police kernel: [21744.072000] audit(0.000:267): nargs=3 a0=7
a1=bfb79ca0 a2=27
Mar 14 18:02:10 turing-police kernel: [21744.072000] audit(0.000:267): nargs=3 a0=1 a1=1
a2=0
Mar 14 18:02:10 turing-police kernel: [21744.072000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
Mar 14 18:02:10 turing-police last message repeated 40 times
Mar 14 18:02:10 turing-police kernel: [21744.076000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
Mar 14 18:02:10 turing-police last message repeated 102 times
Mar 14 18:02:10 turing-police kernel: [21744.080000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
Mar 14 18:02:10 turing-police last message repeated 99 times
Mar 14 18:02:10 turing-police kernel: [21744.080000] audit(0.000:267): nargs=2 a0=7 a1=4
Mar 14 18:02:10 turing-police kernel: [21744.080000] audit(0.000:267):
saddr=01002F746D702F616C73612D646D69782D393632352D313134323337373234352D323032303434
Mar 14 18:02:10 turing-police kernel: [21744.080000] audit(0.000:267): nargs=3 a0=7
a1=bfb79c90 a2=27
Mar 14 18:02:10 turing-police kernel: [21744.080000] audit(0.000:267): nargs=3 a0=1 a1=1
a2=0
Mar 14 18:02:10 turing-police kernel: [21744.080000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
Mar 14 18:02:10 turing-police last message repeated 5 times
Mar 14 18:02:10 turing-police kernel: [21744.084000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
Mar 14 18:02:10 turing-police last message repeated 91 times
Mar 14 18:02:10 turing-police kernel: [21744.088000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
Mar 14 18:02:10 turing-police last message repeated 106 times
Mar 14 18:02:10 turing-police kernel: [21744.092000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
Mar 14 18:02:10 turing-police last message repeated 89 times
Mar 14 18:02:10 turing-police kernel: [21744.092000] audit(0.000:267): nargs=2 a0=7 a1=4
Mar 14 18:02:10 turing-police kernel: [21744.092000] audit(0.000:267):
saddr=01002F746D702F616C73612D646D69782D393632352D313134323337373233372D363635333438
Mar 14 18:02:10 turing-police kernel: [21744.092000] audit(0.000:267): nargs=3 a0=7
a1=bfb79c90 a2=27
Mar 14 18:02:10 turing-police kernel: [21744.092000] audit(0.000:267): nargs=3 a0=1 a1=1
a2=0
Mar 14 18:02:10 turing-police kernel: [21744.092000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
Mar 14 18:02:10 turing-police last message repeated 6 times
Mar 14 18:02:10 turing-police kernel: [21744.096000] audit(0.000:267): nargs=3 a0=4
a1=bfb7a4f8 a2=bfb7a4a0
That's the first second or so of the spew, which continued until 18:02:33.
Interesting that the event is *again* 267......
5:11 p.m.
On Tuesday 14 March 2006 18:06, Valdis.Kletnieks(a)vt.edu wrote:
Yee. Hah. Didn't take but a little time, and suddenly the disk
lit up
again - this time it was syslogd scribbling, so it looks like a
2.6.15-rc5-mm3 issue
FWIW, I wonder if the same thing happens with lspp.12 kernel. I know what's in
lspp.12, but I don't know what all's in -mm.
-Steve
8:30 a.m.
On Tuesday 14 March 2006 18:06, Valdis.Kletnieks(a)vt.edu wrote:
Mar 14 18:02:09 turing-police kernel: [21744.040000]
audit(0.000:267):
nargs=3 a0=4 a1=bfb7a4f8 a2=bfb7a4a0 Mar 14 18:02:10 turing-police last
message repeated 16 times
I think I found the problem with time being 0.000. I'm still looking for the
reason why so many of these were spit out.
-Steve
11:52 a.m.
On Wed, 15 Mar 2006 09:30:34 EST, Steve Grubb said:
On Tuesday 14 March 2006 18:06, Valdis.Kletnieks(a)vt.edu wrote:
> Mar 14 18:02:09 turing-police kernel: [21744.040000] audit(0.000:267):
> nargs=3 a0=4 a1=bfb7a4f8 a2=bfb7a4a0 Mar 14 18:02:10 turing-police last
> message repeated 16 times
I think I found the problem with time being 0.000. I'm still looking for the
reason why so many of these were spit out.
Following up on this one...
1) The msg flood problem is still present in 2.6.16-mm1.
2) Your patch to set ctx->ctime isn't in 2.6.12-mm1, and does fix the 0.000 time
problem, but doesn't fix the msg flood problem.
3) It *does* seem related to the kernel throwing an AVC message - I'm only
using auditd to catch avc's at the moment....
12:16 p.m.
On Friday 24 March 2006 12:52, Valdis.Kletnieks(a)vt.edu wrote:
1) The msg flood problem is still present in 2.6.16-mm1.
We dropped the patch from the main branch of audit git tree. I would think
that it should be dropped in mm tree whenever its refreshed against audit git
tree.
2) Your patch to set ctx->ctime isn't in 2.6.12-mm1, and does
fix the 0.000
time problem, but doesn't fix the msg flood problem.
True. We need to look deeper into what went wrong.
Thanks,
-Steve
6847
days inactive
6857
days old
linux-audit@lists.linux-audit.osci.io
7 comments
2 participants
participants (2)
-
Steve Grubb -
Valdis.Kletnieks＠vt.edu