[logback-user] SyslogAppender behaving strangely

[Robert Kuhar]

The root cause of my issue appears to be the syslogd implementations.
 Somehow the first colon of the message is significant.  Our syslog guru
guy describes it as "program" and says its just a string followed by a
colon and a space.  Adding a static text program field terminated with a
colon ("dm-service: ") to the front of the suffixPattern appears to fix the
problem.  You've got to give the syslog what it wants.

My SyslogAppender is configured like...

  <appender name="SYSLOG" class="ch.qos.logback.classic.net.SyslogAppender">
    <syslogHost>localhost</syslogHost>
    <facility>local4</facility>
    <suffixPattern>dm-service: %d{yyyy-MM-dd'T'HH:mm:ss.SSS'Z'} [%p] %c{2}
DSN:%X{X-HTC-DEVICE-SN} APV:%X{X-HTC-APP-VERSION} RID:%X{X-HTC-REQUEST-ID}
- %m</suffixPattern>
  </appender>

produces the syslog message...

Jun 13 14:35:50 bobk-mbp.local dm-service <Info>: 2013-06-13T14:35:50.064Z
[INFO] Global$ DSN: APV: RID: - dm2-server starting

The "level" remains duplicated but I've observed that they don't appear to
map each other 1:1 (I'm sure this is documented somewhere but am not
motivated enough to go in search of it).  Syslog <Info> is indeed slf4j
INFO, but Syslog <Debug> somehow ends up with both my DEBUG and TRACE slf4j
messages.  I've come to the conclusion that this isn't duplication as much
as mapping and because the mapping isn't 1:1 I need to keep it around.

In any event.  Thanks to all for their insights.

Bob

On Thu, Jun 6, 2013 at 11:51 PM, Robert Kuhar <robertkuhar at gmail.com> wrote:

> Removing the %d mitigates the issue without solving the problem.  The lame
> syslogd on OS X doesn't give me millisecond precision and, sometimes, that
> matters to my app.  I'm really just trying to figure out who dropped the
> ball here.  Did the SyslogAppender send a message that was already dorked
> or was the SyslogAppender message fine and the syslog server itself screwed
> things up.
>
> Thanks for the suggestion, though.
>
>
> On Thu, Jun 6, 2013 at 6:38 PM, Chris Pratt <thechrispratt at gmail.com>wrote:
>
>> How about just removing the %d parameter (since syslogd already
>> timestamps each entry) and seeing if the problem moves or goes away.
>>   (*Chris*)
>>
>>
>> On Thu, Jun 6, 2013 at 5:13 PM, Robert Kuhar <robertkuhar at gmail.com>wrote:
>>
>>> I too am suspicious of the OS X syslogd, but I really don't know how to
>>> trouble shoot it.  Maybe I sniff the wire to see what the UDP packets look
>>> like?  That seems rather primitive.  I just wondered if anyone else has
>>> ever seen this apparent message corruption when using a SyslogAppender.
>>>
>>> THanks,
>>> Bob
>>>
>>>
>>> On Thu, Jun 6, 2013 at 4:03 PM, Chris Pratt <thechrispratt at gmail.com>wrote:
>>>
>>>> It looks to me like the first timestamp and the bobk-mbp.local are
>>>> being output by the SysLog daemon, but I have no idea what would be
>>>> inserting the <Info> in the center of the timestamp from Logback.  Could
>>>> your SysLog daemon be automatically inserting the log level at the first
>>>> colon in the message?
>>>>   (*Chris*)
>>>>
>>>>
>>>> On Thu, Jun 6, 2013 at 3:24 PM, Robert Kuhar <robertkuhar at gmail.com>wrote:
>>>>
>>>>> My SyslogAppender succeeds in sending messages to the syslogd on my
>>>>> MacBook, but the messages themselves are "corrupt" the syslogd logs them.
>>>>>  For example, a RollingFileAppender
>>>>>
>>>>>   <appender name="DAILY_ROLLING"
>>>>> class="ch.qos.logback.core.rolling.RollingFileAppender">
>>>>>     <File>logs/dm.log</File>
>>>>>     <rollingPolicy
>>>>> class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
>>>>>       <FileNamePattern>logs/dm.%d{yyyyMMdd}.log</FileNamePattern>
>>>>>     </rollingPolicy>
>>>>>     <encoder>
>>>>>       <pattern>%d{yyyy-MM-dd'T'HH:mm:ss.SSS} [%p] %c{2}
>>>>> DSN:%X{X-HTC-DEVICE-SN} APV:%X{X-HTC-APP-VERSION} RID:%X{X-HTC-REQUEST-ID}
>>>>> - %m%n</pattern>
>>>>>     </encoder>
>>>>>   </appender>
>>>>>
>>>>> logs a message like...
>>>>>
>>>>> 2013-06-06T15:02:17.129 [INFO] Global$ DSN: APV: RID: - dm2-server
>>>>> starting
>>>>>
>>>>> But the SysLog appender dorks the message corrupting the %d timestamp
>>>>> and duplicating the level.  My SyslogAppender is configured like...
>>>>>
>>>>>   <appender name="SYSLOG"
>>>>> class="ch.qos.logback.classic.net.SyslogAppender">
>>>>>     <syslogHost>localhost</syslogHost>
>>>>>     <facility>local4</facility>
>>>>>     <suffixPattern>%d{yyyy-MM-dd'T'HH:mm:ss.SSS} %p %c{2}
>>>>> DSN:%X{X-HTC-DEVICE-SN} APV:%X{X-HTC-APP-VERSION} RID:%X{X-HTC-REQUEST-ID}
>>>>> - %m</suffixPattern>
>>>>>   </appender>
>>>>>
>>>>> With the same log message appearing like...
>>>>>
>>>>> Jun  6 15:02:17 bobk-mbp.local 2013-06-06T15 <Info>: 02:17.129 INFO
>>>>> Global$ DSN: APV: RID: - dm2-server starting
>>>>>
>>>>> Where did the <Info> come from and what is it doing in the middle of
>>>>> logback's %d timestamp?  Is this logback messing up or syslogd?  Any
>>>>> recommendations on how to troubleshoot this?
>>>>>
>>>>> Bob
>>>>>
>>>>>
>>>>>
>>>>> _______________________________________________
>>>>> Logback-user mailing list
>>>>> Logback-user at qos.ch
>>>>> http://mailman.qos.ch/mailman/listinfo/logback-user
>>>>>
>>>>
>>>>
>>>> _______________________________________________
>>>> Logback-user mailing list
>>>> Logback-user at qos.ch
>>>> http://mailman.qos.ch/mailman/listinfo/logback-user
>>>>
>>>
>>>
>>> _______________________________________________
>>> Logback-user mailing list
>>> Logback-user at qos.ch
>>> http://mailman.qos.ch/mailman/listinfo/logback-user
>>>
>>
>>
>> _______________________________________________
>> 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/20130614/50f426a0/attachment.html>