From 9d62c13aad92daffa6af483306af35fc5609d89d Mon Sep 17 00:00:00 2001 From: Jungtaek Lim Date: Wed, 30 Aug 2017 22:59:13 +0900 Subject: [PATCH] STORM-2443 Fix issues on changing log level * Addressed below issues * Nimbus throws error when changing log level on UI topology page * Log configs in worker are removed even they're not timed out and never reset * The unit of epoch between backend and frontend are different * second in backend, millisecond in frontend * millisecond is right so fixed it --- .../storm/daemon/worker/LogConfigManager.java | 13 +++--- .../daemon/worker/LogConfigManagerTest.java | 42 +++++++++++++++++++ .../apache/storm/daemon/nimbus/Nimbus.java | 13 +++--- 3 files changed, 58 insertions(+), 10 deletions(-) diff --git a/storm-client/src/jvm/org/apache/storm/daemon/worker/LogConfigManager.java b/storm-client/src/jvm/org/apache/storm/daemon/worker/LogConfigManager.java index 00fccf9a301..c900580add2 100644 --- a/storm-client/src/jvm/org/apache/storm/daemon/worker/LogConfigManager.java +++ b/storm-client/src/jvm/org/apache/storm/daemon/worker/LogConfigManager.java @@ -111,6 +111,9 @@ public void processLogConfigChange(LogConfig logConfig) { // also called from processLogConfigChange public void resetLogLevels() { TreeMap latestLogLevelMap = latestLogConfig.get(); + + LOG.debug("Resetting log levels: Latest log config is {}", latestLogLevelMap); + LoggerContext loggerContext = (LoggerContext) LogManager.getContext(false); for (String loggerName : latestLogLevelMap.descendingKeySet()) { @@ -120,12 +123,12 @@ public void resetLogLevels() { if (timeout < Time.currentTimeMillis()) { LOG.info("{}: Resetting level to {}", loggerName, resetLogLevel); setLoggerLevel(loggerContext, loggerName, resetLogLevel); + latestLogConfig.getAndUpdate(input -> { + TreeMap result = new TreeMap<>(input); + result.remove(loggerName); + return result; + }); } - latestLogConfig.getAndUpdate(input -> { - TreeMap result = new TreeMap<>(input); - result.remove(loggerName); - return result; - }); } loggerContext.updateLoggers(); } diff --git a/storm-client/test/jvm/org/apache/storm/daemon/worker/LogConfigManagerTest.java b/storm-client/test/jvm/org/apache/storm/daemon/worker/LogConfigManagerTest.java index 95491a44f93..e8259e0a429 100644 --- a/storm-client/test/jvm/org/apache/storm/daemon/worker/LogConfigManagerTest.java +++ b/storm-client/test/jvm/org/apache/storm/daemon/worker/LogConfigManagerTest.java @@ -20,6 +20,7 @@ import static org.junit.Assert.*; import static org.mockito.Mockito.*; +import java.util.Collections; import java.util.TreeMap; import java.util.concurrent.atomic.AtomicReference; @@ -132,6 +133,47 @@ public void testLogResetResetsRootLoggerIfSet() { verify(underTest).setLoggerLevel(anyObject(), eq(LogManager.ROOT_LOGGER_NAME), eq("WARN")); } } + + @Test + public void testLogResetProperlyResetLogLevelAfterTimeout() throws InterruptedException { + try (SimulatedTime t = new SimulatedTime()){ + long inThirtySeconds = Time.currentTimeMillis() + 30_000; + TreeMap config = new TreeMap<>(); + config.put(LogManager.ROOT_LOGGER_NAME, ll("DEBUG", "WARN", inThirtySeconds)); + AtomicReference> atomConf = new AtomicReference<>(config); + + LogConfigManager underTest = spy(new LogConfigManagerUnderTest(atomConf)); + + TreeMap expected = new TreeMap<>(); + LogLevel logLevel = new LogLevel(LogLevelAction.UPDATE); + logLevel.set_target_log_level("DEBUG"); + logLevel.set_reset_log_level("WARN"); + logLevel.set_reset_log_level_timeout_epoch(30_000); + expected.put(LogManager.ROOT_LOGGER_NAME, logLevel); + + underTest.resetLogLevels(); + assertEquals(expected, atomConf.get()); + verify(underTest, never()).setLoggerLevel(anyObject(), eq(LogManager.ROOT_LOGGER_NAME), anyString()); + + // 11 seconds passed by, not timing out + Time.advanceTimeSecs(11); + underTest.resetLogLevels(); + assertEquals(expected, atomConf.get()); + verify(underTest, never()).setLoggerLevel(anyObject(), eq(LogManager.ROOT_LOGGER_NAME), anyString()); + + // 22 seconds passed by, still not timing out + Time.advanceTimeSecs(11); + underTest.resetLogLevels(); + assertEquals(expected, atomConf.get()); + verify(underTest, never()).setLoggerLevel(anyObject(), eq(LogManager.ROOT_LOGGER_NAME), anyString()); + + // 33 seconds passed by, timed out + Time.advanceTimeSecs(11); + underTest.resetLogLevels(); + assertEquals(new TreeMap<>(), atomConf.get()); + verify(underTest).setLoggerLevel(anyObject(), eq(LogManager.ROOT_LOGGER_NAME), eq("WARN")); + } + } @Test public void testLogResetsNamedLoggersWithPastTimeout() { diff --git a/storm-server/src/main/java/org/apache/storm/daemon/nimbus/Nimbus.java b/storm-server/src/main/java/org/apache/storm/daemon/nimbus/Nimbus.java index fb2c3e15504..d702b478fbb 100644 --- a/storm-server/src/main/java/org/apache/storm/daemon/nimbus/Nimbus.java +++ b/storm-server/src/main/java/org/apache/storm/daemon/nimbus/Nimbus.java @@ -903,7 +903,7 @@ private static void validateTopologySize(Map topoConf, Map 0) { - level.set_reset_log_level_timeout_epoch(Time.currentTimeSecs() + timeoutSecs); + level.set_reset_log_level_timeout_epoch(Time.currentTimeMillis() + Time.secsToMillis(timeoutSecs)); } else { level.unset_reset_log_level_timeout_epoch(); } @@ -2752,11 +2752,14 @@ public void setLogConfig(String topoId, LogConfig config) throws TException { if (mergedLogConfig == null) { mergedLogConfig = new LogConfig(); } - Map namedLoggers = mergedLogConfig.get_named_logger_level(); - for (LogLevel level: namedLoggers.values()) { - level.set_action(LogLevelAction.UNCHANGED); + + if (mergedLogConfig.is_set_named_logger_level()) { + Map namedLoggers = mergedLogConfig.get_named_logger_level(); + for (LogLevel level: namedLoggers.values()) { + level.set_action(LogLevelAction.UNCHANGED); + } } - + if (config.is_set_named_logger_level()) { for (Entry entry: config.get_named_logger_level().entrySet()) { LogLevel logConfig = entry.getValue();