Wazuh: FIM: Some Auditd modified-events are dropped when monitoring several directories

[0xN3utr0n]

|Wazuh version|Component|Install type|Install method|Platform|
|---|---|---|---|---|
| 3319-fim-rework-sqlite | Syscheckd | Agent | ALL | Linux |

Description

As shown in the following ossec.log, a few modified events are dropped as soon as they arrive to audit_parse(). It would seem they have either an invalid key (above 3) or an invalid format.

2020/03/11 15:42:11 ossec-syscheckd[28689] syscheck_audit.c:1372 at filterkey_audit_events(): DEBUG: (6251): Match audit_key: 'key="wazuh_fim"'
2020/03/11 15:42:11 ossec-syscheckd[28689] syscheck_audit.c:868 at audit_parse(): DEBUG: (6247): audit_event: uid=root, auid=centos, euid=root, gid=root, pid=11737, ppid=11736, inode=4405832, path=/testdir57/regular, pname=/usr/bin/python3.6
2020/03/11 15:42:11 ossec-syscheckd[28689] syscheck_audit.c:1372 at filterkey_audit_events(): DEBUG: (6251): Match audit_key: 'key="wazuh_fim"'
2020/03/11 15:42:11 ossec-syscheckd[28689] syscheck_audit.c:847 at audit_parse(): DEBUG: (6247): audit_event: uid=root, auid=centos, euid=root, gid=root, pid=11737, ppid=11736, inode=4405832, path=/testdir57/regular, pname=/usr/bin/python3.6
2020/03/11 15:42:11 ossec-syscheckd[28689] syscheck_audit.c:1372 at filterkey_audit_events(): DEBUG: (6251): Match audit_key: 'key="wazuh_fim"'
2020/03/11 15:42:11 ossec-syscheckd[28689] syscheck_audit.c:1372 at filterkey_audit_events(): DEBUG: (6251): Match audit_key: 'key="wazuh_fim"'
2020/03/11 15:42:11 ossec-syscheckd[28689] syscheck_audit.c:1372 at filterkey_audit_events(): DEBUG: (6251): Match audit_key: 'key="wazuh_fim"'
2020/03/11 15:42:11 ossec-syscheckd[28689] syscheck_audit.c:1372 at filterkey_audit_events(): DEBUG: (6251): Match audit_key: 'key="wazuh_fim"'
2020/03/11 15:42:11 ossec-syscheckd[28689] syscheck_audit.c:1372 at filterkey_audit_events(): DEBUG: (6251): Match audit_key: 'key="wazuh_fim"'
2020/03/11 15:42:11 ossec-syscheckd[28689] syscheck_audit.c:1372 at filterkey_audit_events(): DEBUG: (6251): Match audit_key: 'key="wazuh_fim"'
2020/03/11 15:42:12 ossec-syscheckd[28689] syscheck_audit.c:1372 at filterkey_audit_events(): DEBUG: (6251): Match audit_key: 'key="wazuh_fim"'

The last 7 events, out of 64, do not show any debug information aside from the one of filterkey_audit_events(), which is used within audit_parse(), at the very beggining.

Configuration

<syscheck><disabled>no</disabled><directories whodata="yes">/testdir0,/testdir1,/testdir2,/testdir3,/testdir4,/testdir5,/testdir6,/testdir7,/testdir8,/testdir9,/testdir10,/testdir11,/testdir12,/testdir13,/testdir14,/testdir15,/testdir16,/testdir17,/testdir18,/testdir19,/testdir20,/testdir21,/testdir22,/testdir23,/testdir24,/testdir25,/testdir26,/testdir27,/testdir28,/testdir29,/testdir30,/testdir31,/testdir32,/testdir33,/testdir34,/testdir35,/testdir36,/testdir37,/testdir38,/testdir39,/testdir40,/testdir41,/testdir42,/testdir43,/testdir44,/testdir45,/testdir46,/testdir47,/testdir48,/testdir49,/testdir50,/testdir51,/testdir52,/testdir53,/testdir54,/testdir55,/testdir56,/testdir57,/testdir58,/testdir59,/testdir60,/testdir61,/testdir62,/testdir63</directories></syscheck>

To replicate the issue run: test_fim/test_multiple_dirs/test_multiple_dirs.py

[0xN3utr0n]

Related https://github.com/wazuh/wazuh/issues/4660

[jotacarma90]

This issue comes out from the same problem as:
https://github.com/wazuh/wazuh/issues/4660
As we know, whodata cannot process large numbers of events if they appear in a very short time interval.
This issue arises from the test:
test_fim/test_multiple_dirs/test_multiple_dirs.py
I have tested it, 64 added, modified and deleted. Of these, the added ones appear all, but modified and deleted only appear about 30-40 of each.
By adjusting the audit settings and the rt_delay of syscheck, more than 50 of the mentioned events appear. This leads me to think that, in fact, the problem is the great amount of events in a very small interval of time.

[jotacarma90]

New analysis for the problem of whodata event loss

Configured a directory with whodata:
/testdir
Generated 1000 files inside:
for i in {1..1000}; do echo "hola" >> file_test_${i} ; done

Result

• 1000 events in the audit log (in order and without remixing)
• 127 modified events in the ossec.log
• With a counter in audit_parse(), it enters the function 180 times

I am printing the buffer in audit_parse() every time is full

Logs:
audit.log
ossec.log

[jotacarma90]

