[logback-user] syslogappender stacktraces get cut
Ingebrigt Berg
ingebrigt at jpro.no
Tue May 15 13:37:04 CEST 2012
Hi !
I completed some changes in SyslogAppender a month ago, but no response so
far, and my pull request has expired.
Sending a last reminder, in case it has simply been forgotten (let me know
if you want me to issue another pull request).
cheers,
Ingebrigt
2012/4/19 Ingebrigt Berg <ingebrigt at jpro.no>
> Hi Ceki!
>
> Just checking up on this, if it's likely to go into Logback, and if you
> think there are any further changes required on my part.
>
> I've been using a local copy of the changes in SyslogAppender in 2
> applications. They have been tested all week (the newest version including
> a stacktraceLayout), so far they're doing fine and our problems with Syslog
> logging are gone. Production on april 25 (I don't expect this to be in
> logback by then).
>
> No hurry in getting the fix in, but it's important to know soon if Logback
> will eventually include this (or a functionally similar) fix. I have
> another 20-30 applications I'll be doing similar maintenance work on over
> the next few months, and until I know where this is heading it's a bit
> difficult to get a go ahead on moving them all from Log4j to Logback (We
> don't really want to maintain inhouse modifications to Logback permanently).
>
> cheers,
> Ingebrigt
>
>
>
>
> Den 15:22 12. april 2012 skrev ceki <ceki at qos.ch> følgende:
>
>
>> 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
>>
>> _______________________________________________
>> Logback-user mailing list
>> Logback-user at qos.ch
>> http://mailman.qos.ch/mailman/listinfo/logback-user
>>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.qos.ch/pipermail/logback-user/attachments/20120515/ea8411da/attachment-0001.html>
More information about the Logback-user
mailing list