Problem with auditd/SnareLinux on RHEL 5.3 - auditd glomming memory

Problem with auditd/SnareLinux on RHEL 5.3 - auditd glomming memory

[Smith, Gary R]

[-- Attachment #1.1: Type: text/plain, Size: 5082 bytes --]

Hello All,

I have some systems that have just been updated to from RHEL 5.2 to RHEL
5.3. The version of auditd is 1.7.7 and SnareLinux is 1.5.0.

Some time after the update ran, I noticed that the amount of free memory
on the systems had dramatically gone down. Running top, I saw that
auditd had sucked up lots of memory:

top - 09:25:59 up 2 days, 2 min,  1 user,  load average: 0.00, 0.03,
0.00
Tasks: 111 total,   1 running, 110 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.1%us,  0.1%sy,  0.0%ni, 99.8%id,  0.0%wa,  0.0%hi,  0.1%si,
0.0%st
Mem:   4043368k total,  3994488k used,    48880k free,    64656k buffers
Swap:  8385920k total,      352k used,  8385568k free,   449884k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND

31136 root      12  -3 6568m 3.1g  568 S  0.0 81.0   0:08.84 auditd

 3861 root      15   0 26152  16m  364 S  0.0  0.4   0:00.01 restorecond

29474 root      16   0 97.9m  14m 2852 S  0.0  0.4   0:00.16 sshd

29382 root      17   0  124m  13m 1464 S  0.0  0.3   0:00.09 crond

29478 gsmith    15   0 97.9m  12m  976 S  0.0  0.3   0:00.01 sshd

 5611 root      15   0 58912 9048 4208 S  0.0  0.2   3:50.38 dsmc

 3937 root      15   0 96556 7588  916 S  0.0  0.2   3:54.00 sec.pl    

When I first started looking at the problem, I figured the easiest fix
was reboot since a new version of auditd was installed along with a new
kernel and there was a mismatch between the auditd daemon and the
running kernel. After rebooting, I watched a 'top' display and did not
see the auditd daemon percolate up. It turns out that it does percolate
up to the top of the memory usage; I didn't watch it long enough.

I wondered if there was a difference between 32 bit and 64 bit systems.
As it turns out, there isn't one; it's seems to be slower to happen on
32 bit systems probably due to slower CPU's 

Next, I wondered if this is due to the version of Snare running on the
systems. Just to be sure, I rebuilt Snare for the 64 bit system,
de-installed Snare, installed the newly rebuilt Snare, and started
auditd. Again, the auditd daemon started to percolate to the top of the
memory usage.

So, does this have anything to do with the number of rules that auditd
has to deal with? I started trimming back the rules one at a time,
restarting auditd and watching a top display. The number of rules
doesn't have any affect until you get to zero rules and then auditd
doesn't move up.

Next, I ran a valgrind on auditd; one on a RHEL 5.3 system with no rules
and another one with the standard set of rules put on our systems. 

criticality=0   event=execve    uid=*,root
criticality=1   event=(mount,umount,umount2,settimeofday,swapon,swapoff,
reboot,setdomainname,create_module,delete_module,quotactl)
uid=*,root
criticality=2   event=execve    exe=*passwd*
criticality=3   event=(login_auth,login_start,logout)
criticality=4   event=acct_mgmt

After 2 hours of running the former had 0 malloc/free problems with the
leak summary. The latter on the other hand:
==30021==
==30021== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 4 from 1)
==30021== malloc/free: in use at exit: 147,024,501 bytes in 16,262
blocks.
==30021== malloc/free: 27,612 allocs, 11,350 frees, 249,669,818 bytes
allocated.
==30021== For counts of detected errors, rerun with: -v ==30021==
searching for pointers to 16,262 not-freed blocks.
==30021== checked 10,651,128 bytes.
==30021==
==30021== LEAK SUMMARY:
==30021==    definitely lost: 146,976,704 bytes in 16,246 blocks.
==30021==      possibly lost: 36,464 bytes in 5 blocks.
==30021==    still reachable: 11,333 bytes in 11 blocks.
==30021==         suppressed: 0 bytes in 0 blocks.

Next, I ran a strace of auditd to see if I could spot where it was doing
all the malloc's. Starting up a strace of fresh instance of auditd,
eventually auditd settled into this loop:

