bwaldvogel
commented
4 years ago Actually keeping newlines (think of stacktraces!) in the log messages is an important feature for me. I’m also not sure if your analysis is entirely correct. Please note that the sd_journal_send man page just talks about a newlines at the end:
Note that log messages written using this function are generally not expected to end in a new-line character.
It’s probably worth to open an issue at systemd and clarify if the "odd processing" is intended.
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' -ppgrep 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 seeMESSAGE\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
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!