SOLR-14099: Fixed @LogLevel annotation in test-framework to correctly 'unset' Loggers after test

This commit is contained in:
Chris Hostetter 2019-12-17 14:58:45 -07:00
parent 279a391cf3
commit cc4262a8ec
4 changed files with 166 additions and 44 deletions

View File

@ -121,7 +121,8 @@ Optimizations
Bug Fixes
---------------------
(No changes)
* SOLR-14099: Fixed @LogLevel annotation in test-framework to correctly 'unset' Loggers after test (hossman)
Other Changes
---------------------

View File

@ -19,19 +19,22 @@ package org.apache.solr.handler.admin;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.config.LoggerConfig;
import org.apache.logging.log4j.core.config.Configuration;
import org.apache.solr.SolrTestCaseJ4;
import org.apache.solr.common.params.CommonParams;
import org.apache.solr.common.util.SuppressForbidden;
import org.apache.solr.util.LogLevel;
import org.junit.BeforeClass;
import org.junit.Test;
@SuppressForbidden(reason = "test uses log4j2 because it tests output at a specific level")
@LogLevel("org.apache.solr.bogus_logger_package.BogusLoggerClass=DEBUG")
public class LoggingHandlerTest extends SolrTestCaseJ4 {
private final String PARENT_LOGGER_NAME = "org.apache.solr.bogus_logger_package";
private final String CLASS_LOGGER_NAME = PARENT_LOGGER_NAME + ".BogusLoggerClass";
// TODO: This only tests Log4j at the moment, as that's what's defined
// through the CoreContainer.
@ -45,36 +48,48 @@ public class LoggingHandlerTest extends SolrTestCaseJ4 {
@Test
public void testLogLevelHandlerOutput() throws Exception {
Logger tst = LogManager.getLogger("org.apache.solr.SolrTestCaseJ4");
LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
LoggerConfig loggerConfig = ctx.getConfiguration().getLoggerConfig(tst.getName());
loggerConfig.setLevel(Level.INFO);
ctx.updateLoggers();
// HACK: work around for SOLR-14099...
Logger apache = LogManager.getLogger("org.apache");
final String apache_level = null == apache.getLevel()
? "null[@name='level']"
: "str[@name='level'][.='"+apache.getLevel()+"']";
// sanity check our setup...
assertNotNull(this.getClass().getAnnotation(LogLevel.class));
final String annotationConfig = this.getClass().getAnnotation(LogLevel.class).value();
assertTrue("WTF: " + annotationConfig, annotationConfig.startsWith( PARENT_LOGGER_NAME ));
assertTrue("WTF: " + annotationConfig, annotationConfig.startsWith( CLASS_LOGGER_NAME ));
assertTrue("WTF: " + annotationConfig, annotationConfig.endsWith( Level.DEBUG.toString() ));
assertEquals(Level.DEBUG, LogManager.getLogger( CLASS_LOGGER_NAME ).getLevel());
final LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
final Configuration config = ctx.getConfiguration();
assertEquals("Unexpected config for " + PARENT_LOGGER_NAME + " ... expected 'root' config",
config.getRootLogger(),
config.getLoggerConfig(PARENT_LOGGER_NAME));
assertEquals(Level.DEBUG, config.getLoggerConfig(CLASS_LOGGER_NAME).getLevel());
assertQ("Show Log Levels OK",
req(CommonParams.QT,"/admin/logging")
,"//arr[@name='loggers']/lst/str[.='"+tst.getName()+"']/../str[@name='level'][.='"+tst.getLevel()+"']"
,"//arr[@name='loggers']/lst/str[.='org.apache']/../" + apache_level
,"//arr[@name='loggers']/lst/str[.='"+CLASS_LOGGER_NAME+"']/../str[@name='level'][.='DEBUG']"
,"//arr[@name='loggers']/lst/str[.='"+PARENT_LOGGER_NAME+"']/../null[@name='level']"
);
assertQ("Set a level",
assertQ("Set a (new) level",
req(CommonParams.QT,"/admin/logging",
"set", tst.getName()+":TRACE")
,"//arr[@name='loggers']/lst/str[.='"+tst.getName()+"']/../str[@name='level'][.='TRACE']"
"set", PARENT_LOGGER_NAME+":TRACE")
,"//arr[@name='loggers']/lst/str[.='"+PARENT_LOGGER_NAME+"']/../str[@name='level'][.='TRACE']"
);
assertEquals(Level.TRACE, config.getLoggerConfig(PARENT_LOGGER_NAME).getLevel());
assertEquals(Level.DEBUG, config.getLoggerConfig(CLASS_LOGGER_NAME).getLevel());
// NOTE: LoggeringHandler doesn't actually "remove" the LoggerConfig, ...
// evidently so people using they UI can see that it was explicitly turned "OFF" ?
assertQ("Remove a level",
req(CommonParams.QT,"/admin/logging",
"set", tst.getName()+":null")
,"//arr[@name='loggers']/lst/str[.='"+tst.getName()+"']/../str[@name='level'][.='OFF']"
"set", PARENT_LOGGER_NAME+":null")
,"//arr[@name='loggers']/lst/str[.='"+PARENT_LOGGER_NAME+"']/../str[@name='level'][.='OFF']"
);
assertEquals(Level.OFF, config.getLoggerConfig(PARENT_LOGGER_NAME).getLevel());
assertEquals(Level.DEBUG, config.getLoggerConfig(CLASS_LOGGER_NAME).getLevel());
}
}

View File

@ -77,21 +77,32 @@ public @interface LogLevel {
}
private static Map<String, Level> setLogLevels(Map<String, Level> logLevels) {
LoggerContext ctx = LoggerContext.getContext(false);
Configuration config = ctx.getConfiguration();
final LoggerContext ctx = LoggerContext.getContext(false);
final Configuration config = ctx.getConfiguration();
Map<String, Level> oldLevels = new HashMap<>();
logLevels.forEach((loggerName, level) -> {
LoggerConfig logConfig = config.getLoggerConfig(loggerName);
// what the initial logger level was. It will use the root value if logger is being defined for the first time
oldLevels.put(loggerName, logConfig.getLevel());
final Map<String, Level> oldLevels = new HashMap<>();
logLevels.forEach((loggerName, newLevel) -> {
final LoggerConfig logConfig = config.getLoggerConfig(loggerName);
if (loggerName.equals(logConfig.getName())) {
logConfig.setLevel(level);
// we have an existing LoggerConfig for this specific loggerName
// record the existing 'old' level...
oldLevels.put(loggerName, logConfig.getLevel());
// ...and set the new one (or remove if null) ...
if (null == newLevel) {
config.removeLogger(loggerName);
} else {
logConfig.setLevel(newLevel);
}
} else {
LoggerConfig loggerConfig = new LoggerConfig(loggerName, level, true);
loggerConfig.setLevel(level);
config.addLogger(loggerName, loggerConfig);
// there is no existing configuration for the exact loggerName, logConfig is some ancestor
// record an 'old' level of 'null' to track the lack of any configured level...
oldLevels.put(loggerName, null);
// ...and now create a new logger config wih our new level
final LoggerConfig newLoggerConfig = new LoggerConfig(loggerName, newLevel, true);
config.addLogger(loggerName, newLoggerConfig);
}
assert oldLevels.containsKey(loggerName);
});
ctx.updateLoggers();
return oldLevels;

View File

@ -17,27 +17,122 @@
package org.apache.solr;
import java.util.Map;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.config.Configuration;
import org.apache.solr.common.util.SuppressForbidden;
import org.apache.solr.util.LogLevel;
import org.junit.Test;
import org.junit.AfterClass;
import org.junit.BeforeClass;
@SuppressForbidden(reason="We need to use log4J2 classes to access the log levels")
@LogLevel("org.apache.solr.ClassLogLevel=error;org.apache.solr.MethodLogLevel=warn")
@LogLevel("org.apache.solr.bogus_logger.ClassLogLevel=error;org.apache.solr.bogus_logger.MethodLogLevel=warn")
public class TestLogLevelAnnotations extends SolrTestCaseJ4 {
@Test
private static final String bogus_logger_prefix = "org.apache.solr.bogus_logger";
/**
* We don't want a hardocded assumption here because it may change based on how the user runs the test.
*/
public static final Level DEFAULT_LOG_LEVEL = LogManager.getRootLogger().getLevel();
/**
* Sanity check that our <code>AfterClass</code> logic is valid, and isn't broken right from the start
*
* @see #checkLogLevelsAfterClass
*/
@BeforeClass
public static void checkLogLevelsBeforeClass() {
final LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
final Configuration config = ctx.getConfiguration();
// NOTE: we're checking the CONFIGURATION of the loggers, not the "effective" value of the Logger
assertEquals(DEFAULT_LOG_LEVEL, config.getRootLogger().getLevel());
assertEquals("Your Logger conf sets a level on a bogus package that breaks this test: "
+ bogus_logger_prefix,
config.getRootLogger(),
config.getLoggerConfig(bogus_logger_prefix));
assertEquals(Level.ERROR, config.getLoggerConfig(bogus_logger_prefix + ".ClassLogLevel").getLevel());
assertEquals(Level.WARN, config.getLoggerConfig(bogus_logger_prefix + ".MethodLogLevel").getLevel());
// Now sanity check the EFFECTIVE Level of these loggers before the methods run...
assertEquals(DEFAULT_LOG_LEVEL, LogManager.getRootLogger().getLevel());
assertEquals(DEFAULT_LOG_LEVEL, LogManager.getLogger(bogus_logger_prefix).getLevel());
assertEquals(Level.ERROR, LogManager.getLogger(bogus_logger_prefix + ".ClassLogLevel").getLevel());
assertEquals(Level.WARN, LogManager.getLogger(bogus_logger_prefix + ".MethodLogLevel").getLevel());
}
/**
* Check that the expected log level <em>configurations</em> have been reset after the test
* <p>
* <b>NOTE:</b> We only validate <code>@LogLevel</code> modifications made at the
* {@link #testMethodLogLevels} level, not at the 'class' level, because of the lifecycle of junit
* methods: This <code>@AfterClass</code> will run before the <code>SolrTestCaseJ4</code>
* <code>@AfterClass</code> method where the 'class' <code>@LogLevel</code> modifications will be reset.
* </p>
*
* @see #checkLogLevelsBeforeClass
* @see #testWhiteBoxMethods
*/
@AfterClass
public static void checkLogLevelsAfterClass() {
final LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
final Configuration config = ctx.getConfiguration();
// NOTE: we're checking the CONFIGURATION of the loggers, not the "effective" value of the Logger
assertEquals(DEFAULT_LOG_LEVEL, config.getRootLogger().getLevel());
assertEquals(bogus_logger_prefix
+ " should have had it's config unset; should now return the 'root' LoggerConfig",
config.getRootLogger(),
config.getLoggerConfig(bogus_logger_prefix));
assertEquals(Level.ERROR, config.getLoggerConfig(bogus_logger_prefix + ".ClassLogLevel").getLevel());
assertEquals(Level.WARN, config.getLoggerConfig(bogus_logger_prefix + ".MethodLogLevel").getLevel());
// Now sanity check the EFFECTIVE Level of these loggers...
assertEquals(DEFAULT_LOG_LEVEL, LogManager.getRootLogger().getLevel());
assertEquals(DEFAULT_LOG_LEVEL, LogManager.getLogger(bogus_logger_prefix).getLevel());
assertEquals(Level.ERROR, LogManager.getLogger(bogus_logger_prefix + ".ClassLogLevel").getLevel());
assertEquals(Level.WARN, LogManager.getLogger(bogus_logger_prefix + ".MethodLogLevel").getLevel());
}
public void testClassLogLevels() {
assertEquals(Level.ERROR, LogManager.getLogger("org.apache.solr.ClassLogLevel").getLevel());
assertEquals(Level.WARN, LogManager.getLogger("org.apache.solr.MethodLogLevel").getLevel());
assertEquals(DEFAULT_LOG_LEVEL, LogManager.getLogger("org.apache.solr.bogus_logger").getLevel());
assertEquals(Level.ERROR, LogManager.getLogger(bogus_logger_prefix + ".ClassLogLevel").getLevel());
assertEquals(Level.WARN, LogManager.getLogger(bogus_logger_prefix + ".MethodLogLevel").getLevel());
}
@Test
@LogLevel("org.apache.solr.MethodLogLevel=debug")
@LogLevel("org.apache.solr.bogus_logger.MethodLogLevel=debug;org.apache.solr.bogus_logger=INFO")
public void testMethodLogLevels() {
assertEquals(Level.ERROR, LogManager.getLogger("org.apache.solr.ClassLogLevel").getLevel());
assertEquals(Level.DEBUG, LogManager.getLogger("org.apache.solr.MethodLogLevel").getLevel());
assertEquals(Level.INFO, LogManager.getLogger(bogus_logger_prefix + ".BogusClass").getLevel());
assertEquals(Level.ERROR, LogManager.getLogger(bogus_logger_prefix + ".ClassLogLevel").getLevel());
assertEquals(Level.DEBUG, LogManager.getLogger(bogus_logger_prefix + ".MethodLogLevel").getLevel());
}
/**
* Directly test the methods in the {@link LogLevel} annotation class
*/
@LogLevel("org.apache.solr.bogus_logger.MethodLogLevel=TRACE")
public void testWhiteBoxMethods() {
final LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
final Configuration config = ctx.getConfiguration();
final Map<String,Level> oldLevels = LogLevel.Configurer.setLevels(bogus_logger_prefix + "=TRACE");
//
assertEquals(oldLevels.toString(), 1, oldLevels.size());
assertNull(oldLevels.get(bogus_logger_prefix));
//
assertEquals(Level.TRACE, config.getLoggerConfig(bogus_logger_prefix).getLevel());
assertEquals(Level.TRACE, LogManager.getLogger(bogus_logger_prefix).getLevel());
// restore (to 'unset' values)...
LogLevel.Configurer.restoreLogLevels(oldLevels);
assertEquals(bogus_logger_prefix
+ " should have had it's config unset; should now return the 'root' LoggerConfig",
config.getRootLogger(),
config.getLoggerConfig(bogus_logger_prefix));
assertEquals(DEFAULT_LOG_LEVEL, LogManager.getLogger(bogus_logger_prefix).getLevel());
}
}