[logback-user] syslogappender stacktraces get cut
ceki
ceki at qos.ch
Thu Apr 12 15:22:46 CEST 2012
FYI, I just commented on https://github.com/ceki/logback/pull/42
On 12.04.2012 15:20, Ingebrigt Berg wrote:
> Done.
>
> Credit where credit is due, it was actually my coworker Marius Eikenes
> that proposed this way of fixing the problem.
> Thanx for looking into this, it's much appreciated.
>
> cheers,
> Ingebrigt
>
> Den 09:08 12. april 2012 skrev ceki <ceki at qos.ch <mailto:ceki at qos.ch>>
> følgende:
>
> 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 <http://twitter.com/#%21/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>
> <mailto: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
> <http://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
> <http://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>
> <mailto: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
>
--
Ceki
http://twitter.com/#!/ceki
More information about the Logback-user
mailing list