Backlog exceeded when using audisp

Backlog exceeded when using audisp

[Andy Ruch]

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

Hello,

I'm trying to send the audit logs on a secure RHEL 6.5 system to rsyslog. Rsyslog will then send them to another system for centralized collection. I can't have audisp send them directly because the connectivity is unreliable and rsyslog provides on disk queues for reliable delivery. I've activated the syslogplugin of audisp to do the transfer. The problem is getting the logs transferred fast enough. The system is configured to panic upon error (-f 2), which it does frequently when I do something like update the SELinux RPM since watching /etc/selinux is required by the STIG. 


I have the audit buffer size configured to 8192 and the audisp queue set to 120. I'm surprised the 8192 buffer is being overwhelmed. When I look at aureport for just the time frame of the action, I get approximately 350 events. I know that each event may have multiple entries, but it is interesting that the capacity of a buffer over 20 times bigger is being exceeded.


Can anyone in a similar situation share any insights? Is there a faster way to transfer the logs rather than the audispsyslogplugin? We use to have rsyslog monitor the audit.log file but ran into some issues when we started dealing with log file rollover. And it just seems cleaner to send the audit logs directly.

Thanks,
Andrew Ruch

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

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

Re: Backlog exceeded when using audisp

[Steve Grubb]

On Wednesday, August 13, 2014 02:37:52 PM Andy Ruch wrote:
> I'm trying to send the audit logs on a secure RHEL 6.5 system to rsyslog.
> Rsyslog will then send them to another system for centralized collection.

This is fine.

> I can't have audisp send them directly because the connectivity is
> unreliable and rsyslog provides on disk queues for reliable delivery. 

So does auditd. It doesn't lose events unless some limit was exceeded.

> I've activated the syslogplugin of audisp to do the transfer. The problem is
> getting the logs transferred fast enough. The system is configured to panic
> upon error (-f 2), which it does frequently when I do something like update
> the SELinux RPM since watching /etc/selinux is required by the STIG.

A couple of thoughts here. Perhaps you want to have a policy where when you 
update selinux policy, you suspend auditing and then update and then resume. 
Short of that, you'll need to boost the priority and enlarge the queue sizes. 
The panic will only occur on an in-kernel buffer overflow. User space can't do 
that.


> I have the audit buffer size configured to 8192 and the audisp queue set to
> 120. I'm surprised the 8192 buffer is being overwhelmed. When I look at
> aureport for just the time frame of the action, I get approximately 350
> events. I know that each event may have multiple entries, but it is
> interesting that the capacity of a buffer over 20 times bigger is being
> exceeded.

Well, if the auditspd buffer is full and you have lossless buffering, the daemon 
waits until there is room in the queue to continue processing and then the 
kernel buffer backs up. You have to have settings in user space that allow 
auditd to keep the kernel queue as empty as possible.

> 
> Can anyone in a similar situation share any insights? Is there a faster way
> to transfer the logs rather than the audispsyslogplugin? We use to have
> rsyslog monitor the audit.log file but ran into some issues when we started
> dealing with log file rollover. And it just seems cleaner to send the audit
> logs directly.

You can also just load rules via auditctl. The kernel defaults to sending 
events to syslog if auditd is not running.

-Steve

Re: Backlog exceeded when using audisp

[Andy Ruch]

> On Wednesday, August 13, 2014 02:37:52 PM Andy Ruch wrote:
> > I'm trying to send the audit logs on a secure RHEL 6.5 system to rsyslog.
> > Rsyslog will then send them to another system for centralized collection. 
>
> This is fine. 
>
> > I can't have audisp send them directly because the connectivity is
> > unreliable and rsyslog provides on disk queues for reliable delivery. 
>
> So does auditd. It doesn't lose events unless some limit was exceeded. 

>

> > I've activated the syslogplugin of audisp to do the transfer. The problem is
> > getting the logs transferred fast enough. The system is configured to panic
> > upon error (-f 2), which it does frequently when I do something like update
> > the SELinux RPM since watching /etc/selinux is required by the STIG. 

>

> A couple of thoughts here. Perhaps you want to have a policy where when you 
> update selinux policy, you suspend auditing and then update and then resume. 
> Short of that, you'll need to boost the priority and enlarge the queue sizes. 
> The panic will only occur on an in-kernel buffer overflow. User space can't do 
> that. 

>

> > I have the audit buffer size configured to 8192 and the audisp queue set to
> > 120. I'm surprised the 8192 buffer is being overwhelmed. When I look at
> > aureport for just the time frame of the action, I get approximately 350
> > events. I know that each event may have multiple entries, but it is
> > interesting that the capacity of a buffer over 20 times bigger is being
> > exceeded. 

>

> Well, if the auditspd buffer is full and you have lossless buffering, the daemon 
> waits until there is room in the queue to continue processing and then the 
> kernel buffer backs up. You have to have settings in user space that allow 
> auditd to keep the kernel queue as empty as possible. 

>

> > 
> > Can anyone in a similar situation share any insights? Is there a faster way
> > to transfer the logs rather than the audispsyslogplugin? We use to have
> > rsyslog monitor the audit.log file but ran into some issues when we started
> > dealing with log file rollover. And it just seems cleaner to send the audit
> > logs directly. 

>

> You can also just load rules via auditctl. The kernel defaults to sending 
> events to syslog if auditd is not running. 

> 

> -Steve

 
Upon further testing, I think there might be something else as the root cause. For my testing, I'm adding an selinux user (semanage user -a ...). This will trigger a load_policy command for SELinux. When everything works fine, auditd processes roughly 2000 events and audisp handles this with no problems. However, sometimes when I run the command, auditd will receive over 15000 events. As far as I can tell, the extra events are all SELinux error events stating "selinux_audit_rule_match: stale rule". What would cause this and why does it not happen every time? Is this an audit issue or an SELinux issue?

Re: Backlog exceeded when using audisp

[Steve Grubb]

On Thursday, August 14, 2014 01:12:19 PM Andy Ruch wrote:
> Upon further testing, I think there might be something else as the root
> cause. For my testing, I'm adding an selinux user (semanage user -a ...).
> This will trigger a load_policy command for SELinux. When everything works
> fine, auditd processes roughly 2000 events and audisp handles this with no
> problems. However, sometimes when I run the command, auditd will receive
> over 15000 events. As far as I can tell, the extra events are all SELinux
> error events stating "selinux_audit_rule_match: stale rule". What would
> cause this 

Looking at kernel code, it would appear that you have rules that use selinux 
as part of the matching. When you load new policy, the sids (which is a number 
from the policy compiler) has likely changed and no longer matches what it 
thinks it does. The kernel only understands numbers. When you compile human 
readable selinux rules, it changes the text into numbers. If policy is 
changed, there is no guarantee that the number for say crond_t is the same as 
it used to be. So, the kernel detects that the audit rule mapping is using 
stale (old) sids.


> and why does it not happen every time? Is this an audit issue or
> an SELinux issue?

A little of both. A work around is probably to reload the audit rules 
immediately so that the sids get resolved against the new policy. The better 
fix would be to file a support ticket and ask for that code to be improved by 
doing what current kernels do for that function. They now have a WARN_ONCE 
message that goes to syslog. That keeps the audit logs cleaner.

-Steve