clock_gettime(CLOCK_MONOTONIC, {432334, 891462998}) = 0 
epoll_wait(0, {{EPOLLIN, {u32=3, u64=3}}}, 64, 59743) = 1 
clock_gettime(CLOCK_MONOTONIC, {432334, 891681998}) = 0 
recvfrom(3, "&\0\0\0\33\5\0\0\0\0\0\0\0\0\0\0audit(1233595754"..., 8988,
MSG_DONTWAIT, {sa_family=AF_NETLINK, pid=0, groups=00000000}, [12]) = 54

writev(5, [{"\0\0\0\0\20\0\0\0\33\5\0\0&\0\0\0", 16},
{"audit(1233595754.282:836040):  c"..., 38}], 2) = 54

And so it goes. Nothing leaps out at me from this tight code sequence
that it's glomming memory.

I wondered if this odd behavior was exhibited back in RHEL 5.2 and we
just never noticed. So, I installed RHEL 5.2 in a virtual machine,
installed all the patches, and installed Snare. After several hours of
going at it, auditd has not moved up the chart at all. 

So, it appears to be an auditd/Snare interaction on RHEL 5.3. I have a
RHEL 5.3 system on which I'm experimenting with auditd, rulesets and
prelude (no Snare). The ruleset has a lot of rules in it by comparison
(> 200) and everybody is well-behaved. 


Any thoughts on what may be happening?

Best Regards,

Gary Smith


[-- Attachment #1.2: Type: text/html, Size: 13198 bytes --]

[-- Attachment #2: Type: text/plain, Size: 0 bytes --]

Re: Problem with auditd/SnareLinux on RHEL 5.3 - auditd glomming memory

[Lucas C. Villa Real]

2009/2/4 Smith, Gary R <gary.smith@pnl.gov>:
> Hello All,

Hi, Gary

> I have some systems that have just been updated to from RHEL 5.2 to RHEL
> 5.3. The version of auditd is 1.7.7 and SnareLinux is 1.5.0.
>
> Some time after the update ran, I noticed that the amount of free memory on
> the systems had dramatically gone down. Running top, I saw that auditd had
> sucked up lots of memory:

[...]

One quick question: are you having lots of events getting logged in
/var/log/audit/audit.log when memory increases?

I noticed a very similar behavior when the system was under high
stress (ie: having many rules and many remote clients generating audit
events). After much debugging, it was found that the asynchronous
nature of netlink made it possible for auditd's queue to grow wildly,
until the kernel started to kill other processes due to OOM (auditd
asks the kernel not to be killed under OOM conditions, so every
process but auditd is shot).

The reason was that audit's consumer thread -- the one that runs
auditd-event.c:event_thread_main() -- was consuming events slower than
the rate in which netlink events were sent from the kernel to auditd's
main thread.

The solution we found (and which is still being tested) was to define
a high water mark on how many events to allow auditd to have in its
input queue. Given that each netlink message takes about 9kb, one can
set the high water mark to e.g: 500000 to have at most 4.5GB events in
RAM. So, when auditd reaches that high water mark, we ask the kernel
to slow down: all further events sent by the kernel have a "need an
ack" flag included so that the caller process (the one that generated
the system call that had to be audited) gets blocked until a reply is
sent from the daemon.

Also, while auditd is in this "OOM mode", for each netlink message
received, the consumer thread digests "N" messages from the input
queue instead of a single one, and just after that it tells the main
thread to acknowledge back to the kernel.

Finally, when the queue reaches a low water mark, auditd tells the
kernel to return into the normal mode, and messages are sent
asynchronously again.

It might be the case that you're falling into the very same situation
(events are being put in the queue in a faster rate than the
consumer's read capabilities). You can check that by doing the
following changes to audit-event.c:

- define a global, static uint64_t input_queue_size;
- increment it in enqueue_event() after the lock on queue_lock is taken;
- decrement it in event_thread_main() before queue_lock is unlocked;
- back into enqueue_event(), add a trace to print input_queue_size
whenever it grows over e.g: 100. You can put that before queue_lock is
unlocked.

Please let me know if that happens to be the reason of the problems
you're having. I've been working mostly with audit 1.7.4 and kernel
2.6.16.16+patches, so our changes still need to be ported to a recent
kernel and audit package before they're submitted officially (that's
likely to happen in march, after my master thesis' final deadline --
which is driving me crazy).

Cheers,
Lucas

Re: Problem with auditd/SnareLinux on RHEL 5.3 - auditd glomming memory

[Steve Grubb]

On Wednesday 04 February 2009 09:14:03 pm Lucas C. Villa Real wrote:
> 2009/2/4 Smith, Gary R <gary.smith@pnl.gov>:
> I noticed a very similar behavior when the system was under high
> stress (ie: having many rules and many remote clients generating audit
> events). After much debugging, it was found that the asynchronous
> nature of netlink made it possible for auditd's queue to grow wildly,
> until the kernel started to kill other processes due to OOM (auditd
> asks the kernel not to be killed under OOM conditions, so every
> process but auditd is shot).

Yes, I think auditd is blamed for the memory consumption related to it inside 
the kernel. I have run valgrind against the audit daemon many times and I 
know of no resource leaks. The only knob you really have to turn if the 
kernel queue is a problem is to increase the priority of the audit daemon so 
it gets more run time.


> The reason was that audit's consumer thread -- the one that runs
> auditd-event.c:event_thread_main() -- was consuming events slower than
> the rate in which netlink events were sent from the kernel to auditd's
> main thread.

This is because of some requirements on CC evals about knowing how many events 
are in flight. The input queue is simply 1. If you have the audit event 
dispatcher running, it gets first shot at handling the event. Then the event 
goes to disk. If you have synchronous logging then write blocks for a while. 
So, changing to buffered IO might be better for throughput.


> The solution we found (and which is still being tested) was to define
> a high water mark on how many events to allow auditd to have in its
> input queue. Given that each netlink message takes about 9kb, one can
> set the high water mark to e.g: 500000 to have at most 4.5GB events in
> RAM. So, when auditd reaches that high water mark, we ask the kernel
> to slow down: all further events sent by the kernel have a "need an
> ack" flag included so that the caller process (the one that generated
> the system call that had to be audited) gets blocked until a reply is
> sent from the daemon.

