Logger slf4j is not using the logback configured level

Question

Even though I have awarded the bounties to the users below that have attempted to help, the original question remains unanswered. No actual workable solution exists to ensure that the logback.groovy configured logging is honoured within the junit tests. The tests load up the logback config and it does report the correct level and yet still the actual test logging (exclusively through slf4j) is at ANY or TRACE level

I know others have encountered this same problem and it is very annoying when tests for big projects take a lot longer due to console logging being much too verbose. I cannot keep throwing bounties at this question. I hope someone comes up with a good solution that allows the tests logging to be properly configured at different levels through a system property. Then, different configurations can be created for the project so that tests will be able to configured at different logging threshold levels.

My logging is configured by logback through a logback.groovy file

Now, when my Maven POM project that aggregates all other projects starts, it passes them all the System property to set the correct logging level.

However, when the junit tests run, for some reason, the logger does not pick up the correct level even though the test classes static @beforeClass ensure that logback is properly configured.

It is not the Loggers in the tests that are the problem, -- well - yes them too-- , the real problem is that the loggers in the code sections that run (all my programs loggers everywhere) are set to the wrong logging level. They are not picking up what the logging is when the program tests are configured.

However, the projects are reporting the correct when logback initializes with the logback.goovy file. However, the actual logging level is set to TRACE or ALL

From the output below, it is clear that logback has configured to INFO. But the first project logging statement at TRACE (last line) shows that is not being picked up.

Help.

-------------------------------------------------------
 T E S T S
-------------------------------------------------------
Running groovy.text.StreamingTemplateEngineTest
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.245 sec
Running net.abcd.templating.InlinerTest
01:22:15,265 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@1e8c3cb - Added status listener of type [ch.qos.logback.core.status.OnConsoleStatusListener]
01:22:15,290 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@1e8c3cb - Setting ReconfigureOnChangeFilter scanning period to 5 minutes
01:22:15,290 |-INFO in ReconfigureOnChangeFilter{invocationCounter=0} - Will scan for changes in [[C:\Users\ABDC\Dropbox\workspace\abcd\AbcdTemplating\conf\logback.groovy]] every 300 seconds. 
01:22:15,290 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@1e8c3cb - Adding ReconfigureOnChangeFilter as a turbo filter
01:22:15,312 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@1e8c3cb - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
01:22:15,316 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@1e8c3cb - Naming appender as [STDOUT]
***********************************************************

LOGGING MODE PROPERTY 'net.abcd.logging.level' SET TO: [info]
IT CAN BE SET TO: OFF, ERROR, WARN, INFO, DEBUG, TRACE, ALL, INFO

***********************************************************
getLogLevel() returned 'INFO'
01:22:15,496 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@1e8c3cb - Setting level of logger [ROOT] to INFO
01:22:15,532 |-INFO in ch.qos.logback.classic.gaffer.ConfigurationDelegate@1e8c3cb - Attaching appender named [STDOUT] to Logger[ROOT]
01:22:15.846 [main] TRACE net.abcd.templating.Inliner - Document:

My logback.groovy file is:

displayStatusOnConsole()
scan('5 minutes')  // Scan for changes every 5 minutes.
setupAppenders()
setupLoggers()

def displayStatusOnConsole() {
    statusListener OnConsoleStatusListener 
}

def setupAppenders() {
    appender('STDOUT', ConsoleAppender) {
        encoder(PatternLayoutEncoder) {
            pattern = "%d{HH:mm:ss.SSS} [%thread] %-5level %-16logger{50} - %msg%n"
        }
    }
}


def setupLoggers() {    
    def loglevel = getLogLevel() 
    println("getLogLevel() returned '${loglevel}'")
    root(loglevel, ['STDOUT'])
}

def getLogLevel() {
    def mode = System.getProperty('net.abcd.logging.level', '')
    println("***********************************************************")
    println("")
    println("LOGGING MODE PROPERTY 'net.abcd.logging.level' SET TO: [${mode}]")
    println("IT CAN BE SET TO: OFF, ERROR, WARN, INFO, DEBUG, TRACE, ALL, INFO")
    println("")
    println("***********************************************************")
    switch(mode.toLowerCase()){
    case 'off':
        return OFF
    case 'error':
        return ERROR
    case 'warn':
        return WARN
    case 'info':
        return INFO
    case 'debug':
        return DEBUG
    case 'trace':
        return TRACE
    case 'all':
        return ALL
    default:
        return INFO
    }
}

I don't know if it helps, but JUnit installs its own class loader, which is known to interfere with logging frameworks. — llogiq, Jun 16 '15 at 14:28
@llogiq I know. .... Then why doe the config started by junit report correct even though the individual tests do not. And how to fix that? — The Coordinator, Jun 17 '15 at 22:20

score 5 · Answer 1 · answered Jun 04 '15 at 09:35

I met a similar issue on my junit tests as well. I couldn't find a good solution. I used below work around:

import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import org.slf4j.LoggerFactory;
...
static Logger logger;
static{
   // Logger.ROOT_LOGGER_NAME == "ROOT"
   logger = ((Logger) LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME));
   logger.setLevel(Level.INFO);
}

...

I think in your case, somehow a library uses it's own ConsoleAppender instance whose name is not 'STDOUT'. I hope setting root log level should resolve the issue.

root(loglevel, ['ROOT']);

That's helpful. I'm not sure it solves the problem though because I do log tests at different levels depending onthe property provided by the Reactor build. But thanks for chiming. — The Coordinator, Jun 04 '15 at 22:49

Ondrej Burkert · Answer 2 · 2015-06-15T19:58:13.013

We usually route every logging through slf4j and then configure the logging with logback. So our Maven dependencies look like:

    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-api</artifactId>
        <version>${slf4j.version}</version>
    </dependency>
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>jcl-over-slf4j</artifactId>
        <version>${slf4j.version}</version>
    </dependency>
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>log4j-over-slf4j</artifactId>
        <version>${slf4j.version}</version>
    </dependency>
    <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>jul-to-slf4j</artifactId>
        <version>${slf4j.version}</version>
    </dependency>
    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-core</artifactId>
        <version>${logback.version}</version>
    </dependency>
    <dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-classic</artifactId>
        <version>${logback.version}</version>
    </dependency>

So if some dependency uses java-commons-logging (jcl), log4j, or java.util.logging (jul) than its logging gets bridged to slf4j. Application logging uses slf4j as well and that is than configured with logback.

So you may need to use one of the bridges (like jcl-over-slf4j) to get logging of external dependencies under control.

Edit: Pavel Horal, thanks for the jul, and yes, you're right. One needs to do a bit more than just add dependencies. We also have a logback configurator which explicitly calls SLF4JBridgeHandler.install(). Our configurator also loads the logback configuration file and I forgot about this call. But I mainly wanted to point in the direction of a problem with multiple logging libraries used by external dependencies and to these bridges that can put different logging libraries under the roof of logback.

*"I don't even know"* -> [`java.util.logging`](http://docs.oracle.com/javase/7/docs/api/java/util/logging/package-summary.html) ... and it is not that easy as *just using the right dependency* - http://stackoverflow.com/questions/9117030/jul-to-slf4j-bridge — Pavel Horal, Jun 14 '15 at 21:41
Everything is using SLF4J. That's why it is a mystery to me why the logging config registers correct but the tests all log as if level is TRACE or ANY. — The Coordinator, Jun 16 '15 at 10:10
Thanks for playing. I gave you the bounty, even though this does not solve the problem. It is a valuable addition. — The Coordinator, Jun 17 '15 at 22:13

Logger slf4j is not using the logback configured level

2 Answers2