diff --git a/solr/CHANGES.txt b/solr/CHANGES.txt index e7295e8a090..e6a2d15de14 100644 --- a/solr/CHANGES.txt +++ b/solr/CHANGES.txt @@ -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 --------------------- diff --git a/solr/core/src/test/org/apache/solr/handler/admin/LoggingHandlerTest.java b/solr/core/src/test/org/apache/solr/handler/admin/LoggingHandlerTest.java index 933b1266f65..d98c65bd3d9 100644 --- a/solr/core/src/test/org/apache/solr/handler/admin/LoggingHandlerTest.java +++ b/solr/core/src/test/org/apache/solr/handler/admin/LoggingHandlerTest.java @@ -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()); + + } } diff --git a/solr/test-framework/src/java/org/apache/solr/util/LogLevel.java b/solr/test-framework/src/java/org/apache/solr/util/LogLevel.java index d064263dc18..0e488e7669f 100644 --- a/solr/test-framework/src/java/org/apache/solr/util/LogLevel.java +++ b/solr/test-framework/src/java/org/apache/solr/util/LogLevel.java @@ -77,21 +77,32 @@ public @interface LogLevel { } private static Map setLogLevels(Map logLevels) { - LoggerContext ctx = LoggerContext.getContext(false); - Configuration config = ctx.getConfiguration(); + final LoggerContext ctx = LoggerContext.getContext(false); + final Configuration config = ctx.getConfiguration(); - Map 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 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; diff --git a/solr/test-framework/src/test/org/apache/solr/TestLogLevelAnnotations.java b/solr/test-framework/src/test/org/apache/solr/TestLogLevelAnnotations.java index cfc9d934433..22c0bb65906 100644 --- a/solr/test-framework/src/test/org/apache/solr/TestLogLevelAnnotations.java +++ b/solr/test-framework/src/test/org/apache/solr/TestLogLevelAnnotations.java @@ -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 AfterClass 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 configurations have been reset after the test + *

+ * NOTE: We only validate @LogLevel modifications made at the + * {@link #testMethodLogLevels} level, not at the 'class' level, because of the lifecycle of junit + * methods: This @AfterClass will run before the SolrTestCaseJ4 + * @AfterClass method where the 'class' @LogLevel modifications will be reset. + *

+ * + * @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 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()); + + } }