touchlab / Kermit

Kermit by Touchlab is a Kotlin Multiplatform centralized logging utility.
https://kermit.touchlab.co
Apache License 2.0
699 stars 40 forks source link

Order of log calls not preserved #401

Closed DavidRobb closed 1 month ago

DavidRobb commented 1 month ago

I an using version 2.0.4 in a desktop build on Windows using the Azul Zulu 21.0.1 SDK and would expect log messages to come out in order regardless of log severity. When running

import co.touchlab.kermit.*

fun main() {

    Logger.e { "Log message-0" }
    Logger.w { "Log message-1" }
    Logger.i { "Log message-2" }
    Logger.e { "Log message-3" }
}

I see

10:02:07: Executing 'desktopRun -DmainClass=LogKt --quiet'...

Warn: Log message-1
Info: Log message-2
Error: Log message-0
Error: Log message-3
10:02:08: Execution finished 'desktopRun -DmainClass=LogKt --quiet'.

Sometimes error messages are first, ither times last as shown.

TadeasKriz commented 1 month ago

Error is appended to System.err and others are appended to System.out. It might be reader of those streams that doesn't synchronize them correctly. Could you share the reproducer project so we can try on our systems? Thanks!

DavidRobb commented 1 month ago

OK. Here's an Intellij Idea project folder: KermitTest.zip

TadeasKriz commented 1 month ago

I believe the problem is in how Gradle forwards the system streams. If you run ./gradlew createDistributable and then run the binary from terminal, the order of messages is correct always. I've had trouble with stream outputs in Gradle in the past.

If you add System.setErr(System.out) to fun main() (before you call application), you can see it prints it in the right order each time. Do not do that for a production app, it's just to show that Kermit doesn't control the order, it's whatever is reading from the streams.

DavidRobb commented 1 month ago

OK. Thanks for the explanation. Yes, this works for me.