-
Notifications
You must be signed in to change notification settings - Fork 979
Test Logging
Drill code makes extensive use of logging to provide the developer with in-depth information about Drill's internals. The logging is vital when tracking down a problem, but a distraction at other times. To control logging, you must understand the various forms of logging and logging control.
Drill uses Logback Classic as its logger. In production mode, you control logging via the $DRILL_HOME/conf/logback.xml (or, alternatively, $DRILL_SITE/logback.xml) file. This configuration is not used when testing, however.
When running tests, either in Maven or your IDE, Drill uses a different configuration file: the one in the src/test/resources folder for the Maven subproject that holds the test. For example, if you run tests in the drill-common project, Logback will find the configuration in common/src/test/resources/logback.xml.
Configure logging in this test file. For example, to set the debug log level:
<logger name="org.apache.drill" additivity="false">
<level value="debug" />
Under Maven, each module has visibility to is own test resources, but not the test resources from any other Maven module. To control test logging, therefore, we must have a copy of logback-test.xml in the src/test/resources folder of each Maven module.
Sometimes it is helpful to verify which configuration file Logback actually uses. As explained in this Stack Overflow post, you can find this information using a Logback property:
mvn surefire:test -Dtest=TestClassPathScanner \
-Dlogback.statusListenerClass=ch.qos.logback.core.status.OnConsoleStatusListener
Maven output is controlled by Maven's logging mechanism which seems to be SLF4J Simple.
To "quiet" the amount of Maven output, you must modify the logging configuration file in your Maven installation. (There seems to be no way to modify logging in the POM file itself.)
$ cd `dirname \`which mvn\``/../conf/logging
$ pwd # Should print /some/path/apache-maven-3.x.y/conf/logging
$ vi simplelogger.properties
The following suppresses all but the most of Maven's "info" logging:
#org.slf4j.simpleLogger.defaultLogLevel=info
org.slf4j.simpleLogger.defaultLogLevel=warn
...
# Custom entries
# Display check style issues (shown at info log level)
org.slf4j.simpleLogger.log.org.apache.maven.plugin.checkstyle=info
Since the maven-checkstyle-plugin displays its errors to the log at the INFO log level, we have to allow it to display info-level messages (the last line in the example.)
Since this is a Maven configuration (not a POM file change), you must make it on each machine on which you run Maven.
As noted above, logging within Drill tests is controlled by Logback, not Maven.
Logback really prefers to find a single logback.xml configuration file on the class path. There seems to be a subtle difference in how Eclipse and Maven build the class path used to run tests. Eclipse includes the test resources from all dependencies, whereas Surefire does not. This means that, if you run a test in exec/java-exec, such as TestClassPathScanner, the test resources from common will be on the class path if run from Eclipse, but not run from Surefire.
For the most part, having extra items on the class path in Eclipse is benign. Problems occur, however, when files of the same name appears multiple time on the class path. This is the situation with Logback.
When run under Maven Surefire, each project requires its own logback.xml (or, preferably logback-test.xml) in src/test/resources.
But, when run under Eclipse, the test program sees all the Logback config files on the path, causing Logback to print a bunch of log messages:
...WARN in ch.qos.logback.classic.LoggerContext[default] -
Resource [logback.xml] occurs multiple times on the classpath.
...WARN in ch.qos.logback.classic.LoggerContext[default] -
Resource [logback.xml] occurs at [file:/path/to/drill/exec/java-exec/target/test-classes/logback.xml]
...WARN in ch.qos.logback.classic.LoggerContext[default] -
Resource [logback.xml] occurs at [file:/path/to/drill/common/target/test-classes/logback.xml]
To see this, add the following to any test from java-exec, such as TestClassPathScanner:
System.out.println( "Class path: " + System.getProperty("java.class.path") );
When run in Eclipse:
Class path: /path/to/drill/exec/java-exec/target/test-classes:\
/path/to/drill/exec/java-exec/target/classes:...\
/path/to/drill/common/target/test-classes:...\
...INFO in ch.qos.logback.classic.LoggerContext[default] - \
Found resource [logback.xml] at [file:/path/to/drill/common/target/test-classes/logback.xml]
But, when run under Maven:
Class path: /path/to/drill/exec/java-exec/target/test-classes:\
/path/to/drill/exec/java-exec/target/classes:...\
/Users/me/.m2/repository/org/apache/drill/drill-common/1.9.0-SNAPSHOT/drill-common-1.9.0-SNAPSHOT.jar:...
...INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.xml]
The Eclipse behavior seems to be both known and unlikely to change.
Based on the Logback Configuration documentation, the solution seems to be to apply a "No-op" logger by default. In Eclipse -> Preferences -> Java -> Installed JREs, select your default JRE or JDK. Click Edit... Add the following as one of the Default VM arguments:
-Dlogback.statusListenerClass=ch.qos.logback.core.status.NopStatusListener
(Since this is a system property, it will be passed to every run or debug session. No harm if you happen to use a project that does not use Logback, the property will just be ignored by everything else.)
Then, if for some reason you want to see the Logback logging, add the following to your debug launch configuration:
-Dlogback.statusListenerClass=ch.qos.logback.core.status.OnConsoleStatusListener
The launch configuration option overrides (appears on the Java command line after) the global setting.