From mboxrd@z Thu Jan 1 00:00:00 1970 From: Lukas Rupprecht Subject: Events Delayed in Example audisp Plugin Date: Fri, 5 Apr 2019 11:35:03 -0700 Message-ID: <701671D3-DD66-4462-89E1-0849CB1BBFCF@gmail.com> Mime-Version: 1.0 (Mac OS X Mail 11.5 \(3445.9.1\)) Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Return-path: Received: from mx1.redhat.com (ext-mx17.extmail.prod.ext.phx2.redhat.com [10.5.110.46]) by smtp.corp.redhat.com (Postfix) with ESMTPS id 2759C17265 for ; Fri, 5 Apr 2019 18:35:08 +0000 (UTC) Received: from mail-qt1-f174.google.com (mail-qt1-f174.google.com [209.85.160.174]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) by mx1.redhat.com (Postfix) with ESMTPS id 73B823082E4F for ; Fri, 5 Apr 2019 18:35:07 +0000 (UTC) Received: by mail-qt1-f174.google.com with SMTP id h39so8564088qte.2 for ; Fri, 05 Apr 2019 11:35:07 -0700 (PDT) Received: from lukass-mbp.almaden.ibm.com ([76.224.107.174]) by smtp.gmail.com with ESMTPSA id f191sm5232498qke.28.2019.04.05.11.35.05 for (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Fri, 05 Apr 2019 11:35:05 -0700 (PDT) List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Sender: linux-audit-bounces@redhat.com Errors-To: linux-audit-bounces@redhat.com To: linux-audit@redhat.com List-Id: linux-audit@redhat.com 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