Split audisp-syslog messages since update to 4.1.4

[heeplr]

I'm using audisp-syslog to log output. Since the last update on multiple boxes, some messages (not all) are split in two lines. (Those sometimes also arrive in the wrong order):

Example:

May 22 09:00:00 server audisp-syslog[14953]: n" exe="/usr/sbin/crond" hostname=? addr=? terminal=cron res=success' UID="root" AUID="munin"
May 22 09:00:00 server audisp-syslog[14953]: node=server.example.com type=CRED_REFR msg=audit(1779433200.325:3873588): pid=5929 uid=0 auid=177 ses=482584 msg='op=PAM:setcred grantors=pam_env,pam_faillock,pam_cap acct="muni

Message lengths differ and the split doesn't happen after a fixed amount of characters.

My plugins.d/syslog.conf should be pretty much the default:

active = yes
direction = out
path = /sbin/audisp-syslog
type = always
args = LOG_INFO
format = string

I can't completely rule out a syslog-ng bug or a configuration error, but the only thing that changed before triggering this, was the audit update.

The log_file log isn't affected by this.

[stevegrubb]

This plugin hasn't really changed since the 4.1 release. So, it is kind of hard to explain in terms of something changed on the audit side. If this is easily reproducible, you might try running the following as root:

strace -s 12000 -tt -f -e trace=sendto,sendmsg,write -p $(pidof audisp-syslog)

If it shows full audit records being sent to /dev/log, the split is definitely in syslog-ng or later. audisp-syslog has an internal line buffer a little over 8k in size. The example split record above is no where near that limit.

[heeplr]

This plugin hasn't really changed since the 4.1 release.

Maybe another change triggered some hidden bug?

strace -s 12000 -tt -f -e trace=sendto,sendmsg,write -p $(pidof audisp-syslog)

With that, I get split messages with tail -f /var/log/messages aswell.

I'm also using syslog-ng to write that file using

source src {
    unix-dgram("/var/log/syslog-dgram.sock");
    system();
    internal();
    file("/proc/kmsg" program-override("dmesg"));
    ...
};
destination messages     { file("/var/log/messages" create_dirs(no) owner("root") group("root") perm(0640) dir_group("root") dir_perm(0750)); };
log { source(src); destination(messages); };

So I guess we can't rule out syslog-ng completely, yet? Could I somehow read /dev/log directly?

EDIT (found that strace terminal is actually generating output):

strace output:

21:09:00.951140 sendto(3, "<14>May 22 21:09:00 audisp-syslog: node=server type=CRED_ACQ", 73, MSG_NOSIGNAL, NULL, 0) = 73                                                   
21:09:00.951809 sendto(3, "<14>May 22 21:09:00 audisp-syslog:  msg=audit(1779476940.946:3882456): pid=23993 uid=0 auid=1000 ses=4 msg='op=PAM:setcred grantors=pam_env,pam_faillock,pam_cap acct=\"user\" exe=\"/usr/sbin/crond\" hostname=? addr=? terminal=cron res=success' UID=\"root\" AUID=\"admin\"\n", 267, MSG_NOSIGNAL, NULL, 0) = 267

It's somewhat reproducible happening randomly (smells like race condition) but often enough to catch it after an hour or so.

I'm happy to provide more info to debug this.

[heeplr]

Any news on this, yet?

I found as a temporary workaround one can use "write_logs = yes", disable the audisp-syslog plugin and point syslog-ng to "/var/log/audit/audit.log".

That's not ideal but at least prevents spam by logging whitelist filters.

[stevegrubb]

TBH, I missed that you replied 2 weeks ago. (Was very busy with fapolicyd.) The code in audisp-syslog hasn't changed in a long while. It might be possible that it is receiving a split record. I guess that is where I would look. I'll have to do some experimenting to see if it is coming out of auditd to the plugin interface like this. There's not a lot that can be done to narrow this down except add fprintf() to a file right where it sends the event to the plugin. I can't look at this right now...I have to turn my attention to libcap-ng. But I believe this warrants more investigation on my end.

When you see this, is it limited to a specific record type or randomly any record?

[heeplr]

No worries. With the mentioned workaround, this doesn't seem to be time critical.

When you see this, is it limited to a specific record type or randomly any record?

All sorts of types (e.g. USER_START, USER_END, USER_ACCT, CRED_REFR, LOGIN, ...).

[stevegrubb]

If this is still reproducible, you might try:

strace -s 12000 -tt -f -e trace=sendto,sendmsg,write -p $(pidof audisp-syslog)

If it shows whole lines, then the problem is downstream of audit. I can't find anything in the audit code that would cause clean splits of events. audisp-syslog reads a whole string and writes a whole string.