All of lore.kernel.org
 help / color / mirror / Atom feed
* Events Delayed in Example audisp Plugin
@ 2019-04-05 18:35 Lukas Rupprecht
  2019-04-07  8:24 ` Steve Grubb
  0 siblings, 1 reply; 3+ messages in thread
From: Lukas Rupprecht @ 2019-04-05 18:35 UTC (permalink / raw)
  To: linux-audit

Hi All,

I'm, having problems with the example audisp plugin from https://github.com/linux-audit/audit-userspace/blob/master/contrib/plugin/audisp-example.c as sometimes, events seem to be delayed. The scenario is as follows:

My audit rules are tracking clone, execve,setpgid, and exit_group calls and I changed the example plugin to just dump records in handle_event using the following code:

static void handle_event(auparse_state_t *au, auparse_cb_event_t cb_event_type,
        void *user_data) {
    int type, num = 0;

    if (cb_event_type != AUPARSE_CB_EVENT_READY)
        return;

    while (auparse_goto_record_num(au, num) > 0) {
        type = auparse_get_type(au);

        // dump whole record
        printf("%s: %s\n", audit_msg_type_to_name(auparse_get_type(au)),
                auparse_get_record_text(au));

        num++;
    }
}

When running a simple 'cat' command, I should see events for (in that order) clone, execve, setpgid, setpgid, exit_group. However, the plugin is only printing the first four events but not the exit_group. The event is printed eventually, but only, if there has been other system activity that triggered new, unrelated events (for example, another clone).

I added some instrumentation and found that, when the exit_group event arrives, fgets_unlocked (line 125) does read the SYSCALL record for exit_group but is missing the corresponding EOE record. A possible explanation could be that, when select unblocks, fgets_unlocked only reads a single line from stdin while the remaining data is buffered. Hence, when select is called the next time, it does not detect any activity on the file descriptor and blocks, and the buffered data is only read once select unblocks due to a new event.

To test this, I replaced the call to fgets_unlocked by a read call to consume all available bytes on stdin. The new code looks as follows (replacing lines 123-130 in audisp-example.c):

/* Now the event loop */
if (!stop && !hup && retval > 0) {
    ssize_t bytesRead = read(0, tmp, MAX_AUDIT_MESSAGE_LENGTH);
    if (bytesRead > 0) {
        // this is just for printf
        tmp[bytesRead] = '\0';
        printf("Read %d bytes from socket: %s", bytesRead, tmp);

        auparse_feed(au, tmp, bytesRead);
    }
}

Using this code, I can now see the EOE record for the corresponding exit_group SYSCALL record being read when the event arrives (I can see it printed by the printf in the event loop). However, the problem is that it is still not processed in handle_event until a new, unrelated event arrives, i.e. it is not printed immediately in handle_event. It should have been feed to the parser though as part of the last read. Could this be a bug or am I missing something? I tried this for versions 2.8.1 and 2.8.5.

Thanks for any help in advance!
Lukas

^ permalink raw reply	[flat|nested] 3+ messages in thread

* Re: Events Delayed in Example audisp Plugin
  2019-04-05 18:35 Events Delayed in Example audisp Plugin Lukas Rupprecht
@ 2019-04-07  8:24 ` Steve Grubb
  2019-04-09  0:31   ` Lukas Rupprecht
  0 siblings, 1 reply; 3+ messages in thread
From: Steve Grubb @ 2019-04-07  8:24 UTC (permalink / raw)
  To: Lukas Rupprecht; +Cc: linux-audit

On Fri, 5 Apr 2019 11:35:03 -0700
Lukas Rupprecht <lukas.l.rupprecht@gmail.com> wrote:

> Hi All,
> 
> I'm, having problems with the example audisp plugin from
> https://github.com/linux-audit/audit-userspace/blob/master/contrib/plugin/audisp-example.c
> as sometimes, events seem to be delayed. 

It is always helpful to list which version of user space you have so
that if I know of any bug fixes, I can point you to that. That said,
there is a pending pull request that I am thinking to accept but
haven't yet that may solve your problem. It is against the example
code. See  https://github.com/linux-audit/audit-userspace/pull/83/files

It has to do with mixing raw and stdio which the latter is buffered.
Let me know if that fixes your problem.

Best Regards,
-Steve

>The scenario is as follows:
> 
> My audit rules are tracking clone, execve,setpgid, and exit_group
> calls and I changed the example plugin to just dump records in
> handle_event using the following code:
> 
> static void handle_event(auparse_state_t *au, auparse_cb_event_t
> cb_event_type, void *user_data) {
>     int type, num = 0;
> 
>     if (cb_event_type != AUPARSE_CB_EVENT_READY)
>         return;
> 
>     while (auparse_goto_record_num(au, num) > 0) {
>         type = auparse_get_type(au);
> 
>         // dump whole record
>         printf("%s: %s\n",
> audit_msg_type_to_name(auparse_get_type(au)),
> auparse_get_record_text(au));
> 
>         num++;
>     }
> }
> 
> When running a simple 'cat' command, I should see events for (in that
> order) clone, execve, setpgid, setpgid, exit_group. However, the
> plugin is only printing the first four events but not the exit_group.
> The event is printed eventually, but only, if there has been other
> system activity that triggered new, unrelated events (for example,
> another clone).
> 
> I added some instrumentation and found that, when the exit_group
> event arrives, fgets_unlocked (line 125) does read the SYSCALL record
> for exit_group but is missing the corresponding EOE record. A
> possible explanation could be that, when select unblocks,
> fgets_unlocked only reads a single line from stdin while the
> remaining data is buffered. Hence, when select is called the next
> time, it does not detect any activity on the file descriptor and
> blocks, and the buffered data is only read once select unblocks due
> to a new event.
> 
> To test this, I replaced the call to fgets_unlocked by a read call to
> consume all available bytes on stdin. The new code looks as follows
> (replacing lines 123-130 in audisp-example.c):
> 
> /* Now the event loop */
> if (!stop && !hup && retval > 0) {
>     ssize_t bytesRead = read(0, tmp, MAX_AUDIT_MESSAGE_LENGTH);
>     if (bytesRead > 0) {
>         // this is just for printf
>         tmp[bytesRead] = '\0';
>         printf("Read %d bytes from socket: %s", bytesRead, tmp);
> 
>         auparse_feed(au, tmp, bytesRead);
>     }
> }
> 
> Using this code, I can now see the EOE record for the corresponding
> exit_group SYSCALL record being read when the event arrives (I can
> see it printed by the printf in the event loop). However, the problem
> is that it is still not processed in handle_event until a new,
> unrelated event arrives, i.e. it is not printed immediately in
> handle_event. It should have been feed to the parser though as part
> of the last read. Could this be a bug or am I missing something? I
> tried this for versions 2.8.1 and 2.8.5.
> 
> Thanks for any help in advance!
> Lukas
> 
> 
> --
> Linux-audit mailing list
> Linux-audit@redhat.com
> https://www.redhat.com/mailman/listinfo/linux-audit

^ permalink raw reply	[flat|nested] 3+ messages in thread

* Re: Events Delayed in Example audisp Plugin
  2019-04-07  8:24 ` Steve Grubb
