<html dir="ltr"><head></head><body style="text-align:left; direction:ltr;"><div>On Sun, 2021-01-03 at 10:41 -0500, Steve Grubb wrote:</div><blockquote type="cite" style="margin:0 0 0 .8ex; border-left:2px #729fcf solid;padding-left:1ex"><pre>On Friday, January 1, 2021 4:22:33 PM EST Burn Alting wrote:</pre><blockquote type="cite" style="margin:0 0 0 .8ex; border-left:2px #729fcf solid;padding-left:1ex"><pre>Sometimes, events recorded in /var/log/audit/audit.log appear some seconds</pre><pre>past co- located events which results in auparse:au_check_events() marking</pre><pre>these events complete before they are. An example of this can be seen</pre><pre>below with the offending event id 44609.</pre><pre> </pre><pre>This has been plaguing me for a year or two and this morning was the first</pre><pre>time I still had access to the raw audit.log files (I monitor a lot of</pre><pre>event types and the log files roll over fairly quickly).</pre><pre>The example below is from a fully patched Centos 7 but I have also seen</pre><pre>this on a patched Fedora 32.</pre><pre> </pre><pre>Has this been seen before? Do we need to re-evaluate how auparse</pre><pre>'completes' an event (ie 2 seconds is too quick).</pre></blockquote><pre> </pre><pre>I have never seen this. But on the way to disk, auditd only does light </pre><pre>processing of the event. If the format is enriched, it looks things up on a </pre><pre>record by record basis. It does not collect events until they are complete - </pre><pre>it dumps it to disk as soon as it can tack on the extra information.</pre><pre> </pre><pre>So, the question would be, does this delay happen on the way to disk? Or is </pre><pre>this an artifact of post processing the logs with an auparse based utility? </pre><pre>Can this be observed repeatedly on the same raw logs? If so, then maybe </pre><pre>auparse does have some issue. But if this is a post processing issue, then </pre><pre>the wall clock doesn't matter because this event should have collected up </pre><pre>together.</pre><pre> </pre><pre>I'd say this merits some investigation.</pre></blockquote><pre> </pre><pre>OK. I think this needs to be addressed on two fronts. There may be more.</pre><pre>A. Within post processing ... a 2 second timeout is not sufficient. I would suggest we modify auparse.c:au_check_events() to</pre><pre> i) perform the event type checks first, then</pre><pre> ii) increase the timeout of 2 seconds to be a larger value based on empirical tests.</pre><pre> </pre><pre>B. I will build a temporary auditd daemon to perform some empirical testing to see how long events can reside within the daemon. I may need some advice on this.</pre><pre>I assume that the code that sets the timestamp is in src/auditd.c:send_audit_event(). If so, I will see if I can put orchestration debug code in to monitor an event's</pre><pre>'time in daemon' until this point. I will then report on this.</pre><pre> </pre><pre>I believe given that AUDIT_PROCTITLE and AUDIT_EOE is fairly widespread, then the testing switch in A. will not be a big issue (time cost wise). It will also mean that if we</pre><pre>over compensate the timeout that would cause additional memory cost in auparse() then this is mittigated.</pre><pre> </pre><pre>With respect to 'There may be more' fronts. Are there other points in the 'audit ecosystem' that makes use of the '2 second timeout'.</pre><pre> </pre><pre>I will start work on this, this coming weekend if the above makes sense.</pre><pre> </pre><pre>Regards</pre><pre>Burn</pre><pre> </pre></body></html>