Newlines in formatted message prevents forwarding to syslog

[cneth]

We recently ran into a subtle issue with this appender: while we could see the messages we created using it in the journal, they were not being forwarded to the syslog socket, where as all other journal messages (i.e. ones created by other components) were being forwarded.

This is a problem if you use rsyslog to forward messages to a centralized log server, as these messages are not being forwarded.

After some debugging, we found that the problem was that our ConversionPattern contained the %n character, i.e. we had something like this:

log4j.appender.journal.layout.ConversionPattern=[myid:%X{myid}] %-5p [%t:%C{1}@%L] - %m%n%throwable

The resulting log message looks good in the forwarder, but if you use strace on systemd-journal to see what the message looks like when it is sent to the journal using something like the following command:

strace -ff -s 1000 -e 'recvmsg' -p pgrep systemd-journal`

you will find that the message buffer it receives from the forwarder looks quite strange:

recvmsg(4, {msg_name=0x7fff48b8a750, msg_namelen=128->0, msg_iov=[{iov_base="MESSAGE\n\254\0\0\0\0\0\0\0[myid:] INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1056] - Closed socket connection for client /172.16.30.185:42590 (no session established for client)\n\nPRIORITY=6\n...

Notice that instead of MESSAGE=, we see MESSAGE\n\254\0\0\0\0\0\0\0, and there is also an extra newline in there...

It turns out that is intended(!) behavior of the sd_journal_send function.. If it encounters a newline in the message, it does some odd processing:

https://github.com/systemd/systemd/blob/master/src/journal/journal-send.c#L238

/* Already includes a newline? Bummer, then * let's write the variable name, then a * newline, then the size (64bit LE), followed * by the data and a final newline */

Because the string is no longer formatted as 'MESSAGE=...' something further down in the journal decides not to forward the message to syslog.

Note that this is also (kind of) documented in the sd_journal_send man page (https://www.freedesktop.org/software/systemd/man/sd_journal_print.html)
'Note that log messages written using this function are generally not expected to end in a new-line character.'

The fix is relatively straightforward - don't put %n in your format string! But it seems like given this limitation, the appender should do something like this:

args.add(buildRenderedMessage(event).replace("\n", ""));

So as to avoid the issue. If you like, I can submit a PR with some changes along this line.

Thanks for listening!