Corrupted JSON logs on concurrent write

[knittl]

Using loki-logback-appender with the a simple config, similar to the one from the docs:

    <appender name="LOKI" class="com.github.loki4j.logback.Loki4jAppender">
        <http>
            <url>http://${LOKI_HOST}:${LOKI_PORT:-80}/loki/api/v1/push</url>
        </http>
        <format>
            <label>
                <pattern>app=example,host=${HOSTNAME}</pattern>
            </label>
            <message class="com.github.loki4j.logback.JsonLayout"/>
        </format>
    </appender>

results in corrupted JSON log entries in Loki, such as the following (1 line = 1 log entry):

{{timestamp_ms\"\":1timestamp_ms\"logger_name\"\":,1logger_name\"h7:92588294com.example.app.RootController\",,\"logger_nameO\"000-exec-4\",\":,\"thread_name\":\"http-nio-5000-exec-6\",,\"message\":\"Checking state: UP\"elevel\":\"INFO\",\"thread_name\":\"http-nio-5000-exec-5\"},\"message\":\"Checking state: UP\"}
{{timestamp_ms\"\":1timestamp_ms\"logger_name\"\":,1logger_name\"h7:92588294com.example.app.RootController\",,\"logger_nameO\"000-exec-4\",\":,\"thread_name\":\"http-nio-5000-exec-6\",,\"message\":\"Checking state: UP\"elevel\":\"INFO\",\"thread_name\":\"http-nio-5000-exec-5\"},
{{timestamp_ms\"\":17192588\"9409,\"logger_name\"\":1logger_name\":\"com.example.app.RootController\"1719258839409\"level\":\"INFO\",,\"thread_name\":logger_name000-exec-8\",00-exec-6\",\":\"mom.example.app.RootController\",\"level\":\"INFO\",}
}

More logs become corrupted when the application is handling many web requests simultaneously.

Looking at the code, we see that JsonLayout uses a single JsonEventWriter instance shared across threads. As soon as multiple threads write logs at the same time, logs can become corrupted easily. An automated test proves this trivially.

A quick fix is to synchronize the method with the caveat that in high-contention scenarios threads will block each other when logging. There are other options, such as creating a new writer instance per event at the cost of increased memory allocations (this is what logback's builtin PatternLayout does) or using a pool of writers, allowing parallelism of up to N threads (could be made configurable via logback.xml) requiring a constant amount of memory.

I'll gladly provide a PR shortly, including a test to protect against regressions of this type of error.

Anybody experiencing the same problem and unable to upgrade to a version with the fix, can use the following workaround for the time being:

public class SynchronizedJsonLayout extends JsonLayout {
    @Override
    public synchronized String doLayout(final ILoggingEvent event) {
        return super.doLayout(event);
    }
}

And then change their logback.xml to use the synchronized layout:

            <message class="com.example.logging.SynchronizedJsonLayout"/>

[nehaev]

Hi @knittl, thanks for posting this and for providing a test and a fix!