From mboxrd@z Thu Jan 1 00:00:00 1970 From: Lukas Rupprecht Subject: Re: Events Delayed in Example audisp Plugin Date: Mon, 8 Apr 2019 17:31:29 -0700 Message-ID: <26C375AA-6078-46FE-83EA-CAE7C5B7CC9D@gmail.com> References: <701671D3-DD66-4462-89E1-0849CB1BBFCF@gmail.com> <20190407102449.6ee98f32@ivy-bridge> Mime-Version: 1.0 (Mac OS X Mail 11.5 \(3445.9.1\)) Content-Type: multipart/mixed; boundary="===============3649156790367919020==" Return-path: In-Reply-To: <20190407102449.6ee98f32@ivy-bridge> List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Sender: linux-audit-bounces@redhat.com Errors-To: linux-audit-bounces@redhat.com To: Steve Grubb Cc: linux-audit@redhat.com List-Id: linux-audit@redhat.com --===============3649156790367919020== Content-Type: multipart/alternative; boundary="Apple-Mail=_023FF301-4E4E-49EF-81E6-59C4879498DA" --Apple-Mail=_023FF301-4E4E-49EF-81E6-59C4879498DA Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=us-ascii 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 #include #include +#include #include "libaudit.h" #include "auparse.h" =20 @@ -77,7 +78,7 @@ static void reload_config(void) =20 int main(int argc, char *argv[]) { - char tmp[MAX_AUDIT_MESSAGE_LENGTH+1]; + char tmp[MAX_AUDIT_MESSAGE_LENGTH]; struct sigaction sa; =20 /* Register sighandlers */ @@ -100,6 +101,7 @@ int main(int argc, char *argv[]) fd_set read_mask; struct timeval tv; int retval =3D -1; + int read_size =3D 0; =20 /* Load configuration */ if (hup) { @@ -121,14 +123,17 @@ int main(int argc, char *argv[]) } while (retval =3D=3D -1 && errno =3D=3D EINTR && !hup = && !stop); =20 /* 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 =3D read(0, tmp, MAX_AUDIT_MESSAGE_LENGTH)) = > 0) { + auparse_feed(au, tmp, strnlen(tmp, read_size)); + } + } + auparse_flush_feed(au); + if (read_size =3D=3D 0) {/* check eof */ + syslog(LOG_INFO, "EXITING MAIN LOOP"); + break; + } + if (read_size =3D=3D 0) break; } while (stop =3D=3D 0); > On Apr 7, 2019, at 1:24 AM, Steve Grubb wrote: >=20 > On Fri, 5 Apr 2019 11:35:03 -0700 > Lukas Rupprecht > wrote: >=20 >> Hi All, >>=20 >> 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.=20 >=20 > 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 = >=20 > It has to do with mixing raw and stdio which the latter is buffered. > Let me know if that fixes your problem. >=20 > Best Regards, > -Steve >=20 >> The scenario is as follows: >>=20 >> 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: >>=20 >> static void handle_event(auparse_state_t *au, auparse_cb_event_t >> cb_event_type, void *user_data) { >> int type, num =3D 0; >>=20 >> if (cb_event_type !=3D AUPARSE_CB_EVENT_READY) >> return; >>=20 >> while (auparse_goto_record_num(au, num) > 0) { >> type =3D auparse_get_type(au); >>=20 >> // dump whole record >> printf("%s: %s\n", >> audit_msg_type_to_name(auparse_get_type(au)), >> auparse_get_record_text(au)); >>=20 >> num++; >> } >> } >>=20 >> 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). >>=20 >> 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. >>=20 >> 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): >>=20 >> /* Now the event loop */ >> if (!stop && !hup && retval > 0) { >> ssize_t bytesRead =3D read(0, tmp, MAX_AUDIT_MESSAGE_LENGTH); >> if (bytesRead > 0) { >> // this is just for printf >> tmp[bytesRead] =3D '\0'; >> printf("Read %d bytes from socket: %s", bytesRead, tmp); >>=20 >> auparse_feed(au, tmp, bytesRead); >> } >> } >>=20 >> 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. >>=20 >> Thanks for any help in advance! >> Lukas >>=20 >>=20 >> -- >> Linux-audit mailing list >> Linux-audit@redhat.com >> https://www.redhat.com/mailman/listinfo/linux-audit = --Apple-Mail=_023FF301-4E4E-49EF-81E6-59C4879498DA Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=us-ascii
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 =3D -1;
+ =               int read_size =3D = 0;
 
      =           /* Load configuration */
                if = (hup) {
@@ -121,14 +123,17 @@ int main(int argc, = char *argv[])
          =       } while (retval =3D=3D -1 && errno =3D=3D = 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 =3D = read(0, tmp, MAX_AUDIT_MESSAGE_LENGTH)) > 0) {
+ =                auparse_feed(au, = tmp, strnlen(tmp, read_size));
+     =        }
+       =  }
+       =  auparse_flush_feed(au);
+     =    if (read_size =3D=3D 0) {/* check eof */
+            syslog(LOG_INFO, = "EXITING MAIN LOOP");
+         =    break;
+       =  }
+        if (read_size = =3D=3D 0)
            =             break;
        } while (stop =3D=3D = 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> wrote:

Hi All,

I'm, having problems with the example audisp plugin from
https://github.com/linux-audit/audit-userspace/blob/master/cont= rib/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 =3D 0;

   if (cb_event_type !=3D = AUPARSE_CB_EVENT_READY)
       return;

   while = (auparse_goto_record_num(au, num) > 0) {
       type =3D = 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 =3D read(0, tmp, = MAX_AUDIT_MESSAGE_LENGTH);
   if (bytesRead = > 0) {
       // = this is just for printf
       tmp[bytesRead] =3D = '\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

= --Apple-Mail=_023FF301-4E4E-49EF-81E6-59C4879498DA-- --===============3649156790367919020== Content-Type: text/plain; charset="us-ascii" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit Content-Disposition: inline --===============3649156790367919020==--