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.