force slf4j to print logs in sequence

Question

I am using slf4j over log-back. Sometimes logs are not printing in the order (timestamp). Could we force it to log in the same order as the code is running?

Update 1: This is happening when running unit tests on Jenkins through maven. It is happening consistently. First log statements from the code are coming then the log statements from the unit test are coming.

Also all logback files looks normal like below.

  <appender name="STDOUT"
            class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.classic.PatternLayout">

Update 2: the log snippets are like this (I have edited file name etc..). During the test1 execution we call code to reverse a transaction which was failed due to some error. But strange thing is that the exception is printed first and then the log statements from test methods are printed. Also the timestamps of log statements are as expected but the order of them in the file is different (14:33:34.718 comes before 14:33:34.449)

14:33:34.667 [869082978@qtp-1587505558-0] [] WARN  org.hibernate.ejb.Ejb3Configuration - hibernate.connection.autocommit = false break the EJB3 specification
14:33:34.718 [869082978@qtp-1587505558-0] [] WARN  o.h.impl.SessionFactoryObjectFactory - InitialContext did not implement EventContext
14:33:34.843 [869082978@qtp-1587505558-0] [] DEBUG c.r.a.exception.ExceptionMapper - <3003> can't reverse transaction. [id=10000000100120014]
.
.
.
.
.
14:33:34.158 [main] [] DEBUG c.r.a.test - ========================= test0: finished.
14:33:34.158 [main] [] DEBUG c.r.a.test - ========================= test1: started.
.
.
.
.
14:33:34.449 [main] [] DEBUG c.r.a.test - reversing transaction, id=10000000100120014
14:33:34.856 [main] [] DEBUG c.r.a.test - ========================= test2: started.

Update 3: Our project uses maven and there are multiple modules. We have logback-test.xml in src/test/resources folder.

Project structure is like this
codemodule/src/test/resources/logback-test.xml - this module will be packaged in jar file. Test case calls this module's code.
parent/src/test/resources/logback-test.xml - this is the parent module which wraps all other modules' jar files and packages into a war. This is where I have test case running and it calls above module's code.

I have log statements in both test case code and actual code. I have checked that both test case and code are using pattern from the parent's logback file (pattern in codemodule is different). It consistently prints code's log statements before printing test case's logs.

Also we are not running tests in parallel.
Concurrency config is parallel='none', perCoreThreadCount=true, threadCount=2, useUnlimitedThreads=false

Update 4: I understand the problem. We are making a http request not a direct method call. So test cases are running in main thread and actual code is running in another thread (Thanks Sebbe).

I understand forcing logging sequence can be performance hit but for the completeness of the question I will ask one more question.

Since both logs are going to single appender (STDOUT), can I force it to log in the order of timestamp?

Answer 1

From your log itself you can see you have at least 2 threads running: 869082978@qtp-1587505558-0 and main.

You can't control the order in which separate threads log their events to the same output (you probably can, but it would be a bad idea).

From your log thread 869082978@qtp-1587505558-0 gets write access to your console first. While writing to it, events are logged from main. Once 869082978@qtp-1587505558-0 releases it's lock, main gets it and it can flush it's logs to the file.