[logback-user] syslogappender stacktraces get cut

[Ingebrigt Berg]

Hi !

We have looked more into this issue.

>From a TCPdump for the traffic between the app (using logback) and the
syslog-server we learn that each line in the stacktrace is actually sent as
a separate message to syslog (sensitive info replaced with xx/yy/zz):

11:28:37.911604 IP xx
    localhost.localdomain.55934 > localhost.localdomain.syslog: [bad udp
cksum af4f!] SYSLOG, length: 101
        Facility local3 (19), Severity error (3)
        Msg: Mar 30 11:28:37 yy2-31 zz-mce-test 30.03.2012 11:28:37.910
[ERROR] [LogbackTester] []: Fjas\0x0a
11:28:37.912028 IP xx
    localhost.localdomain.55934 > localhost.localdomain.syslog: [bad udp
cksum 6076!] SYSLOG, length: 104
        Facility local3 (19), Severity error (3)
        Msg: Mar 30 11:28:37 yy2-31 \0x09at
sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)

The first packet is a regular log statement, the second one is a line in a
stack trace.

Notice how
'zz-mce-test 30.03.2012 11:28:37.910 [ERROR] [LogbackTester] []:'
is replaced with:
'\0x09at'

If we interpret this correctly, SyslogAppender  will log the error message
and each StackTraceElement separately. But for the StackTraceElements it
will ignore what we configure in the <SuffixPattern> property:
( <SuffixPattern>%contextName %d{dd.MM.yyyy HH:mm:ss.SSS} [%p] [%c{1}]
[%X{ThreadId}]: %m%n</SuffixPattern> )
Instead the stackline messages simply get a '\0x09at' (a TAB) appended in
place of the SuffixPattern.

This happens in line 89 in ch.qos.logback.classic.net.SyslogAppender:
sb.append(prefix).append(CoreConstants.TAB).append(step);

Contrast that to line 59 in ch.qos.logback.classic.net.SyslogAppender
(normal messages), where the SuffixPattern gets added:
fullLayout.setPattern(prefixPattern + suffixPattern);

We see two viable solutions:

EITHER:
when a message is split into a main message and StackTraceElements,
the StackTraceElement
messages must also get the content of the <SuffixPattern> appended

OR:
an optional property <StackTraceSuffixPattern> could be added to
SyslogAppender, allowing control of what goes into StackTraceElement
messages.

cheers,
Ingebrigt Berg + Marius Eikenes


Den 11:40 20. mars 2012 skrev Ingebrigt Berg <ingebrigt at jpro.no> følgende:

> Hi !
>
> We've recently made the switch from Log4j to Logback. We use Syslog to
> send logfiles to our logserver, and things generally work.
>
> But when there are stacktraces in the logs we get in trouble.
> SyslogAppender will replace lineshifts with '#011' to make the logentry a
> single line. Then it will cut each line that is to long according to the
> syslog limit of 2K/line. Only the fist segment will arrive in the correct
> log. The remaining segments are not prefixed with everything in the
> suffixPattern, and our regexp will not have anything to match. The segment
> will end up in a 'trash' log for unmatchable loglines.
>
> My config for the SyslogAppender looks like this:
>
>     <contextName>company-${CONTEXT_PATH}-${environment}</contextName>
>     <appender name="LOGSERVER_FILE"
> class="ch.qos.logback.classic.net.SyslogAppender">
>         <syslogHost>localhost</syslogHost>
>         <facility>local3</facility>
>         <SuffixPattern>%contextName %d{dd.MM.yyyy HH:mm:ss.SSS} [%p]
> [%c{1}] [%X{ThreadId}]: %m%n</SuffixPattern>
>     </appender>
>
> We use the contextName property to control the logfilename. On the
> receiving end we read the contextName parameter (using a regexp) for each
> log line, and write the line to a file with a corresponding name.
>
> We had a similar problem when we used Log4J (Where the Tag element was
> used in the same manner), and fixed it back then by writing a custom log4j
> SyslogAppender. But the main purpose of moving to Logback is to loose all
> our home brew logging stuff, we don't want to go down that path again. If
> we can't make Logback work out of the box with Syslog we'll probably end up
> going back to Log4J. (Another alternative is to replace Syslog with Gelf,
> but that's further down the road).
>
> However, I imagine Logback and Syslog being a common combination, and
> surely someone must have this working out of the box. Any advice will be
> appreciated. My requirements are simple:
> -must work with no custom logging code, only config (preferably xml)
> -stacktraces in logs must work
> -must be able to fully control the filename on the recieving end.
>
> cheers,
> Ingebrigt Berg
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20120330/2f02d2e6/attachment.html>