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...

<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@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@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@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@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@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@qos.ch
http://mailman.qos.ch/mailman/listinfo/logback-user

_______________________________________________
Logback-user mailing list
Logback-user@qos.ch
http://mailman.qos.ch/mailman/listinfo/logback-user

_______________________________________________
Logback-user mailing list
Logback-user@qos.ch
http://mailman.qos.ch/mailman/listinfo/logback-user

_______________________________________________
Logback-user mailing list
Logback-user@qos.ch
http://mailman.qos.ch/mailman/listinfo/logback-user