Logback hack to log different levels in the same package to different appenders

Given the long title you could think that this is going to be a blog about a ridiculous edge case. It isn't, honestly! It is a blog about an edge case, but not ridiculous and not as far fetched as you think. Let's say that you have a class logging on DEBUG and TRACE. The debug messages contain (frequent) checks, but lack the full information needed to analyze the problem. This information (say a full xml message) is logged on TRACE level. Now your friendly system administrator decides that he needs this trace logging to go into a different file from the debug logging. He has good arguments and you don't want to pick a fight. Logback provides a lot of configuration options that you can do lots of neat things with. But it can't fill this requirement. Really? Well, there is a hack.

Setting up the experiment

-----------------------------------

Logback works with appenders and loggers. Appenders define where output goes and how it is formatted. Loggers define where logs come from and which appenders should be used to write to. 

So if we want to log to a certain appender on a certain level we create a logger like this.

1 2 3 4

<logger name="iwein.samples.foo">     <appender-ref ref="STDOUT1" level="trace" />     <appender-ref ref="STDOUT2" level="debug" />   </logger>

The appender totally standard, but I'll include it anyway.

1 2 3 4 5

<appender name="STDOUT1" class="ch.qos.logback.core.ConsoleAppender">     <layout class="ch.qos.logback.classic.PatternLayout">       <Pattern>STDOUT2 %logger{36} - %msg%n</Pattern>     </layout>   </appender>

The logging is done in a class in the package 'iwein.samples.foo', again just adding it for completeness.

1 2 3 4 5 6 7 8 9 10 11 12 13

package iwein.samples.foo; //... public class SomeLoggingThing {     private static final Logger logger = LoggerFactory.getLogger(SomeLoggingThing.class);     public static void saySomething(){         logger.info("INFO");         logger.debug("DEBUG");         logger.trace("TRACE");     } }

I wrapped this in a testcase, but if you want all the code you'll just have to [grab it](https://github.com/iwein/logback-testdrive/commit/1b543645dc561ebb81237238d5698d95c34d4f4f).  We now have the basic position from which the interesting stuff can start. Let's try to implement the requirement next.

First attempt: multiple appender-refs

-------------------------------------------------

We want our logger that is created in the java code up there to log to different appenders. You can do this by adding an appender ref, but we also want to log with different levels to different appenders. That's a little harder.

1 2 3 4

<logger name="iwein.samples.foo" level="trace">     <appender-ref ref="STDOUT1" />     <appender-ref ref="STDOUT2" />   </logger>

If I did the domain model for logback (which I didn't), the appender-ref would correspond to an object, on which the log level would be set. In reality, logback allows you to set a level on the logger, so one logger only has one level. Would be nice if you could do something like this:

1 2 3 4

<logger name="iwein.samples.foo">     <appender-ref ref="STDOUT1" level="trace" />     <appender-ref ref="STDOUT2" level="debug" />   </logger>

Which you can't... which is a bummer.

Second attempt: multiple loggers

--------------------------------------------

Now conceptually, if you add another logger, you could use a different level there and a different appender too: problem solved, TADA! So let's try.

1 2 3 4 5 6 7

<logger name="iwein.samples.foo" level="trace">     <appender-ref ref="STDOUT1" />  </logger>  <logger name="iwein.samples.foo" level="debug">     <appender-ref ref="STDOUT2" />  </logger>

When I run this in my test the output is:

STDOUT2 iwein.samples.foo.SomeLoggingThing - INFO

STDOUT1 iwein.samples.foo.SomeLoggingThing - INFO

STDOUT2 iwein.samples.foo.SomeLoggingThing - DEBUG

STDOUT1 iwein.samples.foo.SomeLoggingThing - DEBUG

What happens is that there is only one logger in the end with two appenders and its level set to the last logger loaded. Kraznoks! 

After some headscratching we came up with another solution. It isn't pretty, but it's the first one to actually do the job.

Third attempt: filter in the appender

-----------------------------------------------

Before you run away screaming, let me assure you that I know this isn't how it _should_ work, but it's the only way I could come up with so far. I'll log an improvement request in the logback issue tracker of course.

So how about you log to both appenders, but filter out the trace messages you don't want in one appender? That would work...

The downside is though that I had to make my appender look like this:

1 2 3 4 5 6 7 8 9 10 11 12

<appender name="STDOUT2" class="ch.qos.logback.core.ConsoleAppender">     <filter class="ch.qos.logback.core.filter.EvaluatorFilter">       <evaluator> <!-- defaults to type ch.qos.logback.classic.boolex.JaninoEventEvaluator -->         <expression>return Level.TRACE.equals(Level.toLevel(level)) &amp;&amp; logger.startsWith("iwein.samples.foo");</expression>       </evaluator>       <OnMismatch>NEUTRAL</OnMismatch>       <OnMatch>DENY</OnMatch>     </filter>     <layout class="ch.qos.logback.classic.PatternLayout">       <Pattern>STDOUT1 %logger{36} - %msg%n</Pattern>     </layout>   </appender>

Which is nothing short of an abomination. See http://jira.qos.ch/browse/LBCLASSIC-284 for progress on this issue.

Posted via email from Iwein's braindumps