Repository: logging-log4j2 Updated Branches: refs/heads/master b886eca88 -> ec11699a3
LOG4J2-1748 and LOG4J2-1780 Remove ExecutorServices from LoggerContext Project: http://git-wip-us.apache.org/repos/asf/logging-log4j2/repo Commit: http://git-wip-us.apache.org/repos/asf/logging-log4j2/commit/162a5e33 Tree: http://git-wip-us.apache.org/repos/asf/logging-log4j2/tree/162a5e33 Diff: http://git-wip-us.apache.org/repos/asf/logging-log4j2/diff/162a5e33 Branch: refs/heads/master Commit: 162a5e33ace3f1b4adf0726502083d0efb1e799a Parents: a6f9d12 Author: Mikael Ståldal <mikael.stal...@magine.com> Authored: Thu Jan 12 12:14:18 2017 +0100 Committer: Mikael Ståldal <mikael.stal...@magine.com> Committed: Thu Jan 12 12:32:00 2017 +0100 ---------------------------------------------------------------------- .../logging/log4j/core/LoggerContext.java | 97 +------------------- .../core/appender/mom/kafka/KafkaManager.java | 11 ++- .../appender/rolling/RollingFileManager.java | 2 +- .../core/config/AbstractConfiguration.java | 4 +- .../core/config/ConfigurationScheduler.java | 51 +++++++--- .../core/config/ConfiguratonFileWatcher.java | 7 +- .../logging/log4j/core/config/Configurator.java | 4 +- .../log4j/core/util/Log4jThreadFactory.java | 11 --- .../nosql/appender/cassandra/CassandraRule.java | 2 +- src/site/xdoc/manual/configuration.xml.vm | 4 +- 10 files changed, 59 insertions(+), 134 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/162a5e33/log4j-core/src/main/java/org/apache/logging/log4j/core/LoggerContext.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/LoggerContext.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/LoggerContext.java index 2322376..9797cc6 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/LoggerContext.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/LoggerContext.java @@ -26,13 +26,6 @@ import java.util.Collection; import java.util.Objects; import java.util.concurrent.ConcurrentMap; import java.util.concurrent.CopyOnWriteArrayList; -import java.util.concurrent.ExecutorService; -import java.util.concurrent.Executors; -import java.util.concurrent.Future; -import java.util.concurrent.RejectedExecutionException; -import java.util.concurrent.SynchronousQueue; -import java.util.concurrent.ThreadFactory; -import java.util.concurrent.ThreadPoolExecutor; import java.util.concurrent.TimeUnit; import java.util.concurrent.locks.Lock; import java.util.concurrent.locks.ReentrantLock; @@ -49,7 +42,6 @@ import org.apache.logging.log4j.core.impl.Log4jLogEvent; import org.apache.logging.log4j.core.jmx.Server; import org.apache.logging.log4j.core.util.Cancellable; import org.apache.logging.log4j.core.util.ExecutorServices; -import org.apache.logging.log4j.core.util.Log4jThreadFactory; import org.apache.logging.log4j.core.util.NetUtils; import org.apache.logging.log4j.core.util.ShutdownCallbackRegistry; import org.apache.logging.log4j.message.MessageFactory; @@ -92,8 +84,6 @@ public class LoggerContext extends AbstractLifeCycle * reference is updated. */ private volatile Configuration configuration = new DefaultConfiguration(); - private ExecutorService executorService; - private ExecutorService executorServiceDeamons; private Object externalContext; private String contextName; private volatile URI configLocation; @@ -326,8 +316,8 @@ public class LoggerContext extends AbstractLifeCycle * Log4j can start threads to perform certain actions like file rollovers, calling this method with a positive timeout will * block until the rollover thread is done. * - * @param timeout the maximum time to wait, or 0 which mean that each apppender uses its default timeout, and don't wait for background - tasks + * @param timeout the maximum time to wait, or 0 which mean that each apppender uses its default timeout, and wait for + * background tasks for one second * @param timeUnit * the time unit of the timeout argument * @return {@code true} if the logger context terminated and {@code false} if the timeout elapsed before @@ -338,8 +328,6 @@ public class LoggerContext extends AbstractLifeCycle public boolean stop(final long timeout, final TimeUnit timeUnit) { LOGGER.debug("Stopping LoggerContext[name={}, {}]...", getName(), this); configLock.lock(); - final boolean shutdownEs; - final boolean shutdownEsd; try { if (this.isStopped()) { return true; @@ -366,16 +354,12 @@ public class LoggerContext extends AbstractLifeCycle } externalContext = null; LogManager.getFactory().removeContext(this); - final String source = "LoggerContext \'" + getName() + "\'"; - shutdownEs = ExecutorServices.shutdown(executorService, timeout, timeUnit, source); - // Do not wait for daemon threads - shutdownEsd = ExecutorServices.shutdown(executorServiceDeamons, 0, timeUnit, source); } finally { configLock.unlock(); this.setStopped(); } LOGGER.debug("Stopped LoggerContext[name={}, {}]...", getName(), this); - return shutdownEs && shutdownEsd; + return true; } /** @@ -548,9 +532,6 @@ public class LoggerContext extends AbstractLifeCycle try { final Configuration prev = this.configuration; config.addListener(this); - executorService = createNonDaemonThreadPool(Log4jThreadFactory.createThreadFactory(contextName)); - // Daemon threads do not prevent the application from shutting down so the default keep-alive time is fine. - executorServiceDeamons = Executors.newCachedThreadPool(Log4jThreadFactory.createDaemonThreadFactory(contextName)); final ConcurrentMap<String, String> map = config.getComponent(Configuration.CONTEXT_PROPERTIES); @@ -586,30 +567,6 @@ public class LoggerContext extends AbstractLifeCycle } } - /** - * Returns an {@code ExecutorService} whose keep-alive time is one second by default, unless another - * value is specified for system property {@code log4j.nondaemon.threads.keepAliveSeconds}. - * <p> - * LOG4J2-1748: ThreadPool for non-daemon threads should use a short keep-alive time to prevent - * applications from being able to shut down promptly after a rollover. - * </p> - * - * @param threadFactory thread factory to use - * @return a new cached thread pool - */ - private ExecutorService createNonDaemonThreadPool(final ThreadFactory threadFactory) { - final String PROP = "log4j.nondaemon.threads.keepAliveSeconds"; - final int keepAliveTimeSeconds = PropertiesUtil.getProperties().getIntegerProperty(PROP, 1); - return createThreadPool(threadFactory, keepAliveTimeSeconds); - } - - private ExecutorService createThreadPool(final ThreadFactory threadFactory, final int keepAliveTimeSeconds) { - return new ThreadPoolExecutor(0, Integer.MAX_VALUE, - keepAliveTimeSeconds, TimeUnit.SECONDS, - new SynchronousQueue<Runnable>(), - threadFactory); - } - private void firePropertyChangeEvent(final PropertyChangeEvent event) { for (final PropertyChangeListener listener : propertyChangeListeners) { listener.propertyChange(event); @@ -719,52 +676,4 @@ public class LoggerContext extends AbstractLifeCycle return new Logger(ctx, name, messageFactory); } - /** - * Gets the executor service to submit normal tasks. - * - * @return the ExecutorService to submit normal tasks. - */ - public ExecutorService getExecutorService() { - return executorService; - } - - /** - * Gets the executor service to submit daemon tasks. - * - * @return the ExecutorService to submit normal daemon tasks. - */ - public ExecutorService getExecutorServiceDeamons() { - return executorServiceDeamons; - } - - /** - * Submits a Runnable task for normal execution and returns a Future representing that task. The Future's - * {@code get} method will return {@code null} upon <em>successful</em> completion. - * - * @param task the task to submit - * @return a Future representing pending completion of the task - * @throws RejectedExecutionException if the task cannot be - * scheduled for execution - * @throws NullPointerException if the task is null - */ - public Future<?> submit(final Runnable task) { - return executorService.submit(task); - } - - /** - * Submits a Runnable task for daemon execution and returns a Future representing that task. The Future's - * {@code get} method will return {@code null} upon <em>successful</em> completion. - * - * @param task - * the task to submit - * @return a Future representing pending completion of the task - * @throws RejectedExecutionException - * if the task cannot be scheduled for execution - * @throws NullPointerException - * if the task is null - */ - public Future<?> submitDaemon(final Runnable task) { - return executorServiceDeamons.submit(task); - } - } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/162a5e33/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/mom/kafka/KafkaManager.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/mom/kafka/KafkaManager.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/mom/kafka/KafkaManager.java index 616191c..b293f2a 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/mom/kafka/KafkaManager.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/mom/kafka/KafkaManager.java @@ -30,6 +30,7 @@ import org.apache.kafka.clients.producer.RecordMetadata; import org.apache.logging.log4j.core.LoggerContext; import org.apache.logging.log4j.core.appender.AbstractManager; import org.apache.logging.log4j.core.config.Property; +import org.apache.logging.log4j.core.util.Log4jThread; public class KafkaManager extends AbstractManager { @@ -73,17 +74,19 @@ public class KafkaManager extends AbstractManager { private void closeProducer(final long timeout, final TimeUnit timeUnit) { if (producer != null) { // This thread is a workaround for this Kafka issue: https://issues.apache.org/jira/browse/KAFKA-1660 - final Runnable task = new Runnable() { + final Thread closeThread = new Log4jThread(new Runnable() { @Override public void run() { if (producer != null) { producer.close(); } } - }; + }, "KafkaManager-CloseThread"); + closeThread.setDaemon(true); // avoid blocking JVM shutdown + closeThread.start(); try { - getLoggerContext().submitDaemon(task).get(timeout, timeUnit); - } catch (InterruptedException | ExecutionException | TimeoutException e) { + closeThread.join(timeUnit.toMillis(timeout)); + } catch (final InterruptedException ignore) { // ignore } } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/162a5e33/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java index 10cb79e..e9c7790 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/RollingFileManager.java @@ -296,7 +296,7 @@ public class RollingFileManager extends FileManager { if (success && descriptor.getAsynchronous() != null) { LOGGER.debug("RollingFileManager executing async {}", descriptor.getAsynchronous()); - future = LoggerContext.getContext(false).submit(new AsyncAction(descriptor.getAsynchronous(), this)); + future = LoggerContext.getContext(false).getConfiguration().getScheduler().submit(new AsyncAction(descriptor.getAsynchronous(), this)); } return true; } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/162a5e33/log4j-core/src/main/java/org/apache/logging/log4j/core/config/AbstractConfiguration.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/AbstractConfiguration.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/AbstractConfiguration.java index 3a6a58e..e5e149e 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/AbstractConfiguration.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/AbstractConfiguration.java @@ -373,9 +373,9 @@ public abstract class AbstractConfiguration extends AbstractFilterable implement root.clearAppenders(); if (watchManager.isStarted()) { - watchManager.stop(); + watchManager.stop(timeout, timeUnit); } - configurationScheduler.stop(); + configurationScheduler.stop(timeout, timeUnit); if (advertiser != null && advertisement != null) { advertiser.unadvertise(advertisement); http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/162a5e33/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationScheduler.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationScheduler.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationScheduler.java index 6c639f2..4af83a5 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationScheduler.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfigurationScheduler.java @@ -17,9 +17,9 @@ package org.apache.logging.log4j.core.config; import java.util.Date; -import java.util.List; import java.util.Queue; import java.util.concurrent.Callable; +import java.util.concurrent.Future; import java.util.concurrent.ScheduledExecutorService; import java.util.concurrent.ScheduledFuture; import java.util.concurrent.ScheduledThreadPoolExecutor; @@ -39,6 +39,7 @@ public class ConfigurationScheduler extends AbstractLifeCycle { private static final Logger LOGGER = StatusLogger.getLogger(); private static final String SIMPLE_NAME = "Log4j2 " + ConfigurationScheduler.class.getSimpleName(); private static final int MAX_SCHEDULED_ITEMS = 5; + private static final long DEFAULT_SHUTDOWN_TIMEOUT_MILLIS = 1000; private ScheduledExecutorService executorService; private int scheduledItems = 0; @@ -52,14 +53,17 @@ public class ConfigurationScheduler extends AbstractLifeCycle { public boolean stop(final long timeout, final TimeUnit timeUnit) { setStopping(); if (isExecutorServiceSet()) { + long timeoutToUse = timeout > 0 ? timeout : DEFAULT_SHUTDOWN_TIMEOUT_MILLIS; + TimeUnit timeUnitToUse = timeout > 0 ? timeUnit : TimeUnit.MILLISECONDS; + LOGGER.debug("{} shutting down threads in {}", SIMPLE_NAME, getExecutorService()); executorService.shutdown(); try { - executorService.awaitTermination(timeout, timeUnit); + executorService.awaitTermination(timeoutToUse, timeUnitToUse); } catch (InterruptedException ie) { executorService.shutdownNow(); try { - executorService.awaitTermination(timeout, timeUnit); + executorService.awaitTermination(timeoutToUse, timeUnitToUse); } catch (InterruptedException inner) { LOGGER.warn("ConfigurationScheduler stopped but some scheduled services may not have completed."); } @@ -95,6 +99,28 @@ public class ConfigurationScheduler extends AbstractLifeCycle { } /** + * Creates and executes a Future that becomes enabled immediately. + * @param <V> The result type returned by this Future + * @param callable the function to execute. + * @return a Future that can be used to extract result or cancel. + * + */ + public <V> Future<V> submit(final Callable<V> callable) { + return getExecutorService().submit(callable); + } + + /** + * Creates and executes a Future that becomes enabled immediately. + * @param runnable the function to execute. + * @return a Future representing pending completion of the task and whose get() method will return null + * upon completion. + */ + public Future<?> submit(final Runnable runnable) { + return getExecutorService().submit(runnable); + } + + + /** * Creates and executes a ScheduledFuture that becomes enabled after the given delay. * @param <V> The result type returned by this Future * @param callable the function to execute. @@ -183,18 +209,13 @@ public class ConfigurationScheduler extends AbstractLifeCycle { private ScheduledExecutorService getExecutorService() { if (executorService == null) { - if (scheduledItems > 0) { - LOGGER.debug("{} starting {} threads", SIMPLE_NAME, scheduledItems); - scheduledItems = Math.min(scheduledItems, MAX_SCHEDULED_ITEMS); - ScheduledThreadPoolExecutor executor = new ScheduledThreadPoolExecutor(scheduledItems, - Log4jThreadFactory.createDaemonThreadFactory("Scheduled")); - executor.setContinueExistingPeriodicTasksAfterShutdownPolicy(false); - executor.setExecuteExistingDelayedTasksAfterShutdownPolicy(false); - this.executorService = executor; - - } else { - LOGGER.debug("{}: No scheduled items", SIMPLE_NAME); - } + LOGGER.debug("{} starting {} threads", SIMPLE_NAME, scheduledItems); + scheduledItems = Math.min(scheduledItems, MAX_SCHEDULED_ITEMS); + ScheduledThreadPoolExecutor executor = new ScheduledThreadPoolExecutor(scheduledItems + 1, + Log4jThreadFactory.createDaemonThreadFactory("Scheduled")); + executor.setContinueExistingPeriodicTasksAfterShutdownPolicy(false); + executor.setExecuteExistingDelayedTasksAfterShutdownPolicy(false); + this.executorService = executor; } return executorService; } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/162a5e33/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfiguratonFileWatcher.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfiguratonFileWatcher.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfiguratonFileWatcher.java index b32f9d0..38491f2 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfiguratonFileWatcher.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/ConfiguratonFileWatcher.java @@ -19,8 +19,8 @@ package org.apache.logging.log4j.core.config; import java.io.File; import java.util.List; -import org.apache.logging.log4j.core.LoggerContext; import org.apache.logging.log4j.core.util.FileWatcher; +import org.apache.logging.log4j.core.util.Log4jThreadFactory; /** * Watcher for configuration files. Causes a reconfiguration when a file changes. @@ -29,10 +29,12 @@ public class ConfiguratonFileWatcher implements FileWatcher { private final Reconfigurable reconfigurable; private final List<ConfigurationListener> configurationListeners; + private final Log4jThreadFactory threadFactory; public ConfiguratonFileWatcher(final Reconfigurable reconfigurable, final List<ConfigurationListener> configurationListeners) { this.reconfigurable = reconfigurable; this.configurationListeners = configurationListeners; + this.threadFactory = Log4jThreadFactory.createDaemonThreadFactory("ConfiguratonFileWatcher"); } public List<ConfigurationListener> getListeners() { @@ -43,7 +45,8 @@ public class ConfiguratonFileWatcher implements FileWatcher { @Override public void fileModified(final File file) { for (final ConfigurationListener configurationListener : configurationListeners) { - LoggerContext.getContext(false).submitDaemon(new ReconfigurationRunnable(configurationListener, reconfigurable)); + final Thread thread = threadFactory.newThread(new ReconfigurationRunnable(configurationListener, reconfigurable)); + thread.start(); } } http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/162a5e33/log4j-core/src/main/java/org/apache/logging/log4j/core/config/Configurator.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/Configurator.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/Configurator.java index 28dd85f..63d8a81 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/config/Configurator.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/config/Configurator.java @@ -331,8 +331,8 @@ public final class Configurator { /** * Shuts down the given logger context. This request does not wait for Log4j tasks to complete. * <p> - * Log4j starts threads to perform certain actions like file rollovers; calling this method will not wait until the - * rollover thread is done. When this method returns, these tasks' status are undefined, the tasks may be done or + * Log4j starts threads to perform certain actions like file rollovers; calling this method will wait up to one second + * until the rollover thread is done. When this method returns, these tasks' status are undefined, the tasks may be done or * not. * </p> * http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/162a5e33/log4j-core/src/main/java/org/apache/logging/log4j/core/util/Log4jThreadFactory.java ---------------------------------------------------------------------- diff --git a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/Log4jThreadFactory.java b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/Log4jThreadFactory.java index 3715243..2318feb 100644 --- a/log4j-core/src/main/java/org/apache/logging/log4j/core/util/Log4jThreadFactory.java +++ b/log4j-core/src/main/java/org/apache/logging/log4j/core/util/Log4jThreadFactory.java @@ -40,17 +40,6 @@ public class Log4jThreadFactory implements ThreadFactory { return new Log4jThreadFactory(threadFactoryName, true, Thread.NORM_PRIORITY); } - /** - * Creates a new thread factory. - * - * @param threadFactoryName - * The thread factory name. - * @return a new daemon thread factory. - */ - public static Log4jThreadFactory createThreadFactory(final String threadFactoryName) { - return new Log4jThreadFactory(threadFactoryName, false, Thread.NORM_PRIORITY); - } - private static final AtomicInteger FACTORY_NUMBER = new AtomicInteger(1); private static final AtomicInteger THREAD_NUMBER = new AtomicInteger(1); private final boolean daemon; http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/162a5e33/log4j-nosql/src/test/java/org/apache/logging/log4j/nosql/appender/cassandra/CassandraRule.java ---------------------------------------------------------------------- diff --git a/log4j-nosql/src/test/java/org/apache/logging/log4j/nosql/appender/cassandra/CassandraRule.java b/log4j-nosql/src/test/java/org/apache/logging/log4j/nosql/appender/cassandra/CassandraRule.java index bec97ea..900f794 100644 --- a/log4j-nosql/src/test/java/org/apache/logging/log4j/nosql/appender/cassandra/CassandraRule.java +++ b/log4j-nosql/src/test/java/org/apache/logging/log4j/nosql/appender/cassandra/CassandraRule.java @@ -37,7 +37,7 @@ import org.junit.rules.ExternalResource; */ public class CassandraRule extends ExternalResource { - private static final ThreadFactory THREAD_FACTORY = Log4jThreadFactory.createThreadFactory("Cassandra"); + private static final ThreadFactory THREAD_FACTORY = new Log4jThreadFactory("Cassandra", false, Thread.NORM_PRIORITY); private final CountDownLatch latch = new CountDownLatch(1); private final Cancellable embeddedCassandra = new EmbeddedCassandra(latch); http://git-wip-us.apache.org/repos/asf/logging-log4j2/blob/162a5e33/src/site/xdoc/manual/configuration.xml.vm ---------------------------------------------------------------------- diff --git a/src/site/xdoc/manual/configuration.xml.vm b/src/site/xdoc/manual/configuration.xml.vm index ec73bac..3075839 100644 --- a/src/site/xdoc/manual/configuration.xml.vm +++ b/src/site/xdoc/manual/configuration.xml.vm @@ -410,8 +410,8 @@ public class Bar { <tr> <td>shutdownTimeout</td> <td>Specifies how many milliseconds appenders and background tasks will get to shutdown when the JVM shuts - down. Default is zero which mean that each appender uses its default timeout, and don't wait for background - tasks. Not all appenders will honor this, it is a hint and not an absolute guarantee that the shutdown + down. Default is zero which mean that each appender uses its default timeout, and wait for background + tasks for one second. Not all appenders will honor this, it is a hint and not an absolute guarantee that the shutdown procedure will not take longer. Setting this too low increase the risk of losing outstanding log events not yet written to the final destination. See <a class="javadoc" href="../log4j-core/target/site/apidocs/org/apache/logging/log4j/core/LoggerContext.html#stop(long, java.util.concurrent.TimeUnit)">LoggerContext.stop(long, java.util.concurrent.TimeUnit)</a>.
