<html dir="ltr"><head></head><body style="text-align:left; direction:ltr;"><div>On Tue, 2021-01-05 at 07:12 +1100, Burn Alting wrote:</div><blockquote type="cite" style="margin:0 0 0 .8ex; border-left:2px #729fcf solid;padding-left:1ex"><div>On Mon, 2021-01-04 at 09:46 -0500, Steve Grubb wrote:</div><blockquote type="cite" style="margin:0 0 0 .8ex; border-left:2px #729fcf solid;padding-left:1ex"><pre>On Monday, January 4, 2021 2:55:25 AM EST Burn Alting wrote:</pre><blockquote type="cite" style="margin:0 0 0 .8ex; border-left:2px #729fcf solid;padding-left:1ex"><pre>On Sun, 2021-01-03 at 10:41 -0500, Steve Grubb wrote:</pre><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</pre><pre>seconds past co- located events which results in</pre><pre>auparse:au_check_events() marking these events complete before they</pre><pre>are. An example of this can be seen below with the offending event id</pre><pre>44609.</pre><br><pre>This has been plaguing me for a year or two and this morning was the</pre><pre>first time I still had access to the raw audit.log files (I monitor a lot</pre><pre>of 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><br><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><br><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</pre><pre>on a record by record basis. It does not collect events until they are</pre><pre>complete - it dumps it to disk as soon as it can tack on the extra</pre><pre>information.</pre><br><pre>So, the question would be, does this delay happen on the way to disk? Or</pre><pre>is this an artifact of post processing the logs with an auparse based</pre><pre>utility? Can this be observed repeatedly on the same raw logs? If so,</pre><pre>then maybe auparse does have some issue. But if this is a post</pre><pre>processing issue, then the wall clock doesn't matter because this event</pre><pre>should have collected up together.</pre><br><pre>I'd say this merits some investigation.</pre></blockquote><br><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</pre><pre>would suggest we modify auparse.c:au_check_events() to i) perform the</pre><pre>event type checks first, then</pre><pre> ii) increase the timeout of 2 seconds to be a larger value based on</pre><pre>empirical tests.</pre></blockquote><br><pre>In the post processing, there are 2 use cases. The first is events that are on </pre><pre>disk. In this usage, the 2 second timeout does not come into effect because </pre><pre>the events are run through probably within nanoseconds or microseconds at the </pre><pre>worst. The only time it would come into effect is if the terminating record </pre><pre>is missing.</pre></blockquote><div><br></div><div>In this first case, the 2 second timeout is on the event's time, not the 'processing time'. See ausearch-lol.c:check_events() and auparse.c:au_get_ready_event().</div><div>And I use the checkpointing code to avoid the incomplete event issue.</div><div><br></div><div>In my case, I have not lost records, it's just that an event has arrived on disk with an event time more than 2 seconds after the previously written event.</div><div>Basically,</div><div>a. The event was delayed getting to auditd and we look to the kernel for a solution.</div><div>b. The event arrived at a reasonable point in time at auditd and for some reason auditd delayed it's printing (by the way I tend to use RAW log format, not enriched.</div><div><br></div><div>In either case, I believe ausearch-lol.c:check_events() and auparse.c:au_get_ready_event() do need to be changed as we have complete events written by auditd</div><div>which these two routines fail to process properly.</div><div><br></div></blockquote><div>Changing the two second timeout in ausearch-lol.c:check_events() and, one assumes in auparse.c:au_get_ready_event() (but I have not tested the auparse code) fixes the processing of the delayed event.</div><div>Changing the value to say 10 seconds fixes my example use case, but given the kernel or auditd could emit an event with a larger delay, should this be a configuration item in /etc/audit/auditd.conf?</div><div><br></div><div>I have raised both a bugzilla report (<a href="https://bugzilla.redhat.com/show_bug.cgi?id=1914603">https://bugzilla.redhat.com/show_bug.cgi?id=1914603</a>) and Issue (<a href="https://github.com/linux-audit/audit-userspace/issues/148">https://github.com/linux-audit/audit-userspace/issues/148</a>)</div><div><br></div><div>How do you want me to proceed ... a simple change to 10 seconds or a more versatile configuration item in auditd.conf?</div><div>I can perform either and issue a PR if so required.</div><div> </div><blockquote type="cite" style="margin:0 0 0 .8ex; border-left:2px #729fcf solid;padding-left:1ex"><blockquote type="cite" style="margin:0 0 0 .8ex; border-left:2px #729fcf solid;padding-left:1ex"><br><pre>The other use case is realtime processing as an audispd plugin. In this use </pre><pre>case the wall clock could matter because records could potentially get lost </pre><pre>due to overflows or another plugin taking too long. This is the use case where </pre><pre>the wall clock matters. And again, it matters when records get lost or </pre><pre>delayed in transit. As long as everything is flowing, it should not factor </pre><pre>into event processing.</pre><br><blockquote type="cite" style="margin:0 0 0 .8ex; border-left:2px #729fcf solid;padding-left:1ex"><pre>B. I will build a temporary auditd daemon to perform some empirical testing</pre><pre>to see how long events can reside within the daemon. I may need some</pre><pre>advice on this. I assume that the code that sets the timestamp is in</pre><pre>src/auditd.c:send_audit_event().</pre></blockquote><br><pre>This is only for audit daemon's internal events. For all "real" events, it's </pre><pre>set in the kernel.</pre></blockquote><div><br></div><div>If that is the case and the kernel is establishing the timestamp, then either the kernel has delayed the events</div><div>arrival at the daemon or the daemon has delayed it's writing.</div><div><br></div><blockquote type="cite" style="margin:0 0 0 .8ex; border-left:2px #729fcf solid;padding-left:1ex"><br><blockquote type="cite" style="margin:0 0 0 .8ex; border-left:2px #729fcf solid;padding-left:1ex"><pre>If so, I will see if I can put orchestration debug code in to monitor an</pre><pre>event's 'time in daemon' until this point. I will then report on this.</pre><br><pre>I believe given that AUDIT_PROCTITLE and AUDIT_EOE is fairly widespread,</pre><pre>then the testing switch in A. will not be a big issue (time cost wise). It</pre><pre>will also mean that if we over compensate the timeout that would cause</pre><pre>additional memory cost in auparse() then this is mittigated.</pre></blockquote><br><pre>I'd suggest breaking up the event completion tests so that an exact </pre><pre>collection termination reason code could be associated to the event.</pre><br><blockquote type="cite" style="margin:0 0 0 .8ex; border-left:2px #729fcf solid;padding-left:1ex"><pre>With respect to 'There may be more' fronts. Are there other points in the</pre><pre>'audit ecosystem' that makes use of the '2 second timeout'.</pre></blockquote><br><pre>Ausearch/report has its own special copy of the event collection logic. It </pre><pre>should be nearly identical to what auparse does.</pre></blockquote><div><br></div><div>They appear identical ... ausearch-lol.c:check_events() and auparse.c:au_get_ready_event().</div><blockquote type="cite" style="margin:0 0 0 .8ex; border-left:2px #729fcf solid;padding-left:1ex"><br><blockquote type="cite" style="margin:0 0 0 .8ex; border-left:2px #729fcf solid;padding-left:1ex"><pre>I will start work on this, this coming weekend if the above makes sense.</pre></blockquote><br><pre>One other thought, the current shipping code is audit-3.0, doing a diff </pre><pre>between it and audit-2.8.5 for the auparse directory does show some </pre><pre>differences in event collection/grouping/next_event. A lot of the differences </pre><pre>are cosmetic to fix extra whitespace or indentation. But if you skip all that, </pre><pre>there are some real changes that probably were because of bug reports. For </pre><pre>example,</pre></blockquote><br><pre>I will go through these, although this occurs on my Centos 7's (audit-2.8.5-4.el7.x86_64) as well as my 8's (audit-3.0-0.17.20191104git1c2f876.el8.x86_64).</pre><br><blockquote type="cite" style="margin:0 0 0 .8ex; border-left:2px #729fcf solid;padding-left:1ex"><br><pre>@@ -259,15 +260,6 @@ static event_list_t *au_get_ready_event(</pre><pre> if (lowest && lowest->status == EBS_COMPLETE) {</pre><pre> lowest->status = EBS_EMPTY;</pre><pre> au->au_ready--;</pre><pre>- // Try to consolidate the array so that we iterate</pre><pre>- // over a smaller portion next time</pre><pre>- if (lowest == &lol->array[lol->maxi]) {</pre><pre>- au_lolnode *ptr = lowest;</pre><pre>- while (ptr->status == EBS_EMPTY && lol->maxi > 0) {</pre><pre>- lol->maxi--;</pre><pre>- ptr = &lol->array[lol->maxi];</pre><pre>- }</pre><pre>- }</pre><pre> return lowest->l;</pre><pre> }</pre><br><pre>and</pre><br><pre>@@ -1536,6 +1550,13 @@ static int au_auparse_next_event(auparse</pre><pre> aup_list_create(l);</pre><pre> aup_list_set_event(l, &e);</pre><pre> aup_list_append(l, au->cur_buf, au->list_idx, au-</pre><blockquote type="cite" style="margin:0 0 0 .8ex; border-left:2px #729fcf solid;padding-left:1ex"><pre>line_number);</pre></blockquote><pre>+ // Eat standalone EOE - main event was already marked </pre><pre>complete</pre><pre>+ if (l->head->type == AUDIT_EOE) {</pre><pre>+ au->cur_buf = NULL;</pre><pre>+ aup_list_clear(l);</pre><pre>+ free(l);</pre><pre>+ continue;</pre><pre>+ }</pre><pre> if (au_lol_append(au->au_lo, l) == NULL) {</pre><pre> free((char *)e.host);</pre><pre> #ifdef LOL_EVENTS_DEBUG01</pre><br><pre>I don't know if those have an effect on what you are seeing. But that is the </pre><pre>only substantial changes that I can see.</pre><br><pre>-Steve</pre></blockquote></blockquote><div><br></div><div>Burn</div></body></html>