Originally, I thin David Woodhouse patched the kernel so that callers were put 
on a wait queue when we hit the end of the internal queue. I think someone 
removed it thinking the system becomes unresponsive.


> Please let me know if that happens to be the reason of the problems
> you're having. I've been working mostly with audit 1.7.4 and kernel
> 2.6.16.16+patches, so our changes still need to be ported to a recent
> kernel and audit package before they're submitted officially (that's
> likely to happen in march, after my master thesis' final deadline --
> which is driving me crazy).

Note that the event model changed inside the audit daemon around 1.7.5. Its 
very different than before. In the near future, I am planning to pull the 
code from audispd into auditd and use the queue code from audispd so that 
input and output of auditd can really become multi-threaded. I'm thinking 
this would allow better dequeuing of kernel events.

-Steve

RE: Problem with auditd/SnareLinux on RHEL 5.3 - auditd glomming memory

[Smith, Gary R]

Hello All, 

I looked at the source code for auditd and came up with the following
fix for the behavior I described.

You may have a better fix for the issue.

When the setting for the output log format is set to "NOLOG" (log_format
= NOLOG in auditd.conf) it appears that audit events are getting stacked
up in the internal message queue (audit_reply_list) and are not removed
from the stack after being written to the audit dispatcher daemon. The
result is the stack grows without end.

I have the following potential fix for audit version 1.7.11:

In "auditd.c" 

