Notes on Logging

Blocking vs Non-blocking mode

In a recent incident investigation, one of our services kept returning 504 (Gateway Timeout status code) for seemingly no particular reason – no extra load, not any particular operation, and not reproducible in lower environments.

… Until we enabled debug logs in the lower environment to help the investigation, that the issue finally reproduced itself.

It turned out that our service containers were logging using the default blocking delivery mode, which led to really slow requests up to the point were the request was cut off with 504.

This article has a detailed explanation on Docker Logging Best Practices.

Logback / Log4J hierarchy cheat sheet

We were continuously fine-tuning the logging setup in our Java/Springboot applications that use Logback library. Here is a cheat sheet on the hierarchy of log levels to stop ourselves from getting confused. (Documentations from Log4J and Logback are detailed, but we needed an “in-a-glance” view.)

# logback.xml
# Content taken directly from https://logback.qos.ch/manual/configuration.html

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

# Custom Logger config *** this is of our interest
    <logger name="org.foo" level="error" />

# Root Logger config *** this is of our interest
    <root level="debug">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

Root logger has higher level than other loggers

Library org.foo will be logging all logs from info and above. Logs for all other libraries will logged only if they are error.

Here are the options to implement it:

## Option 1
    <logger name="org.foo" level="info" additivity="false">
        <appender-ref ref="STDOUT"/>
    </logger>

    <root level="error">
        <appender-ref ref="STDOUT"/>
    </root>

## Option 2
    <logger name="org.foo" level="info" />

    <root level="error">
        <appender-ref ref="STDOUT"/>
    </root>

However, this leads to duplicated INFO logs from org.foo library:

    <logger name="org.foo" level="info">
        <appender-ref ref="STDOUT"/>
    </logger>

    <root level="error">
        <appender-ref ref="STDOUT"/>
    </root>

Root logger has lower level than other loggers

There will only be error level logs from library org.foo. Logs for all other libraries will logged if they are debug and above. Note: this could be confusing – there will be no logs lower than error (i.e. info and warn) for org.foo.

Here are the options to implement it:

## Option 1
    <logger name="org.foo" level="error" additivity="false">
        <appender-ref ref="STDOUT"/>
    </logger>

    <root level="debug">
        <appender-ref ref="STDOUT"/>
    </root>

## Option 2
    <logger name="org.foo" level="error" />

    <root level="info">
        <appender-ref ref="STDOUT"/>
    </root>

But this will lead to duplicated error logs from org.foo:

    <logger name="org.foo" level="error">
        <appender-ref ref="STDOUT"/>
    </logger>

    <root level="debug">
        <appender-ref ref="STDOUT"/>
    </root>

Root logger has same level as other loggers

These two options will yield the same results:

## Option 1
   
   ## Some would argue this line is not necessary, since the effect is the same as without. But if there are different Spring profiles in the same logback.xml file and you want to easily tweak levels according to the profiles, this could be more explicit, i.e. one could see org.foo would log info level in "local" profile, but would log warn level in "prod" profile.
    <logger name="org.foo" level="info"/>

    <root level="info">
        <appender-ref ref="STDOUT"/>
    </root>

## Option 2
    <root level="info">
        <appender-ref ref="STDOUT"/>
    </root>