Accounting audit messages dropped from kernel

Accounting audit messages dropped from kernel

[Kangkook Jee]

Hi, all

I'm running a customized user-level audit client and getting the following messages from /var/log/kern.log every now and then. 
The message seems like that it is dropping audit messages due to buffer limitations. 


Dec 11 21:46:56 hostname-10 kernel: [2081500.871616] audit_log_start: 109700 callbacks suppressed
Dec 11 21:46:56 hostname-10 kernel: [2081500.871620] audit: audit_backlog=102401 > audit_backlog_limit=102400
Dec 11 21:46:56 hostname-10 kernel: [2081500.871622] audit: audit_lost=-295739022 audit_rate_limit=0 audit_backlog_limit=102400
Dec 11 21:46:56 hostname-10 kernel: [2081500.871623] audit: backlog limit exceeded
Dec 11 21:46:56 hostname-10 kernel: [2081500.871646] audit: audit_backlog=102401 > audit_backlog_limit=102400
Dec 11 21:46:56 hostname-10 kernel: [2081500.871647] audit: audit_lost=-295739021 audit_rate_limit=0 audit_backlog_limit=102400
Dec 11 21:46:56 hostname-10 kernel: [2081500.871648] audit: backlog limit exceeded
Dec 11 21:46:56 hostname-10 kernel: [2081500.871657] audit: audit_backlog=102401 > audit_backlog_limit=102400
Dec 11 21:46:56 hostname-10 kernel: [2081500.871659] audit: audit_lost=-295739020 audit_rate_limit=0 audit_backlog_limit=102400
Dec 11 21:46:56 hostname-10 kernel: [2081500.871660] audit: backlog limit exceeded
Dec 11 21:46:56 hostname-10 kernel: [2081500.871665] audit: audit_backlog=102401 > audit_backlog_limit=102400

What I want to know more from this is that how many messages we are missing. 
For this, can I simply refer audit_lost field? or I also need to consider the value from " callbacks suppressed" line?

If anyone can help with this it will be very helpful.

Regards, Kangkook

Re: Accounting audit messages dropped from kernel

[Steve Grubb]

On Thursday, December 11, 2014 05:12:03 PM Kangkook Jee wrote:
> Hi, all
> 
> I'm running a customized user-level audit client and getting the following
> messages from /var/log/kern.log every now and then. The message seems like
> that it is dropping audit messages due to buffer limitations.

I wouldn't say, due to buffer limitations. Its because your client is not 
reading fast enough. 102400 should be plenty of buffers. By contrast, I 
recommend 8192 for busy systems using auditd.

> Dec 11 21:46:56 hostname-10 kernel: [2081500.871616] audit_log_start: 109700
> callbacks suppressed 
> Dec 11 21:46:56 hostname-10 kernel: [2081500.871620] audit: 
audit_backlog=102401 > audit_backlog_limit=102400
> Dec 11 21:46:56 hostname-10 kernel: [2081500.871622] audit:
> audit_lost=-295739022 audit_rate_limit=0 audit_backlog_limit=102400 
 
> What I want to know more from this is that how many messages we are missing.
> For this, can I simply refer audit_lost field?

Probably.

> or I also need to consider the value from " callbacks suppressed" line?

I cannot find that in any kernel code I have.

-Steve

Re: Accounting audit messages dropped from kernel

[Richard Guy Briggs]

On 14/12/12, Steve Grubb wrote:
> On Thursday, December 11, 2014 05:12:03 PM Kangkook Jee wrote:
> > Hi, all
> > 
> > I'm running a customized user-level audit client and getting the following
> > messages from /var/log/kern.log every now and then. The message seems like
> > that it is dropping audit messages due to buffer limitations.
> 
> I wouldn't say, due to buffer limitations. Its because your client is not 
> reading fast enough. 102400 should be plenty of buffers. By contrast, I 
> recommend 8192 for busy systems using auditd.
> 
> > Dec 11 21:46:56 hostname-10 kernel: [2081500.871616] audit_log_start: 109700
> > callbacks suppressed 
> > Dec 11 21:46:56 hostname-10 kernel: [2081500.871620] audit: 
> audit_backlog=102401 > audit_backlog_limit=102400
> > Dec 11 21:46:56 hostname-10 kernel: [2081500.871622] audit:
> > audit_lost=-295739022 audit_rate_limit=0 audit_backlog_limit=102400 
>  
> > What I want to know more from this is that how many messages we are missing.
> > For this, can I simply refer audit_lost field?
> 
> Probably.

Possibly.  Some of these would be printed with printk to kbuf, governed
by the main kernel rate limiter.

Some could get saved by audit_hold_queue and successfully dequeued by
auditd later.

In some recent testing I've been doing with systemd, I find I need at
least 7k buffers to avoid certain types of problems.

> > or I also need to consider the value from " callbacks suppressed" line?
> 
> I cannot find that in any kernel code I have.

That's the printk's rate limiter.

> -Steve

- RGB

--
Richard Guy Briggs <rbriggs@redhat.com>
Senior Software Engineer, Kernel Security, AMER ENG Base Operating Systems, Red Hat
Remote, Ottawa, Canada
Voice: +1.647.777.2635, Internal: (81) 32635, Alt: +1.613.693.0684x3545