imuxsock module fails to parse systemd-journald forwarded message, possibly due to extra space character

[mk-fg]

Expected behavior

Running rsyslogd with input(type="imuxsock" Socket="/run/systemd/journal/syslog") parses correct "programname" and "procid" attributes from the forwarded message, for example:

{
  "timereported": "Sep  2 15:43:02",
  "pri-text": "syslog.info",
  "programname": "rsyslogd",
  "procid": "73104",
  "msg": "[origin software=\"rsyslogd\" swVersion=\"8.2208.0\" x-pid=\"73104\" x-info=\"https://www.rsyslog.com\"] start"
}

Actual behavior

Parsed message looks like this:

{
  "timereported": "Sep  2 15:46:25",
  "pri-text": "syslog.info",
  "programname": "",
  "procid": "-",
  "msg": " rsyslogd: [origin software=\"rsyslogd\" swVersion=\"8.2208.0\" x-pid=\"73148\" x-info=\"https://www.rsyslog.com\"] start"
}

Note the missing "programname" and "procid" attributes and "rsyslogd:" prefix in "msg".

Steps to reproduce the behavior

• Build and install latest rsyslogd on a modern Arch Linux OS.
• Enable ForwardToSyslog=yes in /etc/systemd/journald.conf, restart systemd-journald.
• Configure rsyslog.conf to have following input module: input(type="imuxsock" Socket="/run/systemd/journal/syslog")
• Start rsyslogd, its own startup logging should be sufficient to see the issue.

Environment

• rsyslog version (rsyslogd -v output):

  rsyslogd  8.2208.0 (aka 2022.08) compiled with:
        PLATFORM:                               x86_64-pc-linux-gnu
        PLATFORM (lsb_release -d):
        FEATURE_REGEXP:                         Yes
        GSSAPI Kerberos 5 support:              No
        FEATURE_DEBUG (debug build, slow code): No
        32bit Atomic operations supported:      Yes
        64bit Atomic operations supported:      Yes
        memory allocator:                       system default
        Runtime Instrumentation (slow code):    No
        uuid support:                           Yes
        systemd support:                        Yes
        Config file:                            /etc/rsyslog.conf
        PID file:                               /var/run/rsyslogd.pid
        Number of Bits in RainerScript integers: 64
  

• platform: Arch Linux (rolling release, state as of 2022-09-02), with systemd 251.4.

• rsyslogd.conf for running as rsyslogd -n | jq -C .:

  global(AbortOnUncleanConfig="on" shutdown.enable.ctlc = "on")
  
  module(load="imuxsock")
  input(type="imuxsock" Socket="/run/systemd/journal/syslog")
  
  template(name="json" type="list" option.jsonf="on") {
    property(name="timereported" format="jsonf")
    property(name="pri-text" format="jsonf")
    property(name="programname" format="jsonf")
    property(name="procid" format="jsonf")
    property(name="msg" format="jsonf")
  }
  
  module(load="omstdout")
  action(type="omstdout" template="json")
  

  Using SysSock.UsePIDFromSystem="on" with imuxsock module changes its output, but it's still broken, just in a different way ("programname": "73220]",).

More information

Afaik Arch uses upstream systemd without any significant patches, and issue appeared after recent update, bumping systemd 251.3 -> 251.4, immediately breaking output of already-installed rsyslogd (that wasn't changed/updated).

This leads me to believe that systemd changed its syslog output/forwarding format, which can be seen in strace output of rsyslogd (e.g. strace -e recvmsg -s8000 -fp $(systemctl show -P MainPID rsyslog)), for example:

old: ... msg_iov=[{iov_base="<30>Sep  2 14:56:09 dbus-daemon[1766]: [system] Activating via systemd: ...
new: ... msg_iov=[{iov_base="<30>Sep  2 14:54:15  dbus-daemon[1661]: [system] Activating via systemd: ...

"old" is the format that works, "new" is the one that does not.
Afaict difference seem to only be in that one space character.

If I understand correctly, parsing of this string is done by "special parser" routine in imuxsock.c itself (due to SysSock.UseSpecialParser=on default), and presumably one workaround would be to disable that and construct your own parser instead.

I wasn't able to find any obvious systemd commit that alters this behavior on short notice.
Wasn't able to find any obvious report/fix/PR for this issue in systemd/systemd repo either.

Is it a bug in systemd, or should rsyslogd default built-in imuxsock.c parser be able to handle this extra whitespace?
(or maybe both of these can be true, if handling of such slightly-broken output can be done anyway)

[rgerhards]

Is it a bug in systemd, or should rsyslogd default built-in imuxsock.c parser be able to handle this extra whitespace?

definitely a bug in systemd, this is not RFC format.

[mk-fg]

Thank you.
Reported it as systemd/systemd#24540 there.

[mk-fg]

Small update: I seem to have isolated this to a glibc 2.36 regression, which does sendto() with that space, which systemd seem to pass through as-is, so updating past that glibc package version or adding a patch to it might be a fix for anyone else bumping into this issue in the future.

glibc issue report - https://sourceware.org/bugzilla/show_bug.cgi?id=29544