auditd logrotation and imfile module cause lots of imfile-state files

[sterlij1]

Hi,

I'm using rhel 7.6 and running rsyslogd 8.24.0-52.el7 and audit-2.8.4-4.el7. Every time the audit daemon rotates it logs (internal to auditd not logrotate configuration) we get imfile-state files that remain on the file system indefinitely and I suspect are losing any messages that are still to be sent from the rotated audit log. Here is an example of this happening:-

[root@testing:/var/spool/rsyslog]#ls -ltr /var/spool/rsyslog/imfile-state:1* |tail -4
-rw-------. 1 root root 112 Oct 28 11:28 /var/spool/rsyslog/imfile-state:18:4369a2957393e7b1
-rw-------. 1 root root 112 Oct 28 11:31 /var/spool/rsyslog/imfile-state:19:ae91f8feb5b52fa5
-rw-------. 1 root root 100 Oct 28 11:34 /var/spool/rsyslog/imfile-state:13:ea1ccbfb3c71e85d
-rw-------. 1 root root 112 Oct 28 11:34 /var/spool/rsyslog/imfile-state:12:2edd93420c1c7d70
[root@testing:/var/spool/rsyslog]#ls -ltr /var/log/audit/ |tail -5
-r--------. 1 root root 104857836 Oct 28 11:25 audit.log.4
-r--------. 1 root root 104857634 Oct 28 11:28 audit.log.3
-r--------. 1 root root 104857626 Oct 28 11:31 audit.log.2
-r--------. 1 root root 104857696 Oct 28 11:34 audit.log.1
-rw-------. 1 root root 92821855 Oct 28 11:37 audit.log

I've read some similar bugs like

https://bugzilla.redhat.com/show_bug.cgi?id=1763746
https://bugzilla.redhat.com/show_bug.cgi?id=1744682

Originally I was using the legacy way of doing this with an audit.conf in rsyslog.d as follows..

$ModLoad imfile
$InputFileName /var/log/audit/audit.log
$InputFileTag audispd:
$InputFileStateFile audit_log
$InputFileSeverity info
$InputFileFacility local6
$InputRunFileMonitor

$WorkDirectory /var/spool/rsyslog # default location for work (spool) files

But having read some other bugs and docs I've tried to move to the following configuration..

audit logs to arcsight

module(load="imfile" mode="inotify")
input(type="imfile"
File="/var/log/audit/audit.log"
Tag="audispd:"
Severity="info"
Facility="local6"
deleteStateOnFileDelete="on")

But no luck.. Whatever I've tried I always get the same imfile-states in the rsyslog working directory. On some of our busy audit systems the log files rotate every few minutes and we end up with tens of thousands of state files.

I do not see this issue on our rhel7.3 boxes that run rsyslogd 7.4.7 and have the legacy "$ModLoad imfile" configuration mentioned above.

Hopefully there is enough information to get this investigated but if there is anything else I need to provide please let me know.

Regards

[atc0005]

FWIW, I've noticed that imfile state files have been accumulating on some Ubuntu boxes of ours in the same /var/spool/rsyslog directory since March 2019. I've not had enough time to really dig into it yet. I found this puzzling since we explicitly specify the workDirectory path as /var/lib/rsyslog for our systems:

global (
    # ...
    workDirectory="/var/lib/rsyslog"
    # ...
)

[zbukhari-apex]

This may be related to: rsyslog/rsyslog#4186

I'm running into this as well. A slew of versions but using Ubuntu:

No state file surprisingly but behaving as it should:
Trusty (i.e. 14.04) - 7.4.4-1ubuntu2.7
Xenial (i.e. 16.04) - 8.16.0-1ubuntu3.1

State file behaving as it should:
Bionic (i.e. 18.04) - 8.32.0-1ubuntu4.2

/var/spool/rsyslog contains imfile-state:-var-log-audit-audit.log it does not leave stale files around.

Problem started:
Focal (i.e. 20.04) - 8.2001.0-1ubuntu1.3
Jammy (i.e. 22.04) - 8.2112.0-2ubuntu2.2

/var/spool/rsyslog contains ... a lot of imfile-state:8620608:ffa5e1b5ced716b0 with the file ID hash changing and the old files not being cleaned up. Documentation says deleteStateOnFileDelete is set to on. It doesn't cleanup. I tried to set it explicitly, it still doesn't clean up. I tried legacy syntax, that doesn't work either. I tried different modes, still doesn't work.

I have debug output if desired. Current for 8.2112.0 but if it would help for another version, let me know and I can do that for you.

