logback: how to set logging level per thread?

Question

I have a multithreaded Java application, each thread being a class extending a base class extending Thread. One of the threads occasionally gives a method in the base class a large amount of machine-generated data, while the others only give small trickles of human-typed data. I want to log those human-typed messages on a higher loglevel than the machine data, but as the base class is part of all threads I cannot distinguish that in the code.

One solution is to inform the base class from the extended classes to log on a different level, but then I'd have to hardcode that knowledge into the application, which is ugly.

What I would like to do is "steer" this through my logback.xml config.

I wrote a small reproducer:

package x.y.z;
import org.slf4j.*;

public class Quickie {
    static final Logger LOG = LoggerFactory.getLogger(Quickie.class);

    public static void main(String[] args) throws Exception {

        MyThread t1 = new MyThread("hi");
        MyThread t2 = new MyThread("bye"); 

        t1.start(); t2.start();
    }
}

class MyThread extends Thread {
    static final Logger LOG = LoggerFactory.getLogger(MyThread.class);

    public MyThread(final String name) { this.setName(name); }

    public void run() { logSomething(); }

    public void logSomething() {
        LOG.trace(getName()); LOG.error(getName());
    }
}

This is the logback config:

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true">

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%date{HH:mm:ss} %-6level %-10([%thread]) %logger{1}.%method:%line %message%n</pattern>
        </encoder>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>TRACE</level>
        </filter>
    </appender>

    <root level="TRACE">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

With most importantly, the encoder pattern being:

            <pattern>%date{HH:mm:ss} %-6level %-10([%thread]) %logger{1}.%method:%line %message%n</pattern>

As this shows the thread clearly:

11:16:09 TRACE  [bye]      c.t.k.t.MyThread.logSomething:24 bye
11:16:09 TRACE  [hi]       c.t.k.t.MyThread.logSomething:24 hi
11:16:09 ERROR  [bye]      c.t.k.t.MyThread.logSomething:24 bye
11:16:09 ERROR  [hi]       c.t.k.t.MyThread.logSomething:24 hi

... I would say there should be a way to configure my logback.xml have the "bye" thread only log on info or higher, while the "hi" thread logs from trace or higher? I spend half a day googling and reading logback documentation and I tried sifters and regex filters and lots of other examples, but they all just go on the message, apparently. Meaning that one solution could be to have a magical string appear in the messages and filter that out, but that too would be ugly.

So, is there a way to steer log levels per thread from within the log configuration without having to inject "specialized code" into the application?

Answer 1

I think you can use MDC and TurboFilter for this purpose.

Add a call of MDC.put() in run() method like this:

public void run() {
    MDC.put("threadname", this.getName());
    logSomething();
}

If you want to the "bye" thread only log on info or higher and the "hi" thread logs from trace or higher, you have to add a definition of DynamicThresholdFilter to logback.xml:

<configuration>
  <turboFilter class="ch.qos.logback.classic.turbo.DynamicThresholdFilter">
    <Key>threadname</Key>
    <!-- You can set default threshold as you like -->
    <DefaultThreshold>TRACE</DefaultThreshold>
    <MDCValueLevelPair>
      <value>bye</value>
      <level>info</level>
    </MDCValueLevelPair>
    <MDCValueLevelPair>
      <value>hi</value>
      <level>trace</level>
    </MDCValueLevelPair>
  </turboFilter>
  ......
</configuration>