Auditd event is not composed fully by audit log_format

[Roman]

Hello, 

I faced an issue with some events from auditd. Seemingly identical events composed differently by wazuh. 

event_ok is composed, decoded correctly. 

event_f is not composed and consists only of one line type=SYSCALL, although in audit.log there are other blocks with same id (msg=audit). 

That leads to empty event in wazuh dashboard which can't be analyzed (no arguments, no path, etc.).

Could you please help me with troubleshooting of this issue?

[fabio.c...@wazuh.com]

Hello Roman,

Looking at the raw files, both events actually have the same structure, including a `nametype=NORMAL` that appears split across two physical lines in the PATH record.

Can you check the raw audit.log directly on the agent?
```
grep "7036003" /var/log/audit/audit.log
```

If the line-split is present in the original log, the next step is to confirm whether logcollector is failing because of it. You can check that with `logcollector.debug=2`, so you'd need to temporarily enable that in `internal_options.conf`:
```
logcollector.debug=2
```
Then after restarting and reproducing, check:
```
grep "invalid syntax" /var/ossec/logs/ossec.log | tail -20
```

Also, what's the agent version?
```
/var/ossec/bin/wazuh-control info
```

Greetings,

[Roman]

Hello, Fabio. 

Thank you for quick response. 

I'll enable debug on several agents and monitor the situation. It's quite random and audit.log rotates itself fast (default is 8Mb). I've changed default settings for audit.log rotation. I'll let you know, what I find. 

Agent version is

/var/ossec/bin/wazuh-control info
WAZUH_VERSION="v4.13.1"
WAZUH_REVISION="rc1"
WAZUH_TYPE="agent"

[Roman]

Hello, Fabio

I've got another event that is not composed. msg=audit(1774423861.441:7287850)

And what's unusual is that there is PROCTILE from previous event in the middle. Maybe that is what breaks compose.

type=EXECVE msg=audit(1774423861.438:7287849): ...
type=PATH msg=audit(1774423861.438:7287849): ...
type=PATH msg=audit(1774423861.438:7287849): ...
type=SYSCALL msg=audit(1774423861.441:7287850): arch=c000003e syscall=59 success=yes exit=0 a0=5595de126220 a1=5595de126b00 a2=5595de121a00 a3=8 items=2 ppid=3048132 pid=3048133 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="ip" exe="/usr/sbin/ip" subj=kernel key="sbin_susp" ARCH=x86_64 SYSCALL=execve AUID="unset" UID="root" GID="root" EUID="root" SUID="root" FSUID="root" EGID="root" SGID="root" FSGID="root"
type=PROCTITLE msg=audit(1774423861.438:7287849): proctitle=677265700064656661756C74
type=EXECVE msg=audit(1774423861.441:7287850): ...

But there are no errors in ossec.log

read_audit.c just reads the lines and goes on.

In the attachments are extract from audit.log, full ossec.log with debug=2

[fabio.c...@wazuh.com]

Hello Roman,

Thanks for sharing the additional logs, and sorry for the late response.

Your observation is correct. From the audit.log extract, the records are clearly interleaved between different audit IDs, with 7287849 and 7287850 appearing out of order (e.g., a PROCTITLE from 7287849 arriving after 7287850 has already started).

Looking at the implementation in read_audit.c, the collector maintains a single active event cache and flushes it immediately when the audit ID changes. Because of that, when events are interleaved:

• The first event is flushed before all its records arrive

• The next event can be flushed prematurely (e.g., only SYSCALL)

• Remaining records are processed later as a separate partial event

This matches exactly what you’re seeing.

On the auditd side, I couldn’t find evidence of what exactly cause this. Audit events are composed of multiple records (SYSCALL, EXECVE, PATH, PROCTITLE, etc.) and are not guaranteed to be written atomically. Under conditions like short-lived processes or bursts of activity, it’s possible for records from different events to be interleaved in the log.

Are you seeing this frequently or only in bursts of activity?

[Roman]

Hello, Fabio.

After observation posted in this conversation, I've started to notice similar problem in other events. Can't say if it's during the burst of activity but events definitely come in short period, almost simultaneously. And I'm noticing this behavior on different servers with different event conditions.

This is really worrisome. It means we can miss a high level alert if the event is not composed by wazuh. 

[fabio.c...@wazuh.com]

Hello Roman,

Thanks for the update.

I'm going to look into whether this interleaving behavior is expected from auditd under concurrent load, and I'll forward this internally so we can evaluate potential changes to handle it properly.

I'll keep you posted

[Roman]

Hi, 

any luck finding a solution? 

I've ended up filtering that type of events, although it's not a solution.

  <rule id="100000" level="0">
    <if_sid>80700</if_sid>
    <regex negate="yes">type=PROCTITLE\s+msg=audit\(\S+\):\s+proctitle=\w+$</regex>
    <description>Non composed event. Skipping.</description>
  </rule>

That way I filter out all events, that are missing PROCTITLE at the end, meaning it wasn't composed as it should.