Affects PMD Version: 7.0.x - because of SLF4J #896
Description:
There are a couple of tests that change the logging level in the pmd 7 branch, to test the --debug cli switch for instance:
|
assertThat(log, containsString("[main] INFO net.sourceforge.pmd.cli.commands.internal.AbstractPmdSubcommand - Log level is at TRACE")); |
I'm afraid this only works by chance... When the trace level is enabled we are supposed to see log statements like Adding file ... from the file collector. If you add an assert like assertThat(log, containsString("Adding file")); to the linked test you will see that it fails, but only if you run the entire test class (not just the given test).
The problem is that when we reinitialize the log level in Slf4jSimpleConfiguration, that doesn't change the log level of loggers that have already been created. This reset routine calls two methods via reflection:
org.slf4j.impl.SimpleLogger#init: this parses system properties and changes the default logging level of the logger factory, meaning, new loggers will use that log level
org.slf4j.impl.SimpleLoggerFactory#reset: this clears the Map<String, Logger> that caches loggers that have already been created. So the next time eg LoggerFactory.getLogger(FileCollector.class) is called, it will get a new logger with the correct new logging level.
The problem is that we create logger instances only once, and then store them in static final fields:
|
private static final Logger LOG = LoggerFactory.getLogger(FileCollector.class); |
The call to LoggerFactory is executed only once in a given VM, and the created logger will use whatever default log level is defined at that point. But if you later change the log level with the reset method, the logger of FileCollector will be the same in that static field, and will still use the old log level.
This makes it significantly harder to test the behavior of the CLI with this debug flag... Tests are order dependent.
For instance in this test class:
|
String[] args = { "-d", SOURCE_FOLDER, "-f", "text", "-R", RSET_NO_VIOLATION, "-version", "1.5", "-language", "java", "--debug", "--no-progress", }; |
|
String log = runTest(args); |
|
assertThat(log, containsPattern("Adding file .*\\.java \\(lang: java 1\\.5\\)")); |
This test apparently succeeds, but it's only because by chance, the first test that gets executed in this class uses the --debug flag. All other tests then actually observe TRACE and DEBUG level log statements, even those that don't use the --debug flag. For instance this is the log of the testWrongRuleset test in this class, which doesn't use the debug flag:
[main] INFO net.sourceforge.pmd.PMD - Log level is at INFO
[main] DEBUG net.sourceforge.pmd.internal.util.FileCollectionUtil - Adding directory src/test/resources/net/sourceforge/pmd/cli.
[main] TRACE net.sourceforge.pmd.lang.document.FileCollector - Adding file /home/clem/Documents/Git/pmd/pmd-java/src/test/resources/net/sourceforge/pmd/cli/EmptyIfStatement.java (lang: java 19)
We announce that the log level is INFO, even though the level of other internal loggers actually stayed at TRACE.
Possible solutions
- Maybe we should never store loggers in final fields, but always call
LoggerFactory.getLogger? This would work but would probably be bad for performance, because getLogger performs a lookup in a ConcurrentMap.
- Maybe we can ask the test runner to fork a JVM for each test?
- A hacky fix: instead of calling
SimpleLoggerFactory#reset and clearing the logger cache, we could
- fetch the map field by reflection
- iterate through all the loggers currently alive
- set their log level field by reflection
This third item seems to me like the easiest thing to do... @adangel wdyt?
Affects PMD Version: 7.0.x - because of SLF4J #896
Description:
There are a couple of tests that change the logging level in the pmd 7 branch, to test the
--debugcli switch for instance:pmd/pmd-cli/src/test/java/net/sourceforge/pmd/cli/PmdCliTest.java
Line 174 in 1f43af7
I'm afraid this only works by chance... When the trace level is enabled we are supposed to see log statements like
Adding file ...from the file collector. If you add an assert likeassertThat(log, containsString("Adding file"));to the linked test you will see that it fails, but only if you run the entire test class (not just the given test).The problem is that when we reinitialize the log level in Slf4jSimpleConfiguration, that doesn't change the log level of loggers that have already been created. This reset routine calls two methods via reflection:
org.slf4j.impl.SimpleLogger#init: this parses system properties and changes the default logging level of the logger factory, meaning, new loggers will use that log levelorg.slf4j.impl.SimpleLoggerFactory#reset: this clears theMap<String, Logger>that caches loggers that have already been created. So the next time egLoggerFactory.getLogger(FileCollector.class)is called, it will get a new logger with the correct new logging level.The problem is that we create logger instances only once, and then store them in static final fields:
pmd/pmd-core/src/main/java/net/sourceforge/pmd/lang/document/FileCollector.java
Line 52 in dd96116
The call to
LoggerFactoryis executed only once in a given VM, and the created logger will use whatever default log level is defined at that point. But if you later change the log level with the reset method, the logger ofFileCollectorwill be the same in that static field, and will still use the old log level.This makes it significantly harder to test the behavior of the CLI with this debug flag... Tests are order dependent.
For instance in this test class:
pmd/pmd-java/src/test/java/net/sourceforge/pmd/cli/CLITest.java
Lines 68 to 70 in 29d31ec
This test apparently succeeds, but it's only because by chance, the first test that gets executed in this class uses the
--debugflag. All other tests then actually observe TRACE and DEBUG level log statements, even those that don't use the--debugflag. For instance this is the log of thetestWrongRulesettest in this class, which doesn't use the debug flag:We announce that the log level is INFO, even though the level of other internal loggers actually stayed at TRACE.
Possible solutions
LoggerFactory.getLogger? This would work but would probably be bad for performance, becausegetLoggerperforms a lookup in a ConcurrentMap.SimpleLoggerFactory#resetand clearing the logger cache, we couldThis third item seems to me like the easiest thing to do... @adangel wdyt?