[logback-user] syslogappender stacktraces get cut

[ceki]

Hi Ingebrigt,

Are you familiar with git/github? In short, you would fork logback on 
github, make your changes and then send me a pull request. Posting a 
diff file with your changes would be OK as well.

BTW, I quite like your idea of a separate pattern for the stack trace.

Best regards,
-- 
Ceki
http://twitter.com/#!/ceki


On 11.04.2012 16:57, Ingebrigt Berg wrote:
> 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
> <mailto: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
>     <mailto: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
>