After this last analysis, we have been able to verify that the problem is on the side of the audit dispatcher daemon, audisp.
On the wazuh side, the socket that receives the audit logs starts to lose events when it reaches a certain amount:

node=ubuntutest type=SYSCALL msg=audit(1607101583.160:8480): arch=c000003e syscall=257 success=yes exit=3 a0=ffffff9c a1=55d5318b9810 a2=441 a3=1b6 items=2 ppid=2591 pid=2595 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts3 ses=8 comm="bash" exe="/bin/bash" key="wazuh_fim"
node=ubuntutest type=CWD msg=audit(1607101583.160:8480): cwd="/testdir"
node=ubuntutest type=PATH msg=audit(1607101583.160:8480): item=0 name="/testdir" inode=786433 dev=08:03 mode=040755 ouid=0 ogid=0 rdev=00:00 nametype=PARENT cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
node=ubuntutest type=PATH msg=audit(1607101583.160:8480): item=1 name="file_test_144" inode=786581 dev=08:03 mode=0100644 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
node=ubuntutest type=PROCTITLE msg=audit(1607101583.160:8480): proctitle="bash"
node=ubuntutest type=EOE msg=audit(1607101583.160:8480): 
node=ubuntutest type=SYSCALL msg=audit(1607101583.160:8481): arch=c000003e syscall=257 success=yes exit=3 a0=ffffff9c a1=55d5318a5220 a2=441 a3=1b6 items=2 ppid=2591 pid=2595 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts3 ses=8 comm="bash" exe="/bin/bash" key="wazuh_fim"
node=ubuntutest type=CWD msg=audit(1607101583.160:8481): cwd="/testdir"
node=ubuntutest type=PATH msg=audit(1607101583.160:8481): item=0 name="/testdir" inode=786433 dev=08:03 mode=040755 ouid=0 ogid=0 rdev=00:00 nametype=PARENT cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
node=ubuntutest type=PATH msg=audit(1607101583.160:8481): item=1 name="file_test_145" inode=786582 dev=08:03 mode=0100644 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
node=ubuntutest type=PROCTITLE msg=audit(1607101583.160:8481): proctitle="bash"
node=ubuntutest type=EOE msg=audit(1607101583.160:8481): 
node=ubuntutest type=PATH msg=audit(1607101583.164:8559): item=1 name="file_test_223" inode=786660 dev=08:03 mode=0100644 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
node=ubuntutest type=PATH msg=audit(1607101583.164:8651): item=1 name="file_test_315" inode=786752 dev=08:03 mode=0100644 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
node=ubuntutest type=PATH msg=audit(1607101583.168:8709): item=1 name="file_test_373" inode=786810 dev=08:03 mode=0100644 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
node=ubuntutest type=SYSCALL msg=audit(1607101583.176:8853): arch=c000003e syscall=257 success=yes exit=3 a0=ffffff9c a1=55d5318b97d0 a2=441 a3=1b6 items=2 ppid=2591 pid=2595 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts3 ses=8 comm="bash" exe="/bin/bash" key="wazuh_fim"
node=ubuntutest type=PATH msg=audit(1607101583.188:9081): item=1 name="file_test_745" inode=787182 dev=08:03 mode=0100644 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
node=ubuntutest type=PROCTITLE msg=audit(1607101583.188:9081): proctitle="bash"
node=ubuntutest type=EOE msg=audit(1607101583.188:9081): 
node=ubuntutest type=SYSCALL msg=audit(1607101583.188:9082): arch=c000003e syscall=257 success=yes exit=3 a0=ffffff9c a1=55d5318b97b0 a2=441 a3=1b6 items=2 ppid=2591 pid=2595 auid=1000 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=pts3 ses=8 comm="bash" exe="/bin/bash" key="wazuh_fim"
node=ubuntutest type=CWD msg=audit(1607101583.188:9082): cwd="/testdir"
node=ubuntutest type=PATH msg=audit(1607101583.188:9082): item=0 name="/testdir" inode=786433 dev=08:03 mode=040755 ouid=0 ogid=0 rdev=00:00 nametype=PARENT cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
node=ubuntutest type=PATH msg=audit(1607101583.188:9082): item=1 name="file_test_746" inode=787183 dev=08:03 mode=0100644 ouid=0 ogid=0 rdev=00:00 nametype=NORMAL cap_fp=0000000000000000 cap_fi=0000000000000000 cap_fe=0 cap_fver=0
node=ubuntutest type=PROCTITLE msg=audit(1607101583.188:9082): proctitle="bash"
node=ubuntutest type=EOE msg=audit(1607101583.188:9082): 

One of the possible configurations that we can read in the audisp manual, is:

q_depth

• _This is a numeric value that tells how big to make the internal queue of the audit event dispatcher. A bigger queue lets it handle a flood of events better, but could hold events that are not processed when the daemon is terminated. If you get messages in syslog about events getting dropped, increase this value. The default value is 80._

This value is the one that limits the number of events that audisp can process, so increasing it, and restarting auditd, allows audisp to have the capacity to send all the necessary audit events to the Wazuh socket, which will then be able to process all the alerts that are expected from whodata.
Making the same test performed previously, with the modified audisp configuration (q_depth = 2500), we can see that Wazuh generates the same number of events as audit logs:

Therefore, we conclude that the only solution to this problem, is to manually change the audisp configuration (/etc/audisp/audispd.conf) adjusting it to the amount of whodata events that we expect at the same time.