[logback-user] syslogappender stacktraces get cut

[Ingebrigt Berg]

Hi again.

As suggested I've implemented a POC on how SyslogAppender could be fixed,
and have got it working. It resolves our issue. With the changes I made,
the stacktrace lines can be prefixed as required, and with the proper
configuration they now end up in the correct file on our logserver.

My configuration now looks like this:

    <contextName>xxx-${CONTEXT_PATH}-${environment}</contextName>
    <appender name="LOGSERVER_FILE" class="no.xxx.logback.SyslogAppender">
        <contextName>xxx-${CONTEXT_PATH}-${environment}</contextName>
        <syslogHost>localhost</syslogHost>
        <facility>local3</facility>
        <SuffixPattern>%contextName %d{dd.MM.yyyy HH:mm:ss.SSS} [%p]
[%c{1}] [%X{ThreadId}]: %m%n</SuffixPattern>
        <StackTraceSuffixPattern>xxx-${CONTEXT_PATH}-${environment} -
</StackTraceSuffixPattern>
    </appender>

( Notice the new property <StackTraceSuffixPattern> )

All I had to change in the code (in SyslogAppender.java) was to implement a
new member variable stackTraceSuffixPattern (plus getter/setter) and to
append it in line 89 (after the prefix and before the tab).

In actual code I imagine you'd also want to add:
-a null test, to make the new parameter optional
-the new property should be subjected to pattern convertion (this was not
required for my POC to work, but would be nice/expected)

If someone would work with me and get this fix into logback proper it would
be much appreciated. I can send/post working code. For how to best activate
pattern conversion for the new property I would hope to get some
help/guidance.

cheers,
Ingebrigt Berg


Den 14:48 30. mars 2012 skrev Ingebrigt Berg <ingebrigt at jpro.no> følgende:

> 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/20120411/eca7f2bf/attachment.html>