@ 2019-04-09  0:31   ` Lukas Rupprecht
  0 siblings, 0 replies; 3+ messages in thread
From: Lukas Rupprecht @ 2019-04-09  0:31 UTC (permalink / raw)
  To: Steve Grubb; +Cc: linux-audit


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

Hi Steve,

Thank you for the quick response and pointing me to the patch. Regarding versions, I saw the problem on both audit-userspace 2.8.1 (the version I was on initially) and 2.8.5.

I applied the changes from the patch but unfortunately, it is still not working as expected. The problem is that the patch sets stdin to O_NONBLOCK, which means that read will return 0 if no data is available and this causes the plugin to exit due to the new EOF check in line 133. As a result, I saw a lot of "audispd: plugin audisp-example terminated unexpectedly" in syslog.

I adapted the patch and removed the read while loop and added an extra auparse_flush_feed after every read (see patch below) and that seems to fix the problem. In particular, I think the extra flush causes the EOE record to be pushed to the parser. I am not sure if this is the best way and if the extra flush may have any implications so if you have any feedback, that would be great.

Best,
Lukas

diff --git a/contrib/plugin/audisp-example.c b/contrib/plugin/audisp-example.c
index 3fe845a..e44bab7 100644
--- a/contrib/plugin/audisp-example.c
+++ b/contrib/plugin/audisp-example.c
@@ -42,6 +42,7 @@
 #include <string.h>
 #include <sys/select.h>
 #include <errno.h>
+#include <unistd.h>
 #include "libaudit.h"
 #include "auparse.h"
 
@@ -77,7 +78,7 @@ static void reload_config(void)
 
 int main(int argc, char *argv[])
 {
-       char tmp[MAX_AUDIT_MESSAGE_LENGTH+1];
+       char tmp[MAX_AUDIT_MESSAGE_LENGTH];
        struct sigaction sa;
 
        /* Register sighandlers */
@@ -100,6 +101,7 @@ int main(int argc, char *argv[])
                fd_set read_mask;
                struct timeval tv;
                int retval = -1;
+               int read_size = 0;
 
                /* Load configuration */
                if (hup) {
@@ -121,14 +123,17 @@ int main(int argc, char *argv[])
                } while (retval == -1 && errno == EINTR && !hup && !stop);
 
                /* Now the event loop */
-                if (!stop && !hup && retval > 0) {
-                       if (fgets_unlocked(tmp, MAX_AUDIT_MESSAGE_LENGTH,
-                               stdin)) {
-                               auparse_feed(au, tmp, strnlen(tmp,
-                                               MAX_AUDIT_MESSAGE_LENGTH));
-                       }
-               }
-               if (feof(stdin))
+        if (!stop && !hup && retval > 0) {
+            if ((read_size = read(0, tmp, MAX_AUDIT_MESSAGE_LENGTH)) > 0) {
+                auparse_feed(au, tmp, strnlen(tmp, read_size));
+            }
+        }
+        auparse_flush_feed(au);
+        if (read_size == 0) {/* check eof */
+            syslog(LOG_INFO, "EXITING MAIN LOOP");
+            break;
+        }
+        if (read_size == 0)
                        break;
        } while (stop == 0);

> On Apr 7, 2019, at 1:24 AM, Steve Grubb <sgrubb@redhat.com> wrote:
> 
> On Fri, 5 Apr 2019 11:35:03 -0700
> Lukas Rupprecht <lukas.l.rupprecht@gmail.com <mailto:lukas.l.rupprecht@gmail.com>> wrote:
> 
>> Hi All,
>> 
>> I'm, having problems with the example audisp plugin from
>> https://github.com/linux-audit/audit-userspace/blob/master/contrib/plugin/audisp-example.c <https://github.com/linux-audit/audit-userspace/blob/master/contrib/plugin/audisp-example.c>
>> as sometimes, events seem to be delayed. 
> 
> It is always helpful to list which version of user space you have so
> that if I know of any bug fixes, I can point you to that. That said,
> there is a pending pull request that I am thinking to accept but
> haven't yet that may solve your problem. It is against the example
> code. See  https://github.com/linux-audit/audit-userspace/pull/83/files <https://github.com/linux-audit/audit-userspace/pull/83/files>
> 
> It has to do with mixing raw and stdio which the latter is buffered.
> Let me know if that fixes your problem.
> 
> Best Regards,
> -Steve
> 
>> The scenario is as follows:
>> 
>> My audit rules are tracking clone, execve,setpgid, and exit_group
>> calls and I changed the example plugin to just dump records in
>> handle_event using the following code:
>> 
>> static void handle_event(auparse_state_t *au, auparse_cb_event_t
>> cb_event_type, void *user_data) {
>>    int type, num = 0;
>> 
>>    if (cb_event_type != AUPARSE_CB_EVENT_READY)
>>        return;
>> 
>>    while (auparse_goto_record_num(au, num) > 0) {
>>        type = auparse_get_type(au);
>> 
>>        // dump whole record
>>        printf("%s: %s\n",
>> audit_msg_type_to_name(auparse_get_type(au)),
>> auparse_get_record_text(au));
>> 
>>        num++;
>>    }
>> }
>> 
>> When running a simple 'cat' command, I should see events for (in that
>> order) clone, execve, setpgid, setpgid, exit_group. However, the
>> plugin is only printing the first four events but not the exit_group.
>> The event is printed eventually, but only, if there has been other
>> system activity that triggered new, unrelated events (for example,
>> another clone).
>> 
>> I added some instrumentation and found that, when the exit_group
>> event arrives, fgets_unlocked (line 125) does read the SYSCALL record
>> for exit_group but is missing the corresponding EOE record. A
>> possible explanation could be that, when select unblocks,
>> fgets_unlocked only reads a single line from stdin while the
>> remaining data is buffered. Hence, when select is called the next
>> time, it does not detect any activity on the file descriptor and
>> blocks, and the buffered data is only read once select unblocks due
>> to a new event.
>> 
>> To test this, I replaced the call to fgets_unlocked by a read call to
>> consume all available bytes on stdin. The new code looks as follows
>> (replacing lines 123-130 in audisp-example.c):
>> 
>> /* Now the event loop */
>> if (!stop && !hup && retval > 0) {
>>    ssize_t bytesRead = read(0, tmp, MAX_AUDIT_MESSAGE_LENGTH);
>>    if (bytesRead > 0) {
>>        // this is just for printf
>>        tmp[bytesRead] = '\0';
>>        printf("Read %d bytes from socket: %s", bytesRead, tmp);
>> 
>>        auparse_feed(au, tmp, bytesRead);
>>    }
>> }
>> 
>> Using this code, I can now see the EOE record for the corresponding
>> exit_group SYSCALL record being read when the event arrives (I can
>> see it printed by the printf in the event loop). However, the problem
>> is that it is still not processed in handle_event until a new,
>> unrelated event arrives, i.e. it is not printed immediately in
>> handle_event. It should have been feed to the parser though as part
>> of the last read. Could this be a bug or am I missing something? I
>> tried this for versions 2.8.1 and 2.8.5.
>> 
>> Thanks for any help in advance!
>> Lukas
>> 
>> 
>> --
>> Linux-audit mailing list
>> Linux-audit@redhat.com <mailto:Linux-audit@redhat.com>
>> https://www.redhat.com/mailman/listinfo/linux-audit <https://www.redhat.com/mailman/listinfo/linux-audit>

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

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



^ permalink raw reply related	[flat|nested] 3+ messages in thread

end of thread, other threads:[~2019-04-09  0:31 UTC | newest]

Thread overview: 3+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-04-05 18:35 Events Delayed in Example audisp Plugin Lukas Rupprecht
2019-04-07  8:24 ` Steve Grubb
2019-04-09  0:31   ` Lukas Rupprecht

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.