From c33ff1c745def3844c5f78007999a2bbdf676ba1 Mon Sep 17 00:00:00 2001 From: Frank Chen Date: Mon, 16 May 2022 17:37:21 +0800 Subject: [PATCH] Enforce console logging for peon process (#12067) Currently all Druid processes share the same log4j2 configuration file located in _common directory. Since peon processes are spawned by middle manager process, they derivate the environment variables from the middle manager. These variables include those in the log4j2.xml controlling to which file the logger writes the log. But current task logging mechanism requires the peon processes to output the log to console so that the middle manager can redirect the console output to a file and upload this file to task log storage. So, this PR imposes this requirement to peon processes, whatever the configuration is in the shared log4j2.xml, peon processes always write the log to console. --- docs/configuration/logging.md | 16 +- ...oggingEnforcementConfigurationFactory.java | 152 ++++++++++ .../indexing/overlord/ForkingTaskRunner.java | 2 + .../ConsoleLoggingEnforcementTest.java | 262 ++++++++++++++++++ website/.spelling | 1 + 5 files changed, 431 insertions(+), 2 deletions(-) create mode 100644 indexing-service/src/main/java/org/apache/druid/indexing/common/tasklogs/ConsoleLoggingEnforcementConfigurationFactory.java create mode 100644 indexing-service/src/test/java/org/apache/druid/indexing/common/tasklogs/ConsoleLoggingEnforcementTest.java diff --git a/docs/configuration/logging.md b/docs/configuration/logging.md index e0fc63a9ad1..bcb70225f6d 100644 --- a/docs/configuration/logging.md +++ b/docs/configuration/logging.md @@ -23,9 +23,12 @@ title: "Logging" --> -Apache Druid processes will emit logs that are useful for debugging to the console. Druid processes also emit periodic metrics about their state. For more about metrics, see [Configuration](../configuration/index.md#enabling-metrics). Metric logs are printed to the console by default, and can be disabled with `-Ddruid.emitter.logging.logLevel=debug`. +Apache Druid processes will emit logs that are useful for debugging to log files. +These processes also emit periodic [metrics](../configuration/index.md#enabling-metrics) about their state. +Metric info logs can be disabled with `-Ddruid.emitter.logging.logLevel=debug`. -Druid uses [log4j2](http://logging.apache.org/log4j/2.x/) for logging. The default configuration file log4j2.xml ships with Druid under conf/druid/{config}/_common/log4j2.xml . +Druid uses [log4j2](http://logging.apache.org/log4j/2.x/) for logging. +The default configuration file log4j2.xml ships with Druid under conf/druid/{config}/_common/log4j2.xml . By default, Druid uses `RollingRandomAccessFile` for rollover daily, and keeps log files up to 7 days. If that's not suitable in your case, you could modify the log4j2.xml to meet your need. @@ -67,6 +70,15 @@ An example log4j2.xml file is shown below: ``` +> NOTE: +> Although the log4j configuration file is shared with Druid's peon processes, +> the appenders in this file DO NOT take effect for peon processes for they always output logs to console. +> And middle managers are responsible to redirect the console output to task log files. +> +> But the logging levels settings take effect for these peon processes +> which means you can still configure loggers at different logging level for peon processes in this file. +> + ## How to change log directory By default, Druid outputs the logs to a directory `log` under the directory where Druid is launched from. For example, if Druid is started from its `bin` directory, there will be a subdirectory `log` generated under `bin` directory to hold the log files. diff --git a/indexing-service/src/main/java/org/apache/druid/indexing/common/tasklogs/ConsoleLoggingEnforcementConfigurationFactory.java b/indexing-service/src/main/java/org/apache/druid/indexing/common/tasklogs/ConsoleLoggingEnforcementConfigurationFactory.java new file mode 100644 index 00000000000..1874963f3ce --- /dev/null +++ b/indexing-service/src/main/java/org/apache/druid/indexing/common/tasklogs/ConsoleLoggingEnforcementConfigurationFactory.java @@ -0,0 +1,152 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +package org.apache.druid.indexing.common.tasklogs; + +import org.apache.logging.log4j.Level; +import org.apache.logging.log4j.core.Appender; +import org.apache.logging.log4j.core.Filter; +import org.apache.logging.log4j.core.LoggerContext; +import org.apache.logging.log4j.core.appender.ConsoleAppender; +import org.apache.logging.log4j.core.config.AppenderRef; +import org.apache.logging.log4j.core.config.Configuration; +import org.apache.logging.log4j.core.config.ConfigurationFactory; +import org.apache.logging.log4j.core.config.ConfigurationSource; +import org.apache.logging.log4j.core.config.LoggerConfig; +import org.apache.logging.log4j.core.config.xml.XmlConfiguration; +import org.apache.logging.log4j.core.layout.PatternLayout; + +import javax.annotation.Nullable; +import java.util.ArrayList; +import java.util.List; +import java.util.Map; +import java.util.stream.Collectors; + +/** + * This class enforces console logging based on a user defined configuration. + *

+ * For all loggers, this class ensure that only {@link ConsoleAppender} is applied for each of them. + *

+ * The reason why this configuration is still based on a user's configuration is that + * user can still configure different logging levels for different loggers in that file. + */ +public class ConsoleLoggingEnforcementConfigurationFactory extends ConfigurationFactory +{ + /** + * Valid file extensions for XML files. + */ + public static final String[] SUFFIXES = new String[]{".xml", "*"}; + + @Override + public String[] getSupportedTypes() + { + return SUFFIXES; + } + + @Override + public Configuration getConfiguration(LoggerContext loggerContext, ConfigurationSource source) + { + return new OverrideConfiguration(loggerContext, source); + } + + /** + * override the original configuration source to ensure only console appender is applied + */ + static class OverrideConfiguration extends XmlConfiguration + { + public OverrideConfiguration(final LoggerContext loggerContext, final ConfigurationSource configSource) + { + super(loggerContext, configSource); + } + + @Override + protected void doConfigure() + { + super.doConfigure(); + + Appender consoleAppender = findConsoleAppender(); + if (consoleAppender == null) { + // create a ConsoleAppender with default pattern if no console appender is configured in the configuration file + consoleAppender = ConsoleAppender.newBuilder() + .setName("_Injected_Console_Appender_") + .setLayout(PatternLayout.newBuilder() + .withPattern("%d{ISO8601} %p [%t] %c - %m%n") + .build()) + .build(); + } + + List loggerConfigList = new ArrayList<>(); + loggerConfigList.add(this.getRootLogger()); + loggerConfigList.addAll(this.getLoggers().values()); + + // + // For all logger configuration, check if its appender is ConsoleAppender. + // If not, replace it's appender to ConsoleAppender. + // + for (LoggerConfig logger : loggerConfigList) { + applyConsoleAppender(logger, consoleAppender); + } + } + + @Nullable + private Appender findConsoleAppender() + { + for (Map.Entry entry : this.getAppenders().entrySet()) { + Appender appender = entry.getValue(); + if (appender instanceof ConsoleAppender) { + return appender; + } + } + return null; + } + + /** + * remove all appenders from a logger and append a console appender to it + */ + private void applyConsoleAppender(LoggerConfig logger, Appender consoleAppender) + { + if (logger.getAppenderRefs().size() == 1 + && logger.getAppenderRefs().get(0).getRef().equals(consoleAppender.getName())) { + // this logger has only one appender and its the console appender + return; + } + + Level level = Level.INFO; + Filter filter = null; + + if (!logger.getAppenderRefs().isEmpty()) { + AppenderRef appenderRef = logger.getAppenderRefs().get(0); + + // clear all appenders first + List appendRefs = logger.getAppenderRefs() + .stream() + .map(AppenderRef::getRef) + .collect(Collectors.toList()); + appendRefs.forEach(logger::removeAppender); + + // use the first appender's definition + level = appenderRef.getLevel(); + filter = appenderRef.getFilter(); + } + + // add ConsoleAppender to this logger + logger.addAppender(consoleAppender, level, filter); + } + } +} diff --git a/indexing-service/src/main/java/org/apache/druid/indexing/overlord/ForkingTaskRunner.java b/indexing-service/src/main/java/org/apache/druid/indexing/overlord/ForkingTaskRunner.java index 77c515502d0..ab7de6cf3c8 100644 --- a/indexing-service/src/main/java/org/apache/druid/indexing/overlord/ForkingTaskRunner.java +++ b/indexing-service/src/main/java/org/apache/druid/indexing/overlord/ForkingTaskRunner.java @@ -47,6 +47,7 @@ import org.apache.druid.indexer.TaskLocation; import org.apache.druid.indexer.TaskStatus; import org.apache.druid.indexing.common.config.TaskConfig; import org.apache.druid.indexing.common.task.Task; +import org.apache.druid.indexing.common.tasklogs.ConsoleLoggingEnforcementConfigurationFactory; import org.apache.druid.indexing.common.tasklogs.LogUtils; import org.apache.druid.indexing.overlord.autoscaling.ScalingStats; import org.apache.druid.indexing.overlord.config.ForkingTaskRunnerConfig; @@ -339,6 +340,7 @@ public class ForkingTaskRunner command.add( StringUtils.format("-Ddruid.task.executor.enableTlsPort=%s", node.isEnableTlsPort()) ); + command.add(StringUtils.format("-Dlog4j2.configurationFactory=%s", ConsoleLoggingEnforcementConfigurationFactory.class.getName())); // These are not enabled per default to allow the user to either set or not set them // Users are highly suggested to be set in druid.indexer.runner.javaOpts diff --git a/indexing-service/src/test/java/org/apache/druid/indexing/common/tasklogs/ConsoleLoggingEnforcementTest.java b/indexing-service/src/test/java/org/apache/druid/indexing/common/tasklogs/ConsoleLoggingEnforcementTest.java new file mode 100644 index 00000000000..ea5622074bd --- /dev/null +++ b/indexing-service/src/test/java/org/apache/druid/indexing/common/tasklogs/ConsoleLoggingEnforcementTest.java @@ -0,0 +1,262 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +package org.apache.druid.indexing.common.tasklogs; + +import org.apache.logging.log4j.Level; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.core.Logger; +import org.apache.logging.log4j.core.LoggerContext; +import org.apache.logging.log4j.core.appender.ConsoleAppender; +import org.apache.logging.log4j.core.config.ConfigurationSource; +import org.apache.logging.log4j.core.layout.PatternLayout; +import org.junit.Assert; +import org.junit.Test; + +import java.io.ByteArrayInputStream; +import java.io.IOException; +import java.nio.charset.StandardCharsets; + +public class ConsoleLoggingEnforcementTest +{ + private static final String ROOT = "ROOT"; + + @Test + public void testConsoleConfiguration() throws IOException + { + // the loggers in configuration already uses Console appender + String log4jConfiguration = "\n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + ""; + + LoggerContext context = enforceConsoleLogger(log4jConfiguration); + + // this logger is not defined in configuration, it derivates ROOT logger configuration + assertHasOnlyOneConsoleAppender(getLogger(context, "name_not_in_config"), Level.INFO); + assertHasOnlyOneConsoleAppender(getLogger(context, "org.apache.druid"), Level.DEBUG); + assertHasOnlyOneConsoleAppender(getLogger(context, ROOT), Level.INFO); + + PatternLayout layout = (PatternLayout) getLogger(context, "anything").getAppenders() + .values() + .stream() + .findFirst() + .get() + .getLayout(); + Assert.assertEquals("%m", layout.getConversionPattern()); + } + + @Test + public void testNoConsoleAppender() throws IOException + { + // this logger configuration has no console logger appender, a default one will be created + String log4jConfiguration = "\n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + ""; + + LoggerContext context = enforceConsoleLogger(log4jConfiguration); + + // this logger is not defined in configuration, it derivates ROOT logger configuration + assertHasOnlyOneConsoleAppender(getLogger(context, "name_not_in_config"), Level.INFO); + assertHasOnlyOneConsoleAppender(getLogger(context, ROOT), Level.INFO); + + String defaultPattern = "%d{ISO8601} %p [%t] %c - %m%n"; + PatternLayout layout = (PatternLayout) getLogger(context, "anything").getAppenders() + .values() + .stream() + .findFirst() + .get() + .getLayout(); + Assert.assertEquals(defaultPattern, layout.getConversionPattern()); + } + + @Test + public void testHasConsoleAppenderButNotUsed() throws IOException + { + // this logger has a console appender, but is not referenced by any logger + String log4jConfiguration = "\n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + ""; + + LoggerContext context = enforceConsoleLogger(log4jConfiguration); + + // this logger is not defined in configuration, it derivates ROOT logger configuration + assertHasOnlyOneConsoleAppender(getLogger(context, "name_not_in_config"), Level.INFO); + + assertHasOnlyOneConsoleAppender(getLogger(context, ROOT), Level.INFO); + + // the ConsoleAppender should be exactly the same as it's in the configuration + PatternLayout layout = (PatternLayout) getLogger(context, "anything").getAppenders() + .values() + .stream() + .findFirst() + .get() + .getLayout(); + Assert.assertEquals("%m", layout.getConversionPattern()); + } + + @Test + public void testMultipleAppender() throws IOException + { + // this logger configuration contains multiple appenders and appender refers + String log4jConfiguration = "\n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + ""; + + LoggerContext context = enforceConsoleLogger(log4jConfiguration); + + // this logger is not defined in configuration, it derivates ROOT logger configuration + assertHasOnlyOneConsoleAppender(getLogger(context, "name_not_in_config"), Level.INFO); + + assertHasOnlyOneConsoleAppender(getLogger(context, "org.apache.druid"), Level.DEBUG); + assertHasOnlyOneConsoleAppender(getLogger(context, ROOT), Level.INFO); + + // the ConsoleAppender should be exactly the same as it's in the configuration + PatternLayout layout = (PatternLayout) getLogger(context, "anything").getAppenders() + .values() + .stream() + .findFirst() + .get() + .getLayout(); + Assert.assertEquals("%m", layout.getConversionPattern()); + } + + @Test + public void testEmptyAppender() throws IOException + { + // the ROOT logger has no appender in this configuration + String log4jConfiguration = "\n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + " \n" + + ""; + + LoggerContext context = enforceConsoleLogger(log4jConfiguration); + + // this logger is not defined in configuration, it derivates ROOT logger configuration + assertHasOnlyOneConsoleAppender(getLogger(context, "name_not_in_config"), Level.INFO); + + assertHasOnlyOneConsoleAppender(getLogger(context, "org.apache.druid"), Level.DEBUG); + assertHasOnlyOneConsoleAppender(getLogger(context, ROOT), Level.INFO); + + // the ConsoleAppender should be exactly the same as it's in the configuration + PatternLayout layout = (PatternLayout) getLogger(context, "anything").getAppenders() + .values() + .stream() + .findFirst() + .get() + .getLayout(); + Assert.assertEquals("%m", layout.getConversionPattern()); + } + + private LoggerContext enforceConsoleLogger(String configuration) throws IOException + { + LoggerContext context = new LoggerContext("test"); + ConfigurationSource source = new ConfigurationSource(new ByteArrayInputStream(configuration.getBytes(StandardCharsets.UTF_8))); + + // enforce the console logging for current configuration + context.reconfigure(new ConsoleLoggingEnforcementConfigurationFactory().getConfiguration(context, source)); + return context; + } + + private void assertHasOnlyOneConsoleAppender(Logger logger, Level level) + { + // there's only one appender + Assert.assertEquals(1, logger.getAppenders().size()); + + // and this appender must be ConsoleAppender + Assert.assertEquals(ConsoleAppender.class, logger.getAppenders() + .values() + .stream() + .findFirst() + .get() + .getClass()); + if (level != null) { + Assert.assertEquals(level, logger.getLevel()); + } + } + + private Logger getLogger(LoggerContext context, String name) + { + final String key = ROOT.equals(name) ? LogManager.ROOT_LOGGER_NAME : name; + return context.getLogger(key); + } +} diff --git a/website/.spelling b/website/.spelling index 9d00a3771b6..f9bed1a7292 100644 --- a/website/.spelling +++ b/website/.spelling @@ -571,6 +571,7 @@ IEC 100x - ../docs/configuration/logging.md _common +appenders - ../docs/dependencies/deep-storage.md druid-hdfs-storage druid-s3-extensions