Handling -ENOBUFS

Handling -ENOBUFS

[Lucas C. Villa Real]

Hi guys,

I'm facing a situation where -ENOBUFS is returned from both
audit_send() and audit_get_reply(). The system is under high stress,
with 250k files being created and having creat() and chmod() syscalls
audited.

Looking the code at lib/netlink.c, I saw that audit_send() doesn't
handle -ENOBUFS. Would it be possible to replace the condition from
"while (retval < 0 && errno == EINTR)" to "while (retval < 0 && (errno
== EINTR || errno == ENOBUFS))" to fix the problem when sending
packets from userspace to kernel?

My understanding for the problem in audit_get_reply() is that the I/O
buffers are all full and auditd was just not scheduled at the expected
rate, causing these buffers to overflow. Does that make sense? If it
does, do you have a suggestion about the best way to approach this
problem, besides changing auditd's priority? I thought of a dirty
trick such as forcing auditd to be rescheduled, but that would be way
too intrusive.

One interesting thing which I noticed is that 'auditctl -s' doesn't
report that messages were lost,  although a few events did not appear
in the logs. I'm still not sure if they didn't appear because of this
specific problem, but given that ENOBUFS was returned I would expect
to see a positive counter in "lost" below:

AUDIT_STATUS: enabled=1 flag=1 pid=3821 rate_limit=0
backlog_limit=8192 lost=0 backlog=0

This is happening with an old kernel, 2.6.16.46 + a bunch of patches,
and audit 1.7.4. I cannot completely upgrade it to a new release, but
I can certainly backport audit specific bits if you remember having
fixed something similar since then.

Thanks,
Lucas

Re: Handling -ENOBUFS

[Steve Grubb]

On Wednesday 05 November 2008 11:30:16 Lucas C. Villa Real wrote:
> I'm facing a situation where -ENOBUFS is returned from both
> audit_send() and audit_get_reply(). The system is under high stress,
> with 250k files being created and having creat() and chmod() syscalls
> audited.

Is this what you really wanted to audit? :)


> Looking the code at lib/netlink.c, I saw that audit_send() doesn't
> handle -ENOBUFS. Would it be possible to replace the condition from
> "while (retval < 0 && errno == EINTR)" to "while (retval < 0 && (errno
> == EINTR || errno == ENOBUFS))" to fix the problem when sending
> packets from userspace to kernel?

Have you tried that? Does it fix the problem or just hang the utility?


> My understanding for the problem in audit_get_reply() is that the I/O
> buffers are all full and auditd was just not scheduled at the expected
> rate, causing these buffers to overflow. Does that make sense?

If you go over the backlog limit, you get a syslog message about that unless 
you have it set to ignore. My guess would be that you have a general network 
memory pool depletion and is not related to audit specifically.


> If it does, do you have a suggestion about the best way to approach this
> problem, besides changing auditd's priority?

Increase the backlog and increase auditd's priority. I have not played with 
running auditd with a different scheduler policy than whatever the default 
is. But you may want to see if one of the other scheduler polices treat audit 
better. or maybe you want to tune  /proc/sys/kernel/sched_granularity_ns.


> One interesting thing which I noticed is that 'auditctl -s' doesn't
> report that messages were lost,

They weren't lost by the audit system so it doesn't know they didn't arrive.


> This is happening with an old kernel, 2.6.16.46 + a bunch of patches,
> and audit 1.7.4. I cannot completely upgrade it to a new release, but
> I can certainly backport audit specific bits if you remember having
> fixed something similar since then.

Well, that proc tunable is only available for the CFS scheduler. Not sure what 
you have for older kernels.

-Steve

Re: Handling -ENOBUFS

[Lucas C. Villa Real]

On Wed, Nov 5, 2008 at 4:19 PM, Steve Grubb <sgrubb@redhat.com> wrote:
> On Wednesday 05 November 2008 11:30:16 Lucas C. Villa Real wrote:
>> I'm facing a situation where -ENOBUFS is returned from both
>> audit_send() and audit_get_reply(). The system is under high stress,
>> with 250k files being created and having creat() and chmod() syscalls
>> audited.
>
> Is this what you really wanted to audit? :)

Yes, not a single event can be missed in the system I'm working on,
unfortunately :)


>> Looking the code at lib/netlink.c, I saw that audit_send() doesn't
>> handle -ENOBUFS. Would it be possible to replace the condition from
>> "while (retval < 0 && errno == EINTR)" to "while (retval < 0 && (errno
>> == EINTR || errno == ENOBUFS))" to fix the problem when sending
>> packets from userspace to kernel?
>
> Have you tried that? Does it fix the problem or just hang the utility?

So far it didn't hang. However, just in case, I added a maximum number
of retries (currently set to 64). I'm about to launch a new batch to
stress the system once again, and then I'll be able to see if it works
as expected.

>> My understanding for the problem in audit_get_reply() is that the I/O
>> buffers are all full and auditd was just not scheduled at the expected
>> rate, causing these buffers to overflow. Does that make sense?
>
> If you go over the backlog limit, you get a syslog message about that unless
> you have it set to ignore. My guess would be that you have a general network
> memory pool depletion and is not related to audit specifically.

Yes. I hope that increasing auditd's priority will help to drain that.
I'll let you know if that works.

>> If it does, do you have a suggestion about the best way to approach this
>> problem, besides changing auditd's priority?
>
> Increase the backlog and increase auditd's priority. I have not played with
> running auditd with a different scheduler policy than whatever the default
> is. But you may want to see if one of the other scheduler polices treat audit
> better. or maybe you want to tune  /proc/sys/kernel/sched_granularity_ns.
>
>
>> One interesting thing which I noticed is that 'auditctl -s' doesn't
>> report that messages were lost,
>
> They weren't lost by the audit system so it doesn't know they didn't arrive.

Do you think it would make sense to add an extra member to struct
sk_buff (a pointer to a callback function) and then have
skb_queue_tail() signal if it failed to send a message? That would
allow audit to keep track of such losses, as well as any other
subsystem using netlink for communicating with userspace.

>> This is happening with an old kernel, 2.6.16.46 + a bunch of patches,
>> and audit 1.7.4. I cannot completely upgrade it to a new release, but
>> I can certainly backport audit specific bits if you remember having
>> fixed something similar since then.
>
> Well, that proc tunable is only available for the CFS scheduler. Not sure what
> you have for older kernels.

It's not, but I'll keep looking for other ways to improve the
responsiveness of auditd here.

Thanks!
Lucas

Re: Handling -ENOBUFS

[Steve Grubb]

On Wednesday 05 November 2008 15:56:30 Lucas C. Villa Real wrote:
> >> Looking the code at lib/netlink.c, I saw that audit_send() doesn't
> >> handle -ENOBUFS. Would it be possible to replace the condition from
> >> "while (retval < 0 && errno == EINTR)" to "while (retval < 0 && (errno
> >> == EINTR || errno == ENOBUFS))" to fix the problem when sending
> >> packets from userspace to kernel?
> >
> > Have you tried that? Does it fix the problem or just hang the utility?
>
> So far it didn't hang. However, just in case, I added a maximum number
> of retries (currently set to 64). I'm about to launch a new batch to
> stress the system once again, and then I'll be able to see if it works
> as expected.

If it works out, send a patch to the list and I'll pull it into the next 
release.


> >> One interesting thing which I noticed is that 'auditctl -s' doesn't
> >> report that messages were lost,
> >
> > They weren't lost by the audit system so it doesn't know they didn't
> > arrive.
>
> Do you think it would make sense to add an extra member to struct
> sk_buff (a pointer to a callback function) and then have
> skb_queue_tail() signal if it failed to send a message? That would
> allow audit to keep track of such losses, as well as any other
> subsystem using netlink for communicating with userspace.

The network developers generally frown on anything getting added to sk_buff 
since that affects overall system performance. You would probably want to 
take this issue up with them on the net-dev mail list. I would be supportive 
of anything that adds reliability. But they control the code base for that 
part of the kernel.

-Steve

Re: Handling -ENOBUFS

[Eric Paris]

On Wed, 2008-11-05 at 18:56 -0200, Lucas C. Villa Real wrote:
> On Wed, Nov 5, 2008 at 4:19 PM, Steve Grubb <sgrubb@redhat.com> wrote:

> >> One interesting thing which I noticed is that 'auditctl -s' doesn't
> >> report that messages were lost,
> >
> > They weren't lost by the audit system so it doesn't know they didn't arrive.
> 
> Do you think it would make sense to add an extra member to struct
> sk_buff (a pointer to a callback function) and then have
> skb_queue_tail() signal if it failed to send a message? That would
> allow audit to keep track of such losses, as well as any other
> subsystem using netlink for communicating with userspace.

Getting a new field in skb is basically a non-starter.  Well, unless you
can find a way to drop 2 fields...

Anyway, I just walked the entire kernel audit "send" system and I don't
see any place we could drop an skb.  I didn't walk all of the receive
side so maybe there is something in that code but it's unlikely and that
'should' be noticed by auditd if there were any errors...

I know auditd has a issue where it can not write things to the log file
even though they came out of the netlink socket (messages over 4k or
so).  Can you run auditd under strace and see if the number of netlink
messages it gets is equal to the number you expect or equal to the
number that show up in the logs?  Things aren't supposed to get dropped
silently....

-Eric

Re: Handling -ENOBUFS

[Lucas C. Villa Real]

On Thu, Nov 6, 2008 at 12:16 PM, Eric Paris <eparis@redhat.com> wrote:
> On Wed, 2008-11-05 at 18:56 -0200, Lucas C. Villa Real wrote:
>> On Wed, Nov 5, 2008 at 4:19 PM, Steve Grubb <sgrubb@redhat.com> wrote:
>
>> >> One interesting thing which I noticed is that 'auditctl -s' doesn't
>> >> report that messages were lost,
>> >
>> > They weren't lost by the audit system so it doesn't know they didn't arrive.
>>
>> Do you think it would make sense to add an extra member to struct
>> sk_buff (a pointer to a callback function) and then have
>> skb_queue_tail() signal if it failed to send a message? That would
>> allow audit to keep track of such losses, as well as any other
>> subsystem using netlink for communicating with userspace.
>
> Getting a new field in skb is basically a non-starter.  Well, unless you
> can find a way to drop 2 fields...

Hi, Eric

Sorry for the late reply.

Indeed, I looked at that structure and it seems like that's not the
best approach.

> Anyway, I just walked the entire kernel audit "send" system and I don't
> see any place we could drop an skb.  I didn't walk all of the receive
> side so maybe there is something in that code but it's unlikely and that
> 'should' be noticed by auditd if there were any errors...

What about audit_send_reply_thread()? We don't check for
netlink_unicast()'s return value. Even though that's not the channel
used to send events, the error seen in auditd logs could be coming
from this point, as the scripts we're running here perform a couple of
queries from time to time to audit in kernel space.

> I know auditd has a issue where it can not write things to the log file
> even though they came out of the netlink socket (messages over 4k or
> so).  Can you run auditd under strace and see if the number of netlink
> messages it gets is equal to the number you expect or equal to the
> number that show up in the logs?  Things aren't supposed to get dropped
> silently....

Last night I realized that my audit_sanitize_log script (which groups
events by their sequence number) had a problem dealing with events
which crossed the boundaries of an audit log after a rotate request
(ie: a few lines for a given event showed up in the rotated log, and a
few others in the new file which replaced that one). That, together
with a few other things that I've been experimenting here, was the
cause of the files missing from my final report.

Still, I'd like to fix both problems so that we certify that no events
are lost, ever. Do you think Audit could be made more reliable
(regarding the message lost indication) by checking all of
netlink_unicast() retvals?

Thanks!
Lucas