171c171
<       if (rep->reply.type != AUDIT_EOE) {
---
>       if (rep->reply.type != AUDIT_EOE && config.log_format !=
LF_NOLOG) {

I've rebuilt the rpm and tried it on a RHEL 5.3 i386 system with
2.6.18-128.el5 kernel and all is well with auditd.

This may not be the best fix for the excessive memory glomming I've
seen.

Best regards,

Gary Smith

-----Original Message-----
From: Steve Grubb [mailto:sgrubb@redhat.com] 
Sent: Thursday, February 05, 2009 8:33 AM
To: linux-audit@redhat.com
Cc: Lucas C. Villa Real; Smith, Gary R
Subject: Re: Problem with auditd/SnareLinux on RHEL 5.3 - auditd
glomming memory

On Wednesday 04 February 2009 09:14:03 pm Lucas C. Villa Real wrote:
> 2009/2/4 Smith, Gary R <gary.smith@pnl.gov>:
> I noticed a very similar behavior when the system was under high
> stress (ie: having many rules and many remote clients generating audit
> events). After much debugging, it was found that the asynchronous
> nature of netlink made it possible for auditd's queue to grow wildly,
> until the kernel started to kill other processes due to OOM (auditd
> asks the kernel not to be killed under OOM conditions, so every
> process but auditd is shot).

Yes, I think auditd is blamed for the memory consumption related to it
inside 
the kernel. I have run valgrind against the audit daemon many times and
I 
know of no resource leaks. The only knob you really have to turn if the 
kernel queue is a problem is to increase the priority of the audit
daemon so 
it gets more run time.


> The reason was that audit's consumer thread -- the one that runs
> auditd-event.c:event_thread_main() -- was consuming events slower than
> the rate in which netlink events were sent from the kernel to auditd's
> main thread.

This is because of some requirements on CC evals about knowing how many
events 
are in flight. The input queue is simply 1. If you have the audit event 
dispatcher running, it gets first shot at handling the event. Then the
event 
goes to disk. If you have synchronous logging then write blocks for a
while. 
So, changing to buffered IO might be better for throughput.


> The solution we found (and which is still being tested) was to define
> a high water mark on how many events to allow auditd to have in its
> input queue. Given that each netlink message takes about 9kb, one can
> set the high water mark to e.g: 500000 to have at most 4.5GB events in
> RAM. So, when auditd reaches that high water mark, we ask the kernel
> to slow down: all further events sent by the kernel have a "need an
> ack" flag included so that the caller process (the one that generated
> the system call that had to be audited) gets blocked until a reply is
> sent from the daemon.

Originally, I thin David Woodhouse patched the kernel so that callers
were put 
on a wait queue when we hit the end of the internal queue. I think
someone 
removed it thinking the system becomes unresponsive.


> Please let me know if that happens to be the reason of the problems
> you're having. I've been working mostly with audit 1.7.4 and kernel
> 2.6.16.16+patches, so our changes still need to be ported to a recent
> kernel and audit package before they're submitted officially (that's
> likely to happen in march, after my master thesis' final deadline --
> which is driving me crazy).

Note that the event model changed inside the audit daemon around 1.7.5.
Its 
very different than before. In the near future, I am planning to pull
the 
code from audispd into auditd and use the queue code from audispd so
that 
input and output of auditd can really become multi-threaded. I'm
thinking 
this would allow better dequeuing of kernel events.

-Steve

Re: Problem with auditd/SnareLinux on RHEL 5.3 - auditd glomming memory

[Steve Grubb]

On Thursday 19 February 2009 04:30:10 pm Smith, Gary R wrote:
> When the setting for the output log format is set to "NOLOG" (log_format
> = NOLOG in auditd.conf) it appears that audit events are getting stacked
> up in the internal message queue (audit_reply_list) and are not removed
> from the stack after being written to the audit dispatcher daemon. The
> result is the stack grows without end.
>
> I have the following potential fix for audit version 1.7.11:

This looks like a really good hint at what's going on. I'll look into this 
deeper and either apply this patch or address the same problem another way in 
the next release.

Thanks,
-Steve

Re: Problem with auditd/SnareLinux on RHEL 5.3 - auditd glomming memory

[Steve Grubb]

On Thursday 19 February 2009 04:30:10 pm Smith, Gary R wrote:
> When the setting for the output log format is set to "NOLOG" (log_format
> = NOLOG in auditd.conf) it appears that audit events are getting stacked
> up in the internal message queue (audit_reply_list) and are not removed
> from the stack after being written to the audit dispatcher daemon. The
> result is the stack grows without end.
>
> I have the following potential fix for audit version 1.7.11:

OK, I had a chance to look into this problem. The big clue was that its only 
happening when NOLOG is given. The patch that was sent does fix the problem, 
but it doesn't allow reconfigure (sighup) and on-demand log rotation 
(sigusr1) to work either. What I believe is the correct fix was put into svn 
as commit 252.

https://fedorahosted.org/audit/changeset/252

Thanks for the troubleshooting.

-Steve