This became an issue as we use rsyslog to process and send auditd (i.e. linux-audit) logs. Some of our servers have a lot of activity and this caused us to run out of inodes. Very rare overall but a thing I'm sure many Linux admins do. There used to be an rsyslog wiki page which showed how to use rsyslog for auditd logging. That's pretty much our setup. I don't have that link anymore but it's probably going to be similar to this. We use UDP but pretty much the same setup.

https://linux-audit.com/central-audit-logging-configuration-collecting-linux-audit-events/

[zbukhari-apex]

I have noticed that the unlink call via strace does not have the actual file name. It shows it in the rsyslog debug logs but when performing strace -f -e trace=file -p PID_OF_RSYSLOG, the actual call is incomplete. It's like the filename is missing the last colon. Looking at the source I can't see where this is incorrect as the debug log prints out statefn. There is an unlink call below it unlink((char *)statefn);.

https://github.com/rsyslog/rsyslog/blob/master/plugins/imfile/imfile.c#L1063

In the rsyslog debug logs essentially (20 lines before and 20 lines after "deleting state file"):

4156.793236863:main Q:Reg/w0  : ruleset.c: Filter: check for property 'msg' (value 'type=SYSCALL msg=audit(1703184156.787:401897213): arch=c000003e syscall=59 success=no exit=-2 a0=7fba5f17b810 a1=7fba5f1bcfb0 a2=7ffe40ae9130 a3=0 items=1 ppid=3177174 pid=3177264 auid=4294967295 uid=1000 gid=1000 euid=1000 su
id=1000 fsuid=1000 egid=1000 sgid=1000 fsgid=1000 tty=(none) ses=4294967295 comm="python3" exe="/opt/omd/versions/2.2.0p8.cre/bin/python3.11" subj=? key="execve"') contains '[UFW ': FALSE
4156.793243671:main Q:Reg/w0  : ruleset.c: PROPFILT condition result is 0
4156.793247013:main Q:Reg/w0  : rainerscript.c:     PROPFILT
4156.793256812:main Q:Reg/w0  : rainerscript.c:         Property.: 'syslogtag'
4156.793266428:main Q:Reg/w0  : rainerscript.c:         Operation: 'isequal'
4156.793279165:main Q:Reg/w0  : rainerscript.c:         Value....: '[CLOUDINIT]'
4156.793288874:main Q:Reg/w0  : ruleset.c: Filter: check for property 'syslogtag' (value 'tag_audit_log') isequal '[CLOUDINIT]': FALSE
4156.793295697:main Q:Reg/w0  : ruleset.c: PROPFILT condition result is 0
4156.793299055:main Q:Reg/w0  : rainerscript.c:     PRIFILT 'local6.info'
4156.793308913:main Q:Reg/w0  : rainerscript.c:     pmask: 
4156.793317010:imfile.c       : imfile.c: removing old state file: '/var/spool/rsyslog/imfile-state:8620502'

4156.793318595:main Q:Reg/w0  : rainerscript.c:  X  X  X  X  X  X 4156.793340063:main Q:Reg/w0  : rainerscript.c:  X 
4156.793340122:imfile.c       : imfile.c: trying to delete no longer valid statefile '/var/spool/rsyslog/imfile-state:8620502' which no longer exists (probably already deleted)

4156.793343682:main Q:Reg/w0  : rainerscript.c:  X 4156.793346708:imfile.c       : strm 0x7fe920003280: stream.c: file 16(/var/log/audit/audit.log) closing, bDeleteOnClose 0

4156.793347651:main Q:Reg/w0  : rainerscript.c:  X 4156.793351455:imfile.c       : strm 0x7fe920003280: stream.c: file 16(/var/log/audit/audit.log) closing

4156.793352379:main Q:Reg/w0  : rainerscript.c:  X  X  X 
4156.793361611:imfile.c       : imfile.c: act_obj_destroy: deleting state file /var/spool/rsyslog/imfile-state:8620502:324c212b17bcc6a5

4156.793363474:main Q:Reg/w0  : rainerscript.c:  X  X  X  X  X  X  X  X  X  X 7F  X  X  X 
4156.793409474:main Q:Reg/w0  : ruleset.c: PRIFILT condition result is 1
4156.793412946:main Q:Reg/w0  : rainerscript.c:     ACTION 2 [builtin:omfwd:@rubberducky1.quack.quack:867]
4156.793422520:main Q:Reg/w0  : ruleset.c: executing action 2
4156.793426251:main Q:Reg/w0  : ../action.c: action 'action-2-builtin:omfwd': called, logging to builtin:omfwd (susp 0/0, direct q 1)
4156.793430284:main Q:Reg/w0  : ../action.c: action 'action-2-builtin:omfwd': is transactional - executing in commit phase
4156.793433705:main Q:Reg/w0  : ../action.c: actionPrepare[action-2-builtin:omfwd]: enter
4156.793437112:main Q:Reg/w0  : ../action.c: checking external state file
4156.793440629:main Q:Reg/w0  : ../action.c: done checking external state file, iRet=0
4156.793444108:main Q:Reg/w0  : omfwd.c: omfwd: beginTransaction
4156.793447611:main Q:Reg/w0  : omfwd.c: omfwd: doTryResume rubberducky1.quack.quack iRet 0
4156.793451074:main Q:Reg/w0  : ../action.c: action[action-2-builtin:omfwd] transitioned to state: itx
4156.793454689:main Q:Reg/w0  : ../action.c: action 'action-2-builtin:omfwd': set suspended state to 0
4156.793458102:main Q:Reg/w0  : rainerscript.c:     ACTION 3 [builtin:omfwd:@rubberducky2.quack.quack:5309]
4156.793467738:main Q:Reg/w0  : ruleset.c: executing action 3
4156.793471516:main Q:Reg/w0  : ../action.c: action 'action-3-builtin:omfwd': called, logging to builtin:omfwd (susp 0/0, direct q 1)
4156.793475204:main Q:Reg/w0  : ../action.c: action 'action-3-builtin:omfwd': is transactional - executing in commit phase
4156.793478688:main Q:Reg/w0  : ../action.c: actionPrepare[action-3-builtin:omfwd]: enter
4156.793483849:main Q:Reg/w0  : ../action.c: checking external state file

However strace never shows that with unlink. These aren't the same files as they were ran at different times but we only have state files for audit logs. /var/log/audit/audit.log:

[pid 3173847] openat(AT_FDCWD, "/var/spool/rsyslog/imfile-state:8620608:7c55a701dd8e041e", O_WRONLY|O_CREAT|O_NOCTTY|O_TRUNC|O_CLOEXEC, 0600) = 22
[pid 3173847] unlink("/var/spool/rsyslog/imfile-state:8620608") = -1 ENOENT (No such file or directory)
[pid 3173847] openat(AT_FDCWD, "/var/spool/rsyslog/imfile-state:8615038:ff0da1b277cd29f3", O_RDONLY|O_NOCTTY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid 3173847] openat(AT_FDCWD, "/var/spool/rsyslog/imfile-state:8615038", O_RDONLY|O_NOCTTY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid 3173847] newfstatat(AT_FDCWD, "/var/spool/rsyslog/imfile-state:-var-log-audit-audit.log", 0x7fe936e283f0, 0) = -1 ENOENT (No such file or directory)
[pid 3173847] openat(AT_FDCWD, "/var/spool/rsyslog/imfile-state:8615038:ff0da1b277cd29f3", O_WRONLY|O_CREAT|O_NOCTTY|O_TRUNC|O_CLOEXEC, 0600) = 22
[pid 3173847] unlink("/var/spool/rsyslog/imfile-state:8615038") = -1 ENOENT (No such file or directory)
[pid 3173847] openat(AT_FDCWD, "/var/spool/rsyslog/imfile-state:8615038:ff0da1b277cd29f3", O_WRONLY|O_CREAT|O_NOCTTY|O_TRUNC|O_CLOEXEC, 0600) = 22
[pid 3173847] unlink("/var/spool/rsyslog/imfile-state:8615038") = -1 ENOENT (No such file or directory)
[pid 3173847] openat(AT_FDCWD, "/var/spool/rsyslog/imfile-state:8620502:20b52b2c9d03a8cc", O_RDONLY|O_NOCTTY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid 3173847] openat(AT_FDCWD, "/var/spool/rsyslog/imfile-state:8620502", O_RDONLY|O_NOCTTY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid 3173847] newfstatat(AT_FDCWD, "/var/spool/rsyslog/imfile-state:-var-log-audit-audit.log", 0x7fe936e283f0, 0) = -1 ENOENT (No such file or directory)
[pid 3173847] openat(AT_FDCWD, "/var/spool/rsyslog/imfile-state:8620502:20b52b2c9d03a8cc", O_WRONLY|O_CREAT|O_NOCTTY|O_TRUNC|O_CLOEXEC, 0600) = 22
[pid 3173847] unlink("/var/spool/rsyslog/imfile-state:8620502") = -1 ENOENT (No such file or directory)
[pid 3173847] openat(AT_FDCWD, "/var/spool/rsyslog/imfile-state:8620502:20b52b2c9d03a8cc", O_WRONLY|O_CREAT|O_NOCTTY|O_TRUNC|O_CLOEXEC, 0600) = 22

Here via strace you can see the argument supplied to unlink is missing the file ID hash.

I found this to be similar - updated a month ago - trying to see if this will work: rsyslog/rsyslog#5258

[zbukhari-apex]

The fix used in #5258 did not work for me. Stale files are still left and the unlink call is not given the right argument.