logback printing log entries out of order

Has anyone ever seen this behavior before: 2012-10-11 16:48:04.418 ALWAYS [Thread-1] camiant.services.qp.AbstractQPInfoImpl$EventListenerWorker.run:247 - AbstractQPInfoImpl.EventListenerWorker shutdown complete. 2012-10-11 16:48:04.415 ALWAYS [Thread-4] camiant.backout.utils.FileProgressIndicator.run:91 - Interrupted!!! .418 is showing up before .415 Please see my filter below for ALWAYS if that even remotely has anything to do with this. <turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter"> <Name>AlwaysTurboFilter</Name> <Marker>ALWAYS</Marker> <OnMatch>ACCEPT</OnMatch> </turboFilter> It happens to both STDOUT and my log file in the same order. Subsequent runs haven't show this and it is happening during shutdown so I am not really that concerned about it, but I figured I would report and see if there's an explanation for it. Here is my jar information.. slf4j-api-1.6.6.jar logback-classic-1.0.6.jar logback-core-1.0.6.jar Thanks, Dave

This looks normal to me. You have two threads writing log messages at approximately the same time, and one thread just happens to acquire the mutex before the other (after generating the log message). -Abraham
participants (2)
-
Abraham Lin
-
David Tkaczyk