Auditd framework slowdowns (sometimes freezes) the entire system.

Auditd framework slowdowns (sometimes freezes) the entire system.

[Kangkook Jee]

Hi all,

I'm writing a custom user-land auditd client subscribing to kauditd to monitor a
number of system calls that we are interested. My auditd client seems to work
fine in overall but I found unexpected behavior of auditd framework which slows
down (or sometimes freezes) the entire system as the consuming rate of audit
client couldn't catch up the speed of audit message generation.

Here's the simple code snippet used to reproduce the problem.

//
// To build.
// g++ -o simple_audit -std=c++11 -L/usr/lib/x86_64-linux-gnu/  main.cpp -laudit
//
#include <libaudit.h>
#include <sys/types.h>
#include <unistd.h>

#include <cassert>
#include <iostream>

static int32_t fd = -1;
static bool au_listen_flag = true;

int main(int argc, char* argv[]) {
    struct audit_reply rep;
    uint64_t cnt = 0;

    if (argc != 2) {
        fprintf(stderr, "Invalid usage: %s <sleep_interval>\n", argv[0]);
        exit(1);
    }

    uint32_t sleep_time = atoi(argv[1]);

    fd = audit_open();
    if (fd < 0) {
        // error handling.
        std::cerr << "Invalid fd returned: " + std::to_string(fd) << std::endl;
        exit(-1);
    }
    int32_t ret = audit_set_pid(fd, getpid(), WAIT_YES);
    if (ret < 0) {
        std::cerr << "audit_set_pid failed: " + std::to_string(fd) << std::endl;
        exit(-1);
    }

    while (au_listen_flag) {
        int32_t rc = audit_get_reply(fd, &rep, GET_REPLY_BLOCKING, 0);
        if (rc > 0) {
            cnt++;
        }

        usleep(sleep_time);

        if (cnt % 10000 == 0) {
            printf ("messages %lu\n", cnt);
        }
    }
    close(fd);
}


The problem becomes more apparent as we increase the amount of sleep time that
is provided as a first command line argument (say a thousand Milli-seconds) and
simultaneously run some heavy-load tasks (i.e., kernel build). 

sudo ./simple_audit 1000

Here's the command line that we used to add system calls to be monitored and
enable.

# Adding events.
/sbin/auditctl -a exit,always -F arch=b64 -S clone -S close -S creat -S dup -S dup2 -S dup3 -S execve -S exit -S exit_group -S fork -S open -S openat -S unlink -S unlinkat -S vfork -S 288 -S accept -S bind -S connect -S listen -S socket -S socketpair

# Enabling events.
/sbin/auditctl -e1 -b 102400

At the very moment, "auditctl -s" indicating that kernel buffer is filled up but
it does not throw away audit messages ('lost' is not increasing ). 

# auditctl -s
AUDIT_STATUS: enabled=1 flag=1 pid=29887 rate_limit=0 backlog_limit=102400 lost=270878600 backlog=102402
# auditctl -s
AUDIT_STATUS: enabled=1 flag=1 pid=29887 rate_limit=0 backlog_limit=102400 lost=270878600 backlog=102402

Could anyone guide me how to configure kauditd's buffer setting so that it can
dump audit messages when the buffer is filled up and user-land consumer can't
catch up the speed of audit message produce?

Thanks a lot for your help in advance!

Regards, Kangkook

Re: Auditd framework slowdowns (sometimes freezes) the entire system.

[Steve Grubb]

On Thursday, July 16, 2015 08:38:22 AM Kangkook Jee wrote:
> I'm writing a custom user-land auditd client subscribing to kauditd to
> monitor a number of system calls that we are interested. My auditd client
> seems to work fine in overall but I found unexpected behavior of auditd
> framework which slows down (or sometimes freezes) the entire system as the
> consuming rate of audit client couldn't catch up the speed of audit message
> generation.

This is by design. Auditing is so important that we cannot let even 1 event 
escape the audit trail. To people that count on auditing, they would normally 
rather have access denied than lose the ability to track who's accessing 
something.

This leads to a couple issues. One is have you done anything about priority? 
Did you give your daemon a healthy boost over the other processes so it gets 
more runtime than normal processes? How about cgroups? Have you checked disk 
synchronization techniques (some yield worse performance but guarantee its 
written)? What about gprof traces to see where the "hotspots" are in your 
daemon?

