[test] Tests that change the logging level do not work

[oowekyala]

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:

pmd/pmd-cli/src/test/java/net/sourceforge/pmd/cli/PmdCliTest.java

Line 174 in 1f43af7

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:

pmd/pmd-core/src/main/java/net/sourceforge/pmd/lang/document/FileCollector.java

Line 52 in dd96116

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:

pmd/pmd-java/src/test/java/net/sourceforge/pmd/cli/CLITest.java

Lines 68 to 70 in 29d31ec

	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

1. 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.
2. Maybe we can ask the test runner to fork a JVM for each test?
3. 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?

[adangel]

Fixed for pmd 7 via #4263