Re: Events Delayed in Example audisp Plugin

[Lukas Rupprecht <lukas.l.rupprecht@gmail.com>]

[-- 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 --]