From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-6.0 required=3.0 tests=BAYES_00,DKIMWL_WL_HIGH, DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,HEADER_FROM_DIFFERENT_DOMAINS, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS autolearn=no autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id CB8CBC433E0 for ; Sun, 3 Jan 2021 15:41:27 +0000 (UTC) Received: from us-smtp-delivery-124.mimecast.com (us-smtp-delivery-124.mimecast.com [216.205.24.124]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-SHA384 (256/256 bits)) (No client certificate requested) by mail.kernel.org (Postfix) with ESMTPS id 5AF182080D for ; Sun, 3 Jan 2021 15:41:26 +0000 (UTC) DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org 5AF182080D Authentication-Results: mail.kernel.org; dmarc=fail (p=none dis=none) header.from=redhat.com Authentication-Results: mail.kernel.org; spf=tempfail smtp.mailfrom=linux-audit-bounces@redhat.com DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=redhat.com; s=mimecast20190719; t=1609688486; h=from:from:sender:sender:reply-to:subject:subject:date:date: message-id:message-id:to:to:cc:mime-version:mime-version: content-type:content-type: content-transfer-encoding:content-transfer-encoding: in-reply-to:in-reply-to:references:references:list-id:list-help: list-unsubscribe:list-subscribe:list-post; bh=MSbB4ltrynVNrxDduzYblTq15m2d+yM87Ur97kn+Dp8=; b=AGC0wzZjhA/c4WJSeuO6Nz7sDnr2JsB+3CG8/P51757CfE6+7q+93HU8n4vIowVS7BlUCq h/os83x0n0oFkEMl6ZO/JMfD4cigxR2p2haJEI1UE94I87nNYOWh+lzFjjkvE4AQhQo32p xrA8xtjczAiOehUqzMTZW45SDT7BY3o= Received: from mimecast-mx01.redhat.com (mimecast-mx01.redhat.com [209.132.183.4]) (Using TLS) by relay.mimecast.com with ESMTP id us-mta-225-dExh6N-dNBmFXgX0JHk69g-1; Sun, 03 Jan 2021 10:41:23 -0500 X-MC-Unique: dExh6N-dNBmFXgX0JHk69g-1 Received: from smtp.corp.redhat.com (int-mx01.intmail.prod.int.phx2.redhat.com [10.5.11.11]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mimecast-mx01.redhat.com (Postfix) with ESMTPS id 0211B10054FF; Sun, 3 Jan 2021 15:41:19 +0000 (UTC) Received: from colo-mx.corp.redhat.com (colo-mx02.intmail.prod.int.phx2.redhat.com [10.5.11.21]) by smtp.corp.redhat.com (Postfix) with ESMTPS id F0D2860657; Sun, 3 Jan 2021 15:41:14 +0000 (UTC) Received: from lists01.pubmisc.prod.ext.phx2.redhat.com (lists01.pubmisc.prod.ext.phx2.redhat.com [10.5.19.33]) by colo-mx.corp.redhat.com (Postfix) with ESMTP id B54384BB7B; Sun, 3 Jan 2021 15:41:11 +0000 (UTC) Received: from smtp.corp.redhat.com (int-mx04.intmail.prod.int.phx2.redhat.com [10.5.11.14]) by lists01.pubmisc.prod.ext.phx2.redhat.com (8.13.8/8.13.8) with ESMTP id 103Ff8aL025341 for ; Sun, 3 Jan 2021 10:41:08 -0500 Received: by smtp.corp.redhat.com (Postfix) id D83E55D9D5; Sun, 3 Jan 2021 15:41:08 +0000 (UTC) Received: from x2.localnet (ovpn-113-86.rdu2.redhat.com [10.10.113.86]) by smtp.corp.redhat.com (Postfix) with ESMTP id 5EB3C5D9D3; Sun, 3 Jan 2021 15:41:04 +0000 (UTC) From: Steve Grubb To: Linux Audit Subject: Re: Occasional delayed output of events Date: Sun, 03 Jan 2021 10:41:02 -0500 Message-ID: <5426593.DvuYhMxLoT@x2> Organization: Red Hat In-Reply-To: <30c5dbc14368a1919717e2f39d2d4c29463c3108.camel@iinet.net.au> References: <30c5dbc14368a1919717e2f39d2d4c29463c3108.camel@iinet.net.au> MIME-Version: 1.0 X-Scanned-By: MIMEDefang 2.79 on 10.5.11.14 X-loop: linux-audit@redhat.com X-BeenThere: linux-audit@redhat.com X-Mailman-Version: 2.1.12 Precedence: junk List-Id: Linux Audit Discussion List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Sender: linux-audit-bounces@redhat.com Errors-To: linux-audit-bounces@redhat.com X-Scanned-By: MIMEDefang 2.79 on 10.5.11.11 Authentication-Results: relay.mimecast.com; auth=pass smtp.auth=CUSA124A263 smtp.mailfrom=linux-audit-bounces@redhat.com X-Mimecast-Spam-Score: 0 X-Mimecast-Originator: redhat.com Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit On Friday, January 1, 2021 4:22:33 PM EST Burn Alting wrote: > Sometimes, events recorded in /var/log/audit/audit.log appear some seconds > past co- located events which results in auparse:au_check_events() marking > these events complete before they are. An example of this can be seen > below with the offending event id 44609. > > This has been plaguing me for a year or two and this morning was the first > time I still had access to the raw audit.log files (I monitor a lot of > event types and the log files roll over fairly quickly). > The example below is from a fully patched Centos 7 but I have also seen > this on a patched Fedora 32. > > Has this been seen before? Do we need to re-evaluate how auparse > 'completes' an event (ie 2 seconds is too quick). I have never seen this. But on the way to disk, auditd only does light processing of the event. If the format is enriched, it looks things up on a record by record basis. It does not collect events until they are complete - it dumps it to disk as soon as it can tack on the extra information. So, the question would be, does this delay happen on the way to disk? Or is this an artifact of post processing the logs with an auparse based utility? Can this be observed repeatedly on the same raw logs? If so, then maybe auparse does have some issue. But if this is a post processing issue, then the wall clock doesn't matter because this event should have collected up together. I'd say this merits some investigation. -Steve -- Linux-audit mailing list Linux-audit@redhat.com https://www.redhat.com/mailman/listinfo/linux-audit