> Here's the simple code snippet used to reproduce the problem.
> 
> //
> // To build.
> // g++ -o simple_audit -std=c++11 -L/usr/lib/x86_64-linux-gnu/  main.cpp
> -laudit //
> #include <libaudit.h>
> #include <sys/types.h>
> #include <unistd.h>
> 
> #include <cassert>
> #include <iostream>
> 
> static int32_t fd = -1;
> static bool au_listen_flag = true;
> 
> int main(int argc, char* argv[]) {
>     struct audit_reply rep;
>     uint64_t cnt = 0;
> 
>     if (argc != 2) {
>         fprintf(stderr, "Invalid usage: %s <sleep_interval>\n", argv[0]);
>         exit(1);
>     }
> 
>     uint32_t sleep_time = atoi(argv[1]);
> 
>     fd = audit_open();
>     if (fd < 0) {
>         // error handling.
>         std::cerr << "Invalid fd returned: " + std::to_string(fd) <<
> std::endl; exit(-1);
>     }
>     int32_t ret = audit_set_pid(fd, getpid(), WAIT_YES);
>     if (ret < 0) {
>         std::cerr << "audit_set_pid failed: " + std::to_string(fd) <<
> std::endl; exit(-1);
>     }
> 
>     while (au_listen_flag) {
>         int32_t rc = audit_get_reply(fd, &rep, GET_REPLY_BLOCKING, 0);
>         if (rc > 0) {
>             cnt++;
>         }
> 
>         usleep(sleep_time);

Why would you do this? You ought to be using epoll or something like that to 
wait on next event.

>         if (cnt % 10000 == 0) {
>             printf ("messages %lu\n", cnt);
>         }
>     }
>     close(fd);
> }
> 
> 
> The problem becomes more apparent as we increase the amount of sleep time
> that is provided as a first command line argument (say a thousand
> Milli-seconds) and simultaneously run some heavy-load tasks (i.e., kernel
> build).
> 
> sudo ./simple_audit 1000
> 
> Here's the command line that we used to add system calls to be monitored and
> enable.
> 
> # Adding events.
> /sbin/auditctl -a exit,always -F arch=b64 -S clone -S close -S creat -S dup
> -S dup2 -S dup3 -S execve -S exit -S exit_group -S fork -S open -S openat
> -S unlink -S unlinkat -S vfork -S 288 -S accept -S bind -S connect -S
> listen -S socket -S socketpair

Next question...why would you want all those syscalls? Do you want them for 
daemons and users? Normally daemons are considered normal system function and 
are not of interest. What is of interest is what users do. So, to weed out 
damons, you don't want anything with auid=-1. Because the kernel uses unsigned 
numbers, you would add

-F auid>=1000 -F auid!=-1

to the rule. That might make a big difference.

> # Enabling events.
> /sbin/auditctl -e1 -b 102400
> 
> At the very moment, "auditctl -s" indicating that kernel buffer is filled up
> but it does not throw away audit messages ('lost' is not increasing ).
> 
> # auditctl -s
> AUDIT_STATUS: enabled=1 flag=1 pid=29887 rate_limit=0 backlog_limit=102400
> lost=270878600 backlog=102402 # auditctl -s
> AUDIT_STATUS: enabled=1 flag=1 pid=29887 rate_limit=0 backlog_limit=102400
> lost=270878600 backlog=102402
> 
> Could anyone guide me how to configure kauditd's buffer setting so that it
> can dump audit messages when the buffer is filled up and user-land consumer
> can't catch up the speed of audit message produce?

If you don't mind losing events, you can also listen on the netlink socket 
without setting the pid the same way that journald does it. That is a best 
effort connection and not guaranteed to be lossless.

-Steve

Re: Auditd framework slowdowns (sometimes freezes) the entire system.

[Kangkook Jee]

Dear Steve, 

Thanks a lot for your sincere reply.

With our custom audit client, we prefer not to take too much resources (CPUs or
memory) from user machine and rather want to drop some events. 

Therefore I'm trying to use audit multicast feature you mentioned
(https://lwn.net/Articles/587166/). I found out that this feature is recently
added and I have a few questions using it. 

Q1. I've gone over journald source code and found out that it issues a number of
netlink socket api calls to join in multi-cast group and receive datagrams. Do
you support rather cleaner api to use this feature? I couldn't find anything
from libaudit.h.

Q2. By joining in audit multi-cast group, can we avoid auditing the audit client
itself? As you know, with audit_set_pid(), it prevents from gathering and
reporting audit event for user-space audit client. We can expect the same
thing?

Q3. By only having a read-only user-space audit client and not having
bi-direction audit client running from the system,  are we going to see audit
entries logged from default system log frameworks which output to
/var/log/kernel.log (Debian family), syslog, or dmesg?

Q4. Our environment for deployment comprises many different types of legacy
distributions (i.e., CentOS 5 or 6, Ubuntu 12.04 ...), could you inform me from
what audit version (or kernel version) audit multicast is supported?

Q5. I'm also considering another design choice to use *rate_limit* to limit the
amount of audit messages delivered to user-level client. Do you think kauditd
will drop some messages with this setting enabled?

Thanks again for your help!

Regards, Kangkook


> On Jul 16, 2015, at 8:56 AM, Steve Grubb <sgrubb@redhat.com> wrote:
> 
> On Thursday, July 16, 2015 08:38:22 AM Kangkook Jee wrote:
>> I'm writing a custom user-land auditd client subscribing to kauditd to
>> monitor a number of system calls that we are interested. My auditd client
>> seems to work fine in overall but I found unexpected behavior of auditd
>> framework which slows down (or sometimes freezes) the entire system as the
>> consuming rate of audit client couldn't catch up the speed of audit message
>> generation.
> 
> This is by design. Auditing is so important that we cannot let even 1 event 
> escape the audit trail. To people that count on auditing, they would normally 
> rather have access denied than lose the ability to track who's accessing 
> something.
> 
> This leads to a couple issues. One is have you done anything about priority? 
> Did you give your daemon a healthy boost over the other processes so it gets 
> more runtime than normal processes? How about cgroups? Have you checked disk 
> synchronization techniques (some yield worse performance but guarantee its 
> written)? What about gprof traces to see where the "hotspots" are in your 
> daemon?
> 
>> Here's the simple code snippet used to reproduce the problem.
>> 
>> //
>> // To build.
>> // g++ -o simple_audit -std=c++11 -L/usr/lib/x86_64-linux-gnu/  main.cpp
>> -laudit //
>> #include <libaudit.h>
>> #include <sys/types.h>
>> #include <unistd.h>
>> 
>> #include <cassert>
>> #include <iostream>
>> 
>> static int32_t fd = -1;
>> static bool au_listen_flag = true;
>> 
>> int main(int argc, char* argv[]) {
>>    struct audit_reply rep;
>>    uint64_t cnt = 0;
>> 
>>    if (argc != 2) {
>>        fprintf(stderr, "Invalid usage: %s <sleep_interval>\n", argv[0]);
>>        exit(1);
>>    }
>> 
>>    uint32_t sleep_time = atoi(argv[1]);
>> 
>>    fd = audit_open();
>>    if (fd < 0) {
>>        // error handling.
>>        std::cerr << "Invalid fd returned: " + std::to_string(fd) <<
>> std::endl; exit(-1);
>>    }
>>    int32_t ret = audit_set_pid(fd, getpid(), WAIT_YES);
>>    if (ret < 0) {
>>        std::cerr << "audit_set_pid failed: " + std::to_string(fd) <<
>> std::endl; exit(-1);
>>    }
>> 
>>    while (au_listen_flag) {
>>        int32_t rc = audit_get_reply(fd, &rep, GET_REPLY_BLOCKING, 0);
>>        if (rc > 0) {
>>            cnt++;
>>        }
>> 
>>        usleep(sleep_time);
> 
> Why would you do this? You ought to be using epoll or something like that to 
> wait on next event.
> 
>>        if (cnt % 10000 == 0) {
>>            printf ("messages %lu\n", cnt);
>>        }
>>    }
>>    close(fd);
>> }
>> 
>> 
>> The problem becomes more apparent as we increase the amount of sleep time
>> that is provided as a first command line argument (say a thousand
>> Milli-seconds) and simultaneously run some heavy-load tasks (i.e., kernel
>> build).
>> 
>> sudo ./simple_audit 1000
>> 
>> Here's the command line that we used to add system calls to be monitored and
>> enable.
>> 
>> # Adding events.
>> /sbin/auditctl -a exit,always -F arch=b64 -S clone -S close -S creat -S dup
>> -S dup2 -S dup3 -S execve -S exit -S exit_group -S fork -S open -S openat
>> -S unlink -S unlinkat -S vfork -S 288 -S accept -S bind -S connect -S
>> listen -S socket -S socketpair
> 
> Next question...why would you want all those syscalls? Do you want them for 
> daemons and users? Normally daemons are considered normal system function and 
> are not of interest. What is of interest is what users do. So, to weed out 
> damons, you don't want anything with auid=-1. Because the kernel uses unsigned 
> numbers, you would add
> 
> -F auid>=1000 -F auid!=-1
> 
> to the rule. That might make a big difference.
> 
>> # Enabling events.
>> /sbin/auditctl -e1 -b 102400
>> 
>> At the very moment, "auditctl -s" indicating that kernel buffer is filled up
>> but it does not throw away audit messages ('lost' is not increasing ).
>> 
>> # auditctl -s
>> AUDIT_STATUS: enabled=1 flag=1 pid=29887 rate_limit=0 backlog_limit=102400
>> lost=270878600 backlog=102402 # auditctl -s
>> AUDIT_STATUS: enabled=1 flag=1 pid=29887 rate_limit=0 backlog_limit=102400
>> lost=270878600 backlog=102402
>> 
>> Could anyone guide me how to configure kauditd's buffer setting so that it
>> can dump audit messages when the buffer is filled up and user-land consumer
>> can't catch up the speed of audit message produce?
> 
> If you don't mind losing events, you can also listen on the netlink socket 
> without setting the pid the same way that journald does it. That is a best 
> effort connection and not guaranteed to be lossless.
> 
> -Steve

Re: Auditd framework slowdowns (sometimes freezes) the entire system.

[Steve Grubb]

On Tuesday, July 21, 2015 01:23:49 PM Kangkook Jee wrote:
> With our custom audit client, we prefer not to take too much resources (CPUs
> or memory) from user machine and rather want to drop some events.

Maybe set a smaller backlog and tell it to ignore overflows?

-b 512
-f 0


> Therefore I'm trying to use audit multicast feature you mentioned
> (https://lwn.net/Articles/587166/). I found out that this feature is
> recently added and I have a few questions using it.
> 
> Q1. I've gone over journald source code and found out that it issues a
> number of netlink socket api calls to join in multi-cast group and receive
> datagrams. Do you support rather cleaner api to use this feature? I
> couldn't find anything from libaudit.h.

This is one for the kernel developers.

> Q2. By joining in audit multi-cast group, can we avoid auditing the audit
> client itself? As you know, with audit_set_pid(), it prevents from
> gathering and reporting audit event for user-space audit client. We can
> expect the same thing?

You can set a rule once your program starts up and you have access to your 
pid. It would be the equivalent of this:

-a never,exit -S all -F pid=<pid>


> Q3. By only having a read-only user-space audit client and not having
> bi-direction audit client running from the system,  are we going to see
> audit entries logged from default system log frameworks which output to
> /var/log/kernel.log (Debian family), syslog, or dmesg?

You should not. I know you said you looked at Journald as an example of how to 
do it. It might be joining a lot more than audit. I haven't looked.

 
> Q4. Our environment for deployment comprises many different types of legacy
> distributions (i.e., CentOS 5 or 6, Ubuntu 12.04 ...), could you inform me
> from what audit version (or kernel version) audit multicast is supported?

It seems to be 3.16.

 
> Q5. I'm also considering another design choice to use *rate_limit* to limit
> the amount of audit messages delivered to user-level client. Do you think
> kauditd will drop some messages with this setting enabled?

I have not played with it. Maybe one of the kernel developers has an opinion. 
I am pretty sure you can just ignore queue overflows, though.
 
-Steve

Re: Auditd framework slowdowns (sometimes freezes) the entire system.

[Paul Moore]

On Tue, Jul 21, 2015 at 2:14 PM, Steve Grubb <sgrubb@redhat.com> wrote:
> On Tuesday, July 21, 2015 01:23:49 PM Kangkook Jee wrote:
>> Therefore I'm trying to use audit multicast feature you mentioned
>> (https://lwn.net/Articles/587166/). I found out that this feature is
>> recently added and I have a few questions using it.
>>
>> Q1. I've gone over journald source code and found out that it issues a
>> number of netlink socket api calls to join in multi-cast group and receive
>> datagrams. Do you support rather cleaner api to use this feature? I
>> couldn't find anything from libaudit.h.
>
> This is one for the kernel developers.

We only support the two APIs at the moment.  We will be doing some
rework of the audit APIs that should improve performance, but that is
far from being ready.

-- 
paul moore
www.paul-moore.com