You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@solr.apache.org by ho...@apache.org on 2023/05/03 19:00:16 UTC
[solr] branch main updated: SOLR-16771: Fixed behavior and handling of 'unset' logging levels in /admin/info/logging API and related Admin UI
This is an automated email from the ASF dual-hosted git repository.
hossman pushed a commit to branch main
in repository https://gitbox.apache.org/repos/asf/solr.git
The following commit(s) were added to refs/heads/main by this push:
new 0788fb488b7 SOLR-16771: Fixed behavior and handling of 'unset' logging levels in /admin/info/logging API and related Admin UI
0788fb488b7 is described below
commit 0788fb488b78a31347738bbc481041f115f673f0
Author: Chris Hostetter <ho...@apache.org>
AuthorDate: Wed May 3 12:00:06 2023 -0700
SOLR-16771: Fixed behavior and handling of 'unset' logging levels in /admin/info/logging API and related Admin UI
---
solr/CHANGES.txt | 2 +
.../apache/solr/logging/log4j2/Log4j2Watcher.java | 81 +++++----
.../solr/handler/admin/LoggingHandlerTest.java | 186 ++++++++++++++-------
3 files changed, 179 insertions(+), 90 deletions(-)
diff --git a/solr/CHANGES.txt b/solr/CHANGES.txt
index 4ad05180a0c..6e34b984d19 100644
--- a/solr/CHANGES.txt
+++ b/solr/CHANGES.txt
@@ -147,6 +147,8 @@ Bug Fixes
* SOLR-16777: Fix for Schema Designer blindly trusting potentially malicious configsets (Ishan Chattopadhyaya, Skay)
+* SOLR-16771: Fixed behavior and handling of 'unset' logging levels in /admin/info/logging API and related Admin UI (hossman)
+
Dependency Upgrades
---------------------
* PR#1494: Upgrade forbiddenapis to 3.5 (Uwe Schindler)
diff --git a/solr/core/src/java/org/apache/solr/logging/log4j2/Log4j2Watcher.java b/solr/core/src/java/org/apache/solr/logging/log4j2/Log4j2Watcher.java
index 66ea68ff3a0..e5ecc60bccf 100644
--- a/solr/core/src/java/org/apache/solr/logging/log4j2/Log4j2Watcher.java
+++ b/solr/core/src/java/org/apache/solr/logging/log4j2/Log4j2Watcher.java
@@ -80,13 +80,16 @@ public class Log4j2Watcher extends LogWatcher<LogEvent> {
@SuppressForbidden(reason = "class is specific to log4j2")
protected static class Log4j2Info extends LoggerInfo {
- Log4j2Info(String name, Level level) {
+ public Log4j2Info(String name, Level level, boolean isSet) {
super(name);
if (level != null) {
this.level = level.toString();
}
+ this.isSet = isSet;
}
+ private final boolean isSet;
+
@Override
public String getLevel() {
return (level != null) ? level : null;
@@ -99,7 +102,7 @@ public class Log4j2Watcher extends LogWatcher<LogEvent> {
@Override
public boolean isSet() {
- return level != null;
+ return isSet;
}
}
@@ -134,22 +137,21 @@ public class Log4j2Watcher extends LogWatcher<LogEvent> {
LoggerConfig loggerConfig = getLoggerConfig(ctx, loggerName);
assert loggerConfig != null;
boolean madeChanges = false;
- if (loggerName.equals(loggerConfig.getName()) || isRootLogger(loggerName)) {
- if (level == null || "unset".equals(level) || "null".equals(level)) {
- level = Level.OFF.toString();
- loggerConfig.setLevel(Level.OFF);
- madeChanges = true;
- } else {
- try {
- loggerConfig.setLevel(Level.valueOf(level));
- madeChanges = true;
- } catch (IllegalArgumentException iae) {
- log.error("{} is not a valid log level! Valid values are: {}", level, getAllLevels());
- }
+
+ Level _level = null;
+ if (!(level == null || "unset".equals(level) || "null".equals(level))) {
+ try {
+ _level = Level.valueOf(level);
+ } catch (IllegalArgumentException iae) {
+ log.error("{} is not a valid log level! Valid values are: {}", level, getAllLevels());
}
+ }
+ if (loggerName.equals(loggerConfig.getName()) || isRootLogger(loggerName)) {
+ loggerConfig.setLevel(_level);
+ madeChanges = true;
} else {
- // It doesn't have its own logger yet so let's create one
- LoggerConfig explicitConfig = new LoggerConfig(loggerName, Level.valueOf(level), true);
+ // It doesn't have its own logger config yet so let's create one
+ LoggerConfig explicitConfig = new LoggerConfig(loggerName, _level, true);
explicitConfig.setParent(loggerConfig);
config.addLogger(loggerName, explicitConfig);
madeChanges = true;
@@ -158,7 +160,7 @@ public class Log4j2Watcher extends LogWatcher<LogEvent> {
if (madeChanges) {
ctx.updateLoggers();
if (log.isInfoEnabled()) {
- log.info("Setting log level to '{}' for logger: {}", level, loggerName);
+ log.info("Setting log level to '{}' for logger: {}", _level, loggerName);
}
}
}
@@ -178,36 +180,53 @@ public class Log4j2Watcher extends LogWatcher<LogEvent> {
public Collection<LoggerInfo> getAllLoggers() {
Logger root = LogManager.getRootLogger();
LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
+ LoggerConfig rootConfig = ctx.getConfiguration().getRootLogger();
Map<String, LoggerInfo> map = new HashMap<>(ctx.getLoggers().size());
- // First let's get the explicitly configured loggers
- Map<String, LoggerConfig> loggers = ctx.getConfiguration().getLoggers();
- for (Map.Entry<String, LoggerConfig> logger : loggers.entrySet()) {
- String name = logger.getKey();
+ // First add the ROOT loger with the ROOT level
+ map.put(
+ LoggerInfo.ROOT_NAME,
+ new Log4j2Info(
+ LoggerInfo.ROOT_NAME, root.getLevel(), null != rootConfig.getExplicitLevel()));
- if (logger == root
- || root.equals(logger)
- || isRootLogger(name)
- || (name != null && name.isEmpty())) {
+ // Next get the explicitly configured loggers
+ Map<String, LoggerConfig> configs = ctx.getConfiguration().getLoggers();
+ for (Map.Entry<String, LoggerConfig> config : configs.entrySet()) {
+ final String name = config.getKey();
+ final Logger logger = ctx.getLogger(name);
+
+ if (logger == root || root.equals(logger) || isRootLogger(name) || "".equals(name)) {
continue;
}
- map.put(name, new Log4j2Info(name, logger.getValue().getLevel()));
+
+ // NOTE: just because we have an explicit configuration, doesn't mean we have an explitly set
+ // level
+ // (Configuration might be for some other property, and level is still inherited)
+ map.putIfAbsent(
+ name,
+ new Log4j2Info(name, logger.getLevel(), null != config.getValue().getExplicitLevel()));
}
- for (org.apache.logging.log4j.core.Logger logger : ctx.getLoggers()) {
+ // Now add any "in use" loggers (that aren't already explicitly configured) and their parents
+ for (Logger logger : ctx.getLoggers()) {
String name = logger.getName();
- if (logger == root || root.equals(logger) || isRootLogger(name)) continue;
- map.put(name, new Log4j2Info(name, logger.getLevel()));
+ if (logger == root || root.equals(logger) || isRootLogger(name) || "".equals(name)) {
+ continue;
+ }
+
+ // If we didn't already see a LoggerConfig for these loggers, then their level is
+ // not (explicitly) set
+ map.putIfAbsent(name, new Log4j2Info(name, logger.getLevel(), false));
while (true) {
int dot = name.lastIndexOf('.');
if (dot < 0) break;
name = name.substring(0, dot);
- if (!map.containsKey(name)) map.put(name, new Log4j2Info(name, null));
+ map.putIfAbsent(name, new Log4j2Info(name, logger.getLevel(), false));
}
}
- map.put(LoggerInfo.ROOT_NAME, new Log4j2Info(LoggerInfo.ROOT_NAME, root.getLevel()));
+
return map.values();
}
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 097306e2088..736ad53c69a 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
@@ -16,9 +16,9 @@
*/
package org.apache.solr.handler.admin;
+import java.util.Arrays;
import java.util.List;
import java.util.Map;
-import org.apache.commons.lang3.ObjectUtils;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.core.LoggerContext;
@@ -35,11 +35,16 @@ import org.apache.solr.util.LogLevel;
import org.junit.BeforeClass;
import org.junit.Test;
+// regardless of what logging config is used to run test, we want a known-fixed logging level for
+// this package
+// to ensure our manipulations have expected effect
+@LogLevel("org.apache.solr.bogus_logger_package=DEBUG")
@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";
+ private final String A_LOGGER_NAME = PARENT_LOGGER_NAME + ".BogusClass_A";
+ private final String B_LOGGER_NAME = PARENT_LOGGER_NAME + ".BogusClass_B";
+ private final String BX_LOGGER_NAME = B_LOGGER_NAME + ".BogusNestedClass_X";
// TODO: This only tests Log4j at the moment, as that's what's defined
// through the CoreContainer.
@@ -55,23 +60,40 @@ public class LoggingHandlerTest extends SolrTestCaseJ4 {
@Test
public void testLogLevelHandlerOutput() throws Exception {
- // 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());
-
+ // Direct access to the internal log4j configuration
final LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
+ assumeTrue("Test only works when log4j is in use", null != ctx);
+
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());
+ { // sanity check our setup...
+
+ // did anybody break the anotations?
+ 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.endsWith(Level.DEBUG.toString()));
+
+ // actual log4j configuration
+ assertNotNull(
+ "Parent logger should have explicit config", config.getLoggerConfig(PARENT_LOGGER_NAME));
+ assertEquals(
+ "Parent logger should have explicit DEBUG",
+ Level.DEBUG,
+ config.getLoggerConfig(PARENT_LOGGER_NAME).getExplicitLevel());
+ for (String logger : Arrays.asList(A_LOGGER_NAME, B_LOGGER_NAME, BX_LOGGER_NAME)) {
+ assertEquals(
+ "Unexpected config for " + logger + " ... expected parent's config",
+ config.getLoggerConfig(PARENT_LOGGER_NAME),
+ config.getLoggerConfig(logger));
+ }
+
+ // Either explicit, or inherited, effictive logger values...
+ for (String logger :
+ Arrays.asList(PARENT_LOGGER_NAME, A_LOGGER_NAME, B_LOGGER_NAME, BX_LOGGER_NAME)) {
+ assertEquals(Level.DEBUG, LogManager.getLogger(logger).getLevel());
+ }
+ }
SolrClient client = new EmbeddedSolrServer(h.getCore());
ModifiableSolrParams mparams = new ModifiableSolrParams();
@@ -80,55 +102,101 @@ public class LoggingHandlerTest extends SolrTestCaseJ4 {
client.request(
new GenericSolrRequest(SolrRequest.METHOD.GET, "/admin/info/logging", mparams));
- @SuppressWarnings({"unchecked"})
- List<Map<String, Object>> loggers = (List<Map<String, Object>>) rsp._get("loggers", null);
-
- // check log levels
- assertTrue(checkLoggerLevel(loggers, PARENT_LOGGER_NAME, ""));
- assertTrue(checkLoggerLevel(loggers, CLASS_LOGGER_NAME, "DEBUG"));
-
- // update parent logger level
- mparams.set("set", PARENT_LOGGER_NAME + ":TRACE");
- rsp =
- client.request(
- new GenericSolrRequest(SolrRequest.METHOD.GET, "/admin/info/logging", mparams));
+ { // GET
+ @SuppressWarnings({"unchecked"})
+ List<Map<String, Object>> loggers = (List<Map<String, Object>>) rsp._get("loggers", null);
- @SuppressWarnings({"unchecked"})
- List<Map<String, Object>> updatedLoggerLevel =
- (List<Map<String, Object>>) rsp._get("loggers", null);
-
- // check new parent logger level
- assertTrue(checkLoggerLevel(updatedLoggerLevel, PARENT_LOGGER_NAME, "TRACE"));
-
- assertEquals(Level.TRACE, config.getLoggerConfig(PARENT_LOGGER_NAME).getLevel());
- assertEquals(Level.DEBUG, config.getLoggerConfig(CLASS_LOGGER_NAME).getLevel());
-
- // NOTE: LoggingHandler doesn't actually "remove" the LoggerConfig, ...
- // evidently so people using the UI can see that it was explicitly turned "OFF" ?
- mparams.set("set", PARENT_LOGGER_NAME + ":null");
- rsp =
- client.request(
- new GenericSolrRequest(SolrRequest.METHOD.GET, "/admin/info/logging", mparams));
-
- @SuppressWarnings({"unchecked"})
- List<Map<String, Object>> removedLoggerLevel =
- (List<Map<String, Object>>) rsp._get("loggers", null);
+ // check expected log levels returned by handler
+ assertLoggerLevel(loggers, PARENT_LOGGER_NAME, "DEBUG", true);
+ for (String logger : Arrays.asList(A_LOGGER_NAME, B_LOGGER_NAME, BX_LOGGER_NAME)) {
+ assertLoggerLevel(loggers, logger, "DEBUG", false);
+ }
+ }
- assertTrue(checkLoggerLevel(removedLoggerLevel, PARENT_LOGGER_NAME, "OFF"));
+ { // SET
+
+ // update B's logger level
+ mparams.set("set", B_LOGGER_NAME + ":TRACE");
+ rsp =
+ client.request(
+ new GenericSolrRequest(SolrRequest.METHOD.GET, "/admin/info/logging", mparams));
+ @SuppressWarnings({"unchecked"})
+ List<Map<String, Object>> updatedLoggerLevel =
+ (List<Map<String, Object>>) rsp._get("loggers", null);
+
+ // check new log levels returned by handler
+ assertLoggerLevel(updatedLoggerLevel, PARENT_LOGGER_NAME, "DEBUG", true);
+ assertLoggerLevel(updatedLoggerLevel, A_LOGGER_NAME, "DEBUG", false);
+ assertLoggerLevel(updatedLoggerLevel, B_LOGGER_NAME, "TRACE", true);
+ assertLoggerLevel(updatedLoggerLevel, BX_LOGGER_NAME, "TRACE", false);
+
+ // check directly with log4j what it's (updated) config has...
+ assertEquals(Level.DEBUG, config.getLoggerConfig(PARENT_LOGGER_NAME).getExplicitLevel());
+ assertEquals(Level.TRACE, config.getLoggerConfig(B_LOGGER_NAME).getExplicitLevel());
+ assertEquals(
+ "Unexpected config for BX ... expected B's config",
+ config.getLoggerConfig(B_LOGGER_NAME),
+ config.getLoggerConfig(BX_LOGGER_NAME));
+ // ...and what it's effective values
+ assertEquals(Level.DEBUG, LogManager.getLogger(PARENT_LOGGER_NAME).getLevel());
+ assertEquals(Level.DEBUG, LogManager.getLogger(A_LOGGER_NAME).getLevel());
+ assertEquals(Level.TRACE, LogManager.getLogger(B_LOGGER_NAME).getLevel());
+ assertEquals(Level.TRACE, LogManager.getLogger(BX_LOGGER_NAME).getLevel());
+ }
- assertEquals(Level.OFF, config.getLoggerConfig(PARENT_LOGGER_NAME).getLevel());
- assertEquals(Level.DEBUG, config.getLoggerConfig(CLASS_LOGGER_NAME).getLevel());
+ { // UNSET
+ final String unset = random().nextBoolean() ? "null" : "unset";
+ mparams.set("set", B_LOGGER_NAME + ":" + unset);
+ rsp =
+ client.request(
+ new GenericSolrRequest(SolrRequest.METHOD.GET, "/admin/info/logging", mparams));
+
+ @SuppressWarnings({"unchecked"})
+ List<Map<String, Object>> removedLoggerLevel =
+ (List<Map<String, Object>>) rsp._get("loggers", null);
+
+ // check new log levels returned by handler
+ assertLoggerLevel(removedLoggerLevel, PARENT_LOGGER_NAME, "DEBUG", true);
+ assertLoggerLevel(removedLoggerLevel, A_LOGGER_NAME, "DEBUG", false);
+ assertLoggerLevel(removedLoggerLevel, B_LOGGER_NAME, "DEBUG", false);
+ assertLoggerLevel(removedLoggerLevel, BX_LOGGER_NAME, "DEBUG", false);
+
+ // check directly with log4j what it's (updated) config has...
+ //
+ // NOTE: LoggingHandler must not actually "remove" the LoggerConfig for B on 'unset'
+ // (it might have already been defined in log4j's original config for some other reason,
+ // w/o an explicit level -- Example: Filtering)
+ //
+ // The LoggerConfig must still exist, but with a 'null' (explicit) level
+ // (so it's inheriting level from parent)
+ assertEquals(Level.DEBUG, config.getLoggerConfig(PARENT_LOGGER_NAME).getLevel());
+ assertEquals(null, config.getLoggerConfig(B_LOGGER_NAME).getExplicitLevel()); // explicit
+ assertEquals(Level.DEBUG, config.getLoggerConfig(B_LOGGER_NAME).getLevel()); // inherited
+ assertEquals(
+ "Unexpected config for BX ... expected B's config",
+ config.getLoggerConfig(B_LOGGER_NAME),
+ config.getLoggerConfig(BX_LOGGER_NAME));
+ // ...and what it's effective values
+ assertEquals(Level.DEBUG, LogManager.getLogger(PARENT_LOGGER_NAME).getLevel());
+ assertEquals(Level.DEBUG, LogManager.getLogger(A_LOGGER_NAME).getLevel());
+ assertEquals(Level.DEBUG, LogManager.getLogger(B_LOGGER_NAME).getLevel());
+ assertEquals(Level.DEBUG, LogManager.getLogger(BX_LOGGER_NAME).getLevel());
+ }
}
- private boolean checkLoggerLevel(
- List<Map<String, Object>> properties, String logger, String level) {
+ private void assertLoggerLevel(
+ List<Map<String, Object>> properties, String logger, String level, boolean isSet) {
+ boolean foundLogger = false;
for (Map<String, Object> property : properties) {
- String loggerProperty = ObjectUtils.firstNonNull(property.get("name"), "").toString();
- String levelProperty = ObjectUtils.firstNonNull(property.get("level"), "").toString();
- if (loggerProperty.equals(logger) && levelProperty.equals(level)) {
- return true;
+ final Object loggerProperty = property.get("name");
+ assertNotNull("Found logger record with null 'name'", loggerProperty);
+ if (logger.equals(loggerProperty)) {
+ assertFalse("Duplicate Logger: " + logger, foundLogger);
+ foundLogger = true;
+ assertEquals("Level: " + logger, level, property.get("level"));
+ assertEquals("isSet: " + logger, isSet, property.get("set"));
}
}
- return false;
+ assertTrue("Logger Missing: " + logger, foundLogger);
}
}