From 3f572479817c85dbbe016f0eb01088702680852a Mon Sep 17 00:00:00 2001 From: Ceki Gulcu Date: Thu, 15 Aug 2024 18:13:13 +0200 Subject: [PATCH] only one shutdown hooks allowed, locks during LoggerContext.stop operation, fixes LOGBACK-1551 Signed-off-by: Ceki Gulcu --- .../ch/qos/logback/classic/LoggerContext.java | 78 +++++++++++------- .../joran/ReconfigureOnChangeTask.java | 6 +- .../joran/SerializedModelConfigurator.java | 7 +- .../ch/qos/logback/classic/Logback1551.java | 81 +++++++++++++++++++ .../logback/classic/LoggerContextTest.java | 30 +++---- .../classic/joran/ChangeDetectedListener.java | 2 +- .../joran/ReconfigurationDoneListener.java | 3 +- .../joran/ReconfigureOnChangeTaskTest.java | 30 +++---- .../classic/spi/ContextListenerTest.java | 29 +++---- .../java/ch/qos/logback/core/Context.java | 10 ++- .../java/ch/qos/logback/core/ContextBase.java | 15 ++-- .../core/joran/GenericXMLConfigurator.java | 16 +++- .../processor/ShutdownHookModelHandler.java | 8 +- .../logback/core/spi/ConfigurationEvent.java | 11 ++- .../ch/qos/logback/core/util/ContextUtil.java | 25 ++++++ ...ntextUtilAddOrReplaceShutdownHookTest.java | 67 +++++++++++++++ 16 files changed, 315 insertions(+), 103 deletions(-) create mode 100644 logback-classic/src/test/java/ch/qos/logback/classic/Logback1551.java create mode 100644 logback-core/src/test/java/ch/qos/logback/core/util/ContextUtilAddOrReplaceShutdownHookTest.java diff --git a/logback-classic/src/main/java/ch/qos/logback/classic/LoggerContext.java b/logback-classic/src/main/java/ch/qos/logback/classic/LoggerContext.java index 8177756892..8faed3ed3c 100755 --- a/logback-classic/src/main/java/ch/qos/logback/classic/LoggerContext.java +++ b/logback-classic/src/main/java/ch/qos/logback/classic/LoggerContext.java @@ -1,13 +1,13 @@ /** * Logback: the reliable, generic, fast and flexible logging framework. * Copyright (C) 1999-2015, QOS.ch. All rights reserved. - * + *

* This program and the accompanying materials are dual-licensed under * either the terms of the Eclipse Public License v1.0 as published by * the Eclipse Foundation - * - * or (per the licensee's choosing) - * + *

+ * or (per the licensee's choosing) + *

* under the terms of the GNU Lesser General Public License version 2.1 * as published by the Free Software Foundation. */ @@ -23,6 +23,7 @@ import java.util.Map; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.ScheduledFuture; +import java.util.concurrent.locks.ReentrantLock; import ch.qos.logback.classic.util.LogbackMDCAdapter; import ch.qos.logback.core.status.ErrorStatus; @@ -57,7 +58,9 @@ */ public class LoggerContext extends ContextBase implements ILoggerFactory, LifeCycle { - /** Default setting of packaging data in stack traces */ + /** + * Default setting of packaging data in stack traces + */ public static final boolean DEFAULT_PACKAGING_DATA = false; final Logger root; @@ -74,7 +77,6 @@ public class LoggerContext extends ContextBase implements ILoggerFactory, LifeCy MDCAdapter mdcAdapter; - private int maxCallerDataDepth = ClassicConstants.DEFAULT_MAX_CALLEDER_DATA_DEPTH; int resetCount = 0; @@ -91,6 +93,10 @@ public LoggerContext() { initEvaluatorMap(); size = 1; this.frameworkPackages = new ArrayList(); + // In 1.5.7, the stop() method assumes that at some point the context has been started + // since earlier versions of logback did not mandate calling the start method + // we need to call in the constructor + this.start(); } void initEvaluatorMap() { @@ -117,8 +123,6 @@ public void setName(String name) { updateLoggerContextVO(); } - - public final Logger getLogger(final Class clazz) { return getLogger(clazz.getName()); } @@ -194,9 +198,7 @@ public Logger exists(String name) { final void noAppenderDefinedWarning(final Logger logger) { if (noAppenderWarning++ == 0) { - getStatusManager().add(new WarnStatus( - "No appenders present in context [" + getName() + "] for logger [" + logger.getName() + "].", - logger)); + getStatusManager().add(new WarnStatus("No appenders present in context [" + getName() + "] for logger [" + logger.getName() + "].", logger)); } } @@ -219,17 +221,24 @@ public boolean isPackagingDataEnabled() { return packagingDataEnabled; } - private void cancelScheduledTasks() { - for (ScheduledFuture sf : scheduledFutures) { - sf.cancel(false); + void cancelScheduledTasks() { + + try { + configurationLock.lock(); + + for (ScheduledFuture sf : scheduledFutures) { + sf.cancel(false); + } + scheduledFutures.clear(); + } finally { + configurationLock.unlock(); } - scheduledFutures.clear(); } private void resetStatusListenersExceptResetResistant() { StatusManager sm = getStatusManager(); for (StatusListener sl : sm.getCopyOfStatusListenerList()) { - if(!sl.isResetResistant()) { + if (!sl.isResetResistant()) { sm.remove(sl); } } @@ -254,29 +263,28 @@ public void resetTurboFilterList() { turboFilterList.clear(); } - final FilterReply getTurboFilterChainDecision_0_3OrMore(final Marker marker, final Logger logger, final Level level, - final String format, final Object[] params, final Throwable t) { + final FilterReply getTurboFilterChainDecision_0_3OrMore(final Marker marker, final Logger logger, final Level level, final String format, + final Object[] params, final Throwable t) { if (turboFilterList.size() == 0) { return FilterReply.NEUTRAL; } return turboFilterList.getTurboFilterChainDecision(marker, logger, level, format, params, t); } - final FilterReply getTurboFilterChainDecision_1(final Marker marker, final Logger logger, final Level level, - final String format, final Object param, final Throwable t) { + final FilterReply getTurboFilterChainDecision_1(final Marker marker, final Logger logger, final Level level, final String format, final Object param, + final Throwable t) { if (turboFilterList.size() == 0) { return FilterReply.NEUTRAL; } return turboFilterList.getTurboFilterChainDecision(marker, logger, level, format, new Object[] { param }, t); } - final FilterReply getTurboFilterChainDecision_2(final Marker marker, final Logger logger, final Level level, - final String format, final Object param1, final Object param2, final Throwable t) { + final FilterReply getTurboFilterChainDecision_2(final Marker marker, final Logger logger, final Level level, final String format, final Object param1, + final Object param2, final Throwable t) { if (turboFilterList.size() == 0) { return FilterReply.NEUTRAL; } - return turboFilterList.getTurboFilterChainDecision(marker, logger, level, format, - new Object[] { param1, param2 }, t); + return turboFilterList.getTurboFilterChainDecision(marker, logger, level, format, new Object[] { param1, param2 }, t); } // === start listeners ============================================== @@ -340,10 +348,21 @@ public void start() { } public void stop() { - reset(); - fireOnStop(); - resetAllListeners(); - super.stop(); + if (!isStarted()) + return; + + try { + configurationLock.lock(); + if (!isStarted()) + return; + + reset(); + fireOnStop(); + resetAllListeners(); + super.stop(); + } finally { + configurationLock.unlock(); + } } /** @@ -395,7 +414,6 @@ public List getFrameworkPackages() { return frameworkPackages; } - @Override public void setSequenceNumberGenerator(SequenceNumberGenerator sng) { this.sequenceNumberGenerator = sng; @@ -411,7 +429,7 @@ public MDCAdapter getMDCAdapter() { } public void setMDCAdapter(MDCAdapter anAdapter) { - if(this.mdcAdapter != null) { + if (this.mdcAdapter != null) { StatusManager sm = getStatusManager(); sm.add(new WarnStatus("mdcAdapter being reset a second time", this)); } diff --git a/logback-classic/src/main/java/ch/qos/logback/classic/joran/ReconfigureOnChangeTask.java b/logback-classic/src/main/java/ch/qos/logback/classic/joran/ReconfigureOnChangeTask.java index 74f0304683..2a2b6767f2 100755 --- a/logback-classic/src/main/java/ch/qos/logback/classic/joran/ReconfigureOnChangeTask.java +++ b/logback-classic/src/main/java/ch/qos/logback/classic/joran/ReconfigureOnChangeTask.java @@ -30,7 +30,7 @@ import ch.qos.logback.core.status.StatusUtil; import static ch.qos.logback.core.spi.ConfigurationEvent.newConfigurationChangeDetectorRunningEvent; -import static ch.qos.logback.core.spi.ConfigurationEvent.newConfigurationEndedEvent; +import static ch.qos.logback.core.spi.ConfigurationEvent.newConfigurationEndedSuccessfullyEvent; public class ReconfigureOnChangeTask extends ContextAwareBase implements Runnable { @@ -92,6 +92,7 @@ private void performXMLConfiguration(LoggerContext lc, URL mainConfigurationURL) StatusUtil statusUtil = new StatusUtil(context); Model failsafeTop = jc.recallSafeConfiguration(); URL mainURL = ConfigurationWatchListUtil.getMainWatchURL(context); + addInfo("Resetting loggerContext ["+lc.getName()+"]"); lc.reset(); long threshold = System.currentTimeMillis(); try { @@ -129,8 +130,7 @@ private void fallbackConfiguration(LoggerContext lc, Model failsafeTop, URL main joranConfigurator.processModel(failsafeTop); addInfo(RE_REGISTERING_PREVIOUS_SAFE_CONFIGURATION); joranConfigurator.registerSafeConfiguration(failsafeTop); - context.fireConfigurationEvent(newConfigurationEndedEvent(this)); - addInfo("after registerSafeConfiguration"); + context.fireConfigurationEvent(newConfigurationEndedSuccessfullyEvent(this)); } catch (Exception e) { addError("Unexpected exception thrown by a configuration considered safe.", e); } diff --git a/logback-classic/src/main/java/ch/qos/logback/classic/joran/SerializedModelConfigurator.java b/logback-classic/src/main/java/ch/qos/logback/classic/joran/SerializedModelConfigurator.java index 9bf7c03f16..2cc7f20868 100644 --- a/logback-classic/src/main/java/ch/qos/logback/classic/joran/SerializedModelConfigurator.java +++ b/logback-classic/src/main/java/ch/qos/logback/classic/joran/SerializedModelConfigurator.java @@ -37,6 +37,7 @@ import java.io.InputStream; import java.net.MalformedURLException; import java.net.URL; +import java.util.concurrent.locks.ReentrantLock; import static ch.qos.logback.core.CoreConstants.MODEL_CONFIG_FILE_EXTENSION; @@ -81,8 +82,12 @@ private void configureByResource(URL url) { mc2mhl.link(defaultProcessor); // disallow simultaneous configurations of the same context - synchronized (context.getConfigurationLock()) { + ReentrantLock configurationLock = context.getConfigurationLock(); + try { + configurationLock.lock(); defaultProcessor.process(model); + } finally { + configurationLock.unlock(); } } else { throw new LogbackException( diff --git a/logback-classic/src/test/java/ch/qos/logback/classic/Logback1551.java b/logback-classic/src/test/java/ch/qos/logback/classic/Logback1551.java new file mode 100644 index 0000000000..85dbfd7746 --- /dev/null +++ b/logback-classic/src/test/java/ch/qos/logback/classic/Logback1551.java @@ -0,0 +1,81 @@ +/* + * Logback: the reliable, generic, fast and flexible logging framework. + * Copyright (C) 1999-2024, QOS.ch. All rights reserved. + * + * This program and the accompanying materials are dual-licensed under + * either the terms of the Eclipse Public License v1.0 as published by + * the Eclipse Foundation + * + * or (per the licensee's choosing) + * + * under the terms of the GNU Lesser General Public License version 2.1 + * as published by the Free Software Foundation. + */ + +package ch.qos.logback.classic; + +import ch.qos.logback.core.util.Duration; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; + +import java.util.Arrays; +import java.util.concurrent.ScheduledExecutorService; +import java.util.concurrent.ScheduledFuture; +import java.util.concurrent.TimeUnit; + +public class Logback1551 { + LoggerContext lc; + + @BeforeEach + public void setUp() throws Exception { + lc = new LoggerContext(); + lc.setName("x"); + } + @Test + public void testConcurrentModificationScheduledTasks() { + ScheduledExecutorService scheduledExecutorService = lc.getScheduledExecutorService(); + Duration duration = Duration.buildByMilliseconds(10); + + Runnable runnable = new Runnable() { + public void run() { + try { + Thread.sleep(100); + } catch (InterruptedException e) { + throw new RuntimeException(e); + } + } + }; + ScheduledFuture scheduledFuture = scheduledExecutorService.scheduleAtFixedRate(runnable, + duration.getMilliseconds(), duration.getMilliseconds(), TimeUnit.MILLISECONDS); + + lc.addScheduledFuture(scheduledFuture); + int THREAD_COUNT = 20; + Thread[] threads = new Thread[THREAD_COUNT]; + + for (int i = 0; i < THREAD_COUNT; i++) { + threads[i] = new Thread(new CancelRunnable(lc)); + threads[i].start(); + } + + Arrays.stream(threads).forEach(t-> { + try { + t.join(); + } catch (InterruptedException e) { + throw new RuntimeException(e); + } + }); + + } + + private class CancelRunnable implements Runnable { + LoggerContext lc; + public CancelRunnable(LoggerContext lc) { + this.lc = lc; + } + + @Override + public void run() { + lc.cancelScheduledTasks(); + } + } +} diff --git a/logback-classic/src/test/java/ch/qos/logback/classic/LoggerContextTest.java b/logback-classic/src/test/java/ch/qos/logback/classic/LoggerContextTest.java index 5d973a40cd..c4d5d64ca8 100644 --- a/logback-classic/src/test/java/ch/qos/logback/classic/LoggerContextTest.java +++ b/logback-classic/src/test/java/ch/qos/logback/classic/LoggerContextTest.java @@ -1,36 +1,30 @@ /** * Logback: the reliable, generic, fast and flexible logging framework. * Copyright (C) 1999-2015, QOS.ch. All rights reserved. - * + *

* This program and the accompanying materials are dual-licensed under * either the terms of the Eclipse Public License v1.0 as published by * the Eclipse Foundation - * - * or (per the licensee's choosing) - * + *

+ * or (per the licensee's choosing) + *

* under the terms of the GNU Lesser General Public License version 2.1 * as published by the Free Software Foundation. */ package ch.qos.logback.classic; -import static ch.qos.logback.core.CoreConstants.FA_FILENAME_COLLISION_MAP; -import static org.junit.jupiter.api.Assertions.assertEquals; -import static org.junit.jupiter.api.Assertions.assertFalse; -import static org.junit.jupiter.api.Assertions.assertNotNull; -import static org.junit.jupiter.api.Assertions.assertNull; -import static org.junit.jupiter.api.Assertions.assertTrue; -import static org.junit.jupiter.api.Assertions.fail; - -import java.util.Map; - -import org.junit.jupiter.api.BeforeEach; - import ch.qos.logback.classic.turbo.NOPTurboFilter; import ch.qos.logback.core.CoreConstants; import ch.qos.logback.core.rolling.helper.FileNamePattern; import ch.qos.logback.core.status.StatusManager; +import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; +import java.util.Map; + +import static ch.qos.logback.core.CoreConstants.FA_FILENAME_COLLISION_MAP; +import static org.junit.jupiter.api.Assertions.*; + public class LoggerContextTest { LoggerContext lc; @@ -251,8 +245,8 @@ public void collisionMapsPostReset() { assertNotNull(fileCollisions); assertTrue(fileCollisions.isEmpty()); - Map filenamePatternCollisionMap = (Map) lc - .getObject(CoreConstants.RFA_FILENAME_PATTERN_COLLISION_MAP); + Map filenamePatternCollisionMap = (Map) lc.getObject( + CoreConstants.RFA_FILENAME_PATTERN_COLLISION_MAP); assertNotNull(filenamePatternCollisionMap); assertTrue(filenamePatternCollisionMap.isEmpty()); } diff --git a/logback-classic/src/test/java/ch/qos/logback/classic/joran/ChangeDetectedListener.java b/logback-classic/src/test/java/ch/qos/logback/classic/joran/ChangeDetectedListener.java index 98f02fb5bf..aa070ee502 100644 --- a/logback-classic/src/test/java/ch/qos/logback/classic/joran/ChangeDetectedListener.java +++ b/logback-classic/src/test/java/ch/qos/logback/classic/joran/ChangeDetectedListener.java @@ -33,7 +33,7 @@ class ChangeDetectedListener implements ConfigurationEventListener { public void listen(ConfigurationEvent configurationEvent) { switch (configurationEvent.getEventType()) { case CHANGE_DETECTED: - System.out.println(this.toString() + "#listen Change detected" + " count="+countDownLatch.getCount()); + System.out.println(this.toString() + "#listen Change detected " + configurationEvent +" count="+countDownLatch.getCount()); countDownLatch.countDown(); Object data = configurationEvent.getData(); diff --git a/logback-classic/src/test/java/ch/qos/logback/classic/joran/ReconfigurationDoneListener.java b/logback-classic/src/test/java/ch/qos/logback/classic/joran/ReconfigurationDoneListener.java index 856838969c..99f3d4b3a7 100644 --- a/logback-classic/src/test/java/ch/qos/logback/classic/joran/ReconfigurationDoneListener.java +++ b/logback-classic/src/test/java/ch/qos/logback/classic/joran/ReconfigurationDoneListener.java @@ -23,6 +23,7 @@ class ReconfigurationDoneListener implements ConfigurationEventListener { CountDownLatch countDownLatch; ReconfigureOnChangeTask roct; + ReconfigurationDoneListener(CountDownLatch countDownLatch, ReconfigureOnChangeTask aRoct) { this.countDownLatch = countDownLatch; this.roct = aRoct; @@ -31,7 +32,7 @@ class ReconfigurationDoneListener implements ConfigurationEventListener { @Override public void listen(ConfigurationEvent configurationEvent) { switch (configurationEvent.getEventType()) { - case CONFIGURATION_ENDED: + case CONFIGURATION_ENDED_SUCCESSFULLY: if(roct == null) { countDownLatch.countDown(); } else { diff --git a/logback-classic/src/test/java/ch/qos/logback/classic/joran/ReconfigureOnChangeTaskTest.java b/logback-classic/src/test/java/ch/qos/logback/classic/joran/ReconfigureOnChangeTaskTest.java index 2fd79a6554..9e2cb11df0 100755 --- a/logback-classic/src/test/java/ch/qos/logback/classic/joran/ReconfigureOnChangeTaskTest.java +++ b/logback-classic/src/test/java/ch/qos/logback/classic/joran/ReconfigureOnChangeTaskTest.java @@ -39,7 +39,6 @@ import ch.qos.logback.core.status.WarnStatus; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.BeforeAll; -import org.junit.jupiter.api.Disabled; import org.junit.jupiter.api.Test; import ch.qos.logback.classic.Logger; @@ -185,6 +184,7 @@ public void reconfigurationIsNotPossibleInTheAbsenceOfATopFile() @Test @Timeout(value = TIMEOUT, unit = TimeUnit.SECONDS) public void fallbackToSafe_FollowedByRecovery() throws IOException, JoranException, InterruptedException { + addInfo("Start fallbackToSafe_FollowedByRecovery", this); String path = CoreTestConstants.OUTPUT_DIR_PREFIX + "reconfigureOnChangeConfig_fallbackToSafe-" + diff + ".xml"; File topLevelFile = new File(path); writeToFile(topLevelFile, @@ -193,30 +193,33 @@ public void fallbackToSafe_FollowedByRecovery() throws IOException, JoranExcepti addResetResistantOnConsoleStatusListener(); configure(topLevelFile); - long afterFirstConfiguration = System.currentTimeMillis(); CountDownLatch changeDetectedLatch = registerChangeDetectedListener(); - CountDownLatch configurationDoneLatch = registerNewReconfigurationDoneListener(); + CountDownLatch configurationDoneLatch = registerNewReconfigurationDoneSuccessfullyListener(); String badXML = "\n" + " "; writeToFile(topLevelFile, badXML); changeDetectedLatch.await(); configurationDoneLatch.await(); - addInfo("Woke from configurationDoneLatch.await()", this); statusChecker.assertContainsMatch(Status.ERROR, CoreConstants.XML_PARSING); statusChecker.assertContainsMatch(Status.WARN, FALLING_BACK_TO_SAFE_CONFIGURATION); statusChecker.assertContainsMatch(Status.INFO, RE_REGISTERING_PREVIOUS_SAFE_CONFIGURATION); + // clear required for checks down below loggerContext.getStatusManager().clear(); - addInfo("after loggerContext.getStatusManager().clear() ", this); - CountDownLatch secondConfigEndedLatch = registerNewReconfigurationDoneListener(); + addInfo("RECOVERY - Writing error-free config file ", this); + CountDownLatch secondConfigEndedLatch = registerNewReconfigurationDoneSuccessfullyListener(); + // recovery writeToFile(topLevelFile, " "); - secondConfigEndedLatch.await(); + try { + addInfo("Awaiting secondConfigEndedLatch ", this); + secondConfigEndedLatch.await(5, TimeUnit.SECONDS); + addInfo("after secondConfigEndedLatch.await ", this); statusChecker.assertIsErrorFree(); statusChecker.containsMatch(DETECTED_CHANGE_IN_CONFIGURATION_FILES); } finally { @@ -263,7 +266,7 @@ public void fallbackToSafeWithIncludedFile_FollowedByRecovery() System.out.println("==================================================="); CountDownLatch changeDetectedLatch = registerChangeDetectedListener(); - CountDownLatch configurationDoneLatch = registerNewReconfigurationDoneListener(roct); + CountDownLatch configurationDoneLatch = registerNewReconfigurationDoneSuccessfullyListener(roct); writeToFile(innerFile, "\n\n"); changeDetectedLatch.await(); @@ -276,7 +279,7 @@ public void fallbackToSafeWithIncludedFile_FollowedByRecovery() loggerContext.getStatusManager().clear(); - CountDownLatch secondDoneLatch = registerNewReconfigurationDoneListener(); + CountDownLatch secondDoneLatch = registerNewReconfigurationDoneSuccessfullyListener(); writeToFile(innerFile, " "); secondDoneLatch.await(); @@ -285,11 +288,11 @@ public void fallbackToSafeWithIncludedFile_FollowedByRecovery() } - CountDownLatch registerNewReconfigurationDoneListener() { - return registerNewReconfigurationDoneListener(null); + CountDownLatch registerNewReconfigurationDoneSuccessfullyListener() { + return registerNewReconfigurationDoneSuccessfullyListener(null); } - CountDownLatch registerNewReconfigurationDoneListener(ReconfigureOnChangeTask roct) { + CountDownLatch registerNewReconfigurationDoneSuccessfullyListener(ReconfigureOnChangeTask roct) { CountDownLatch latch = new CountDownLatch(1); ReconfigurationDoneListener reconfigurationDoneListener = new ReconfigurationDoneListener(latch, roct); loggerContext.addConfigurationEventListener(reconfigurationDoneListener); @@ -368,9 +371,6 @@ public void scan_LOGBACK_474() throws JoranException, IOException, InterruptedEx addResetResistantOnConsoleStatusListener(); configure(file); - // ReconfigureOnChangeTask roct = waitForReconfigureOnChangeTaskToRun(); - System.out.println(" ------------ creating ReconfigureOnChangeTaskHarness"); - int expectedResets = 2; ReconfigureOnChangeTaskHarness harness = new ReconfigureOnChangeTaskHarness(loggerContext, expectedResets); diff --git a/logback-classic/src/test/java/ch/qos/logback/classic/spi/ContextListenerTest.java b/logback-classic/src/test/java/ch/qos/logback/classic/spi/ContextListenerTest.java index 17a1f11c96..1dec87840f 100644 --- a/logback-classic/src/test/java/ch/qos/logback/classic/spi/ContextListenerTest.java +++ b/logback-classic/src/test/java/ch/qos/logback/classic/spi/ContextListenerTest.java @@ -26,47 +26,48 @@ public class ContextListenerTest { - LoggerContext context; + LoggerContext loggerContext; BasicContextListener listener; @BeforeEach public void setUp() throws Exception { - context = new LoggerContext(); + loggerContext = new LoggerContext(); + loggerContext.start(); listener = new BasicContextListener(); - context.addListener(listener); + loggerContext.addListener(listener); } @Test public void testNotifyOnReset() { - context.reset(); + loggerContext.reset(); assertEquals(UpdateType.RESET, listener.updateType); - assertEquals(listener.context, context); + assertEquals(listener.context, loggerContext); } @Test - public void testNotifyOnStopResistant() { + public void testResistantListener_NotifyOnStop() { listener.setResetResistant(true); - context.stop(); + loggerContext.stop(); assertEquals(UpdateType.STOP, listener.updateType); - assertEquals(listener.context, context); + assertEquals(listener.context, loggerContext); } @Test - public void testNotifyOnStopNotResistant() { - context.stop(); + public void testNotResistantListener_NotifyOnStop() { + loggerContext.stop(); assertEquals(UpdateType.RESET, listener.updateType); - assertEquals(listener.context, context); + assertEquals(listener.context, loggerContext); } @Test public void testNotifyOnStart() { - context.start(); + loggerContext.start(); assertEquals(UpdateType.START, listener.updateType); - assertEquals(listener.context, context); + assertEquals(listener.context, loggerContext); } void checkLevelChange(String loggerName, Level level) { - Logger logger = context.getLogger(loggerName); + Logger logger = loggerContext.getLogger(loggerName); logger.setLevel(level); assertEquals(UpdateType.LEVEL_CHANGE, listener.updateType); diff --git a/logback-core/src/main/java/ch/qos/logback/core/Context.java b/logback-core/src/main/java/ch/qos/logback/core/Context.java index 0a8b57af70..eb35feaa68 100644 --- a/logback-core/src/main/java/ch/qos/logback/core/Context.java +++ b/logback-core/src/main/java/ch/qos/logback/core/Context.java @@ -18,6 +18,7 @@ import java.util.concurrent.ScheduledExecutorService; import java.util.concurrent.ScheduledFuture; import java.util.concurrent.ThreadPoolExecutor; +import java.util.concurrent.locks.ReentrantLock; import ch.qos.logback.core.spi.ConfigurationEvent; import ch.qos.logback.core.spi.ConfigurationEventListener; @@ -107,7 +108,7 @@ public interface Context extends PropertyContainer { /** * Object used for synchronization purposes. INTENDED FOR INTERNAL USAGE. */ - Object getConfigurationLock(); + ReentrantLock getConfigurationLock(); /** * Returns the ScheduledExecutorService for this context. @@ -169,12 +170,17 @@ default ExecutorService getAlternateExecutorService() { *

The propagation of {@link ConfigurationEvent configuration events} is intended for internal testing * as well as some coordination between configurators.

* - * * @param listener * @since 1.3.6/1.4.6 */ void addConfigurationEventListener(ConfigurationEventListener listener); + /** + * Remove an existing ConfigurationEventListener + * @param listener + * @since 1.5.7 + */ + default void removeConfigurationEventListener(ConfigurationEventListener listener) {}; /** * Fire {@link ConfigurationEvent} by invoking {@link #addConfigurationEventListener registered listeners}. * diff --git a/logback-core/src/main/java/ch/qos/logback/core/ContextBase.java b/logback-core/src/main/java/ch/qos/logback/core/ContextBase.java index 0c9920dacb..8bd4c148f9 100755 --- a/logback-core/src/main/java/ch/qos/logback/core/ContextBase.java +++ b/logback-core/src/main/java/ch/qos/logback/core/ContextBase.java @@ -23,12 +23,12 @@ import java.util.List; import java.util.Map; import java.util.concurrent.*; +import java.util.concurrent.locks.ReentrantLock; import ch.qos.logback.core.rolling.helper.FileNamePattern; import ch.qos.logback.core.spi.ConfigurationEvent; import ch.qos.logback.core.spi.ConfigurationEventListener; import ch.qos.logback.core.spi.LifeCycle; -import ch.qos.logback.core.spi.LogbackLock; import ch.qos.logback.core.spi.SequenceNumberGenerator; import ch.qos.logback.core.status.InfoStatus; import ch.qos.logback.core.status.StatusManager; @@ -47,7 +47,7 @@ public class ContextBase implements Context, LifeCycle { Map propertyMap = new HashMap(); Map objectMap = new ConcurrentHashMap<>(); - LogbackLock configurationLock = new LogbackLock(); + protected ReentrantLock configurationLock = new ReentrantLock(); final private List configurationEventListenerList = new CopyOnWriteArrayList<>(); @@ -61,7 +61,8 @@ public class ContextBase implements Context, LifeCycle { private LifeCycleManager lifeCycleManager; private SequenceNumberGenerator sequenceNumberGenerator; - private boolean started; + // 'started' is used to mitigate race conditions in stop() and possibly other methods, hence the volatile qualifier. + private volatile boolean started; public ContextBase() { initCollisionMaps(); @@ -223,7 +224,7 @@ public long getBirthTime() { return birthTime; } - public Object getConfigurationLock() { + public ReentrantLock getConfigurationLock() { return configurationLock; } @@ -336,9 +337,13 @@ public void addConfigurationEventListener(ConfigurationEventListener listener) { configurationEventListenerList.add(listener); } + @Override + public void removeConfigurationEventListener(ConfigurationEventListener listener) { + configurationEventListenerList.remove(listener); + } + @Override public void fireConfigurationEvent(ConfigurationEvent configurationEvent) { - //System.out.println("xxxx fireConfigurationEvent of "+configurationEvent); configurationEventListenerList.forEach( l -> l.listen(configurationEvent)); } } diff --git a/logback-core/src/main/java/ch/qos/logback/core/joran/GenericXMLConfigurator.java b/logback-core/src/main/java/ch/qos/logback/core/joran/GenericXMLConfigurator.java index e0c66d388c..3680903a31 100755 --- a/logback-core/src/main/java/ch/qos/logback/core/joran/GenericXMLConfigurator.java +++ b/logback-core/src/main/java/ch/qos/logback/core/joran/GenericXMLConfigurator.java @@ -12,8 +12,7 @@ package ch.qos.logback.core.joran; import static ch.qos.logback.core.CoreConstants.SAFE_JORAN_CONFIGURATION; -import static ch.qos.logback.core.spi.ConfigurationEvent.newConfigurationEndedEvent; -import static ch.qos.logback.core.spi.ConfigurationEvent.newConfigurationStartedEvent; +import static ch.qos.logback.core.spi.ConfigurationEvent.*; import java.io.File; import java.io.FileInputStream; @@ -22,6 +21,7 @@ import java.net.URL; import java.net.URLConnection; import java.util.List; +import java.util.concurrent.locks.ReentrantLock; import org.xml.sax.InputSource; @@ -182,8 +182,11 @@ public final void doConfigure(final InputSource inputSource) throws JoranExcepti if (statusUtil.noXMLParsingErrorsOccurred(threshold)) { addInfo("Registering current configuration as safe fallback point"); registerSafeConfiguration(top); + context.fireConfigurationEvent(newConfigurationEndedSuccessfullyEvent(this)); + } else { + context.fireConfigurationEvent(newConfigurationEndedWithXMLParsingErrorsEvent(this)); } - context.fireConfigurationEvent(newConfigurationEndedEvent(this)); + } @@ -212,8 +215,13 @@ public void processModel(Model model) { addModelHandlerAssociations(defaultProcessor); // disallow simultaneous configurations of the same context - synchronized (context.getConfigurationLock()) { + ReentrantLock configurationLock = context.getConfigurationLock(); + + try { + configurationLock.lock(); defaultProcessor.process(model); + } finally { + configurationLock.unlock(); } } diff --git a/logback-core/src/main/java/ch/qos/logback/core/model/processor/ShutdownHookModelHandler.java b/logback-core/src/main/java/ch/qos/logback/core/model/processor/ShutdownHookModelHandler.java index dc14303a45..6677571e42 100755 --- a/logback-core/src/main/java/ch/qos/logback/core/model/processor/ShutdownHookModelHandler.java +++ b/logback-core/src/main/java/ch/qos/logback/core/model/processor/ShutdownHookModelHandler.java @@ -20,6 +20,7 @@ import ch.qos.logback.core.hook.ShutdownHookBase; import ch.qos.logback.core.model.Model; import ch.qos.logback.core.model.ShutdownHookModel; +import ch.qos.logback.core.util.ContextUtil; import ch.qos.logback.core.util.DynamicClassLoadingException; import ch.qos.logback.core.util.IncompatibleClassException; import ch.qos.logback.core.util.OptionHelper; @@ -87,11 +88,8 @@ public void postHandle(ModelInterpretationContext mic, Model model) throws Model if (o != hook) { addWarn("The object on the top the of the stack is not the hook object pushed earlier."); } else { - Thread hookThread = new Thread(hook, "Logback shutdown hook [" + context.getName() + "]"); - addInfo("Registering shutdown hook with JVM runtime."); - context.putObject(CoreConstants.SHUTDOWN_HOOK_THREAD, hookThread); - Runtime.getRuntime().addShutdownHook(hookThread); - + ContextUtil contextUtil = new ContextUtil(context); + contextUtil.addOrReplaceShutdownHook(hook); mic.popObject(); } } diff --git a/logback-core/src/main/java/ch/qos/logback/core/spi/ConfigurationEvent.java b/logback-core/src/main/java/ch/qos/logback/core/spi/ConfigurationEvent.java index d019309dcd..17a3504db1 100644 --- a/logback-core/src/main/java/ch/qos/logback/core/spi/ConfigurationEvent.java +++ b/logback-core/src/main/java/ch/qos/logback/core/spi/ConfigurationEvent.java @@ -32,7 +32,8 @@ public enum EventType { CHANGE_DETECTOR_RUNNING, CHANGE_DETECTED, CONFIGURATION_STARTED, - CONFIGURATION_ENDED; + CONFIGURATION_ENDED_SUCCESSFULLY, + CONFIGURATION_ENDED_WITH_XML_PARSING_ERRORS; } final EventType eventType; final Object data; @@ -61,10 +62,12 @@ static public ConfigurationEvent newConfigurationChangeDetectedEvent(Object data static public ConfigurationEvent newConfigurationStartedEvent(Object data) { return new ConfigurationEvent(EventType.CONFIGURATION_STARTED, data); } - static public ConfigurationEvent newConfigurationEndedEvent(Object data) { - return new ConfigurationEvent(EventType.CONFIGURATION_ENDED, data); + static public ConfigurationEvent newConfigurationEndedSuccessfullyEvent(Object data) { + return new ConfigurationEvent(EventType.CONFIGURATION_ENDED_SUCCESSFULLY, data); + } + static public ConfigurationEvent newConfigurationEndedWithXMLParsingErrorsEvent(Object data) { + return new ConfigurationEvent(EventType.CONFIGURATION_ENDED_WITH_XML_PARSING_ERRORS, data); } - public EventType getEventType() { return eventType; } diff --git a/logback-core/src/main/java/ch/qos/logback/core/util/ContextUtil.java b/logback-core/src/main/java/ch/qos/logback/core/util/ContextUtil.java index ac9c63fcbe..4ad3abb283 100755 --- a/logback-core/src/main/java/ch/qos/logback/core/util/ContextUtil.java +++ b/logback-core/src/main/java/ch/qos/logback/core/util/ContextUtil.java @@ -22,6 +22,8 @@ import java.util.Properties; import ch.qos.logback.core.Context; +import ch.qos.logback.core.CoreConstants; +import ch.qos.logback.core.hook.ShutdownHook; import ch.qos.logback.core.rolling.helper.FileNamePattern; import ch.qos.logback.core.spi.ContextAwareBase; @@ -73,4 +75,27 @@ public void addFrameworkPackage(List frameworkPackages, String packageNa } } + /** + * Add a shutdown hook thread with the JVM runtime. + * + * If a previous shutdown hook thread was registered, it is replaced. + * @param hook + * @since 1.5.7 + */ + public void addOrReplaceShutdownHook(ShutdownHook hook) { + Runtime runtime = Runtime.getRuntime(); + + Thread oldShutdownHookTread = (Thread) context.getObject(CoreConstants.SHUTDOWN_HOOK_THREAD); + if(oldShutdownHookTread != null) { + addInfo("Removing old shutdown hook from JVM runtime"); + runtime.removeShutdownHook(oldShutdownHookTread); + } + + Thread hookThread = new Thread(hook, "Logback shutdown hook [" + context.getName() + "]"); + addInfo("Registering shutdown hook with JVM runtime."); + context.putObject(CoreConstants.SHUTDOWN_HOOK_THREAD, hookThread); + runtime.addShutdownHook(hookThread); + + } + } diff --git a/logback-core/src/test/java/ch/qos/logback/core/util/ContextUtilAddOrReplaceShutdownHookTest.java b/logback-core/src/test/java/ch/qos/logback/core/util/ContextUtilAddOrReplaceShutdownHookTest.java new file mode 100644 index 0000000000..2978832345 --- /dev/null +++ b/logback-core/src/test/java/ch/qos/logback/core/util/ContextUtilAddOrReplaceShutdownHookTest.java @@ -0,0 +1,67 @@ +/* + * Logback: the reliable, generic, fast and flexible logging framework. + * Copyright (C) 1999-2024, QOS.ch. All rights reserved. + * + * This program and the accompanying materials are dual-licensed under + * either the terms of the Eclipse Public License v1.0 as published by + * the Eclipse Foundation + * + * or (per the licensee's choosing) + * + * under the terms of the GNU Lesser General Public License version 2.1 + * as published by the Free Software Foundation. + */ + +package ch.qos.logback.core.util; + +import ch.qos.logback.core.Context; +import ch.qos.logback.core.ContextBase; +import ch.qos.logback.core.hook.ShutdownHookBase; +import org.junit.jupiter.api.Disabled; +import org.junit.jupiter.api.Test; + +/** + * Given the code executed in a shutdown hook is the last bit of code that is executed + * before the JVM exits, there is no way to test that a shutdown hook has been removed or + * is active. + * + * As such, this test cannot be automated. + */ +@Disabled +class ContextUtilAddOrReplaceShutdownHookTest { + + Context context = new ContextBase(); + ContextUtil contextUtil = new ContextUtil(context); + + @Test + public void smoke() { + + contextUtil.addOrReplaceShutdownHook(new HelloShutdownHookHook(2)); + contextUtil.addOrReplaceShutdownHook(new HelloShutdownHookHook(3)); + contextUtil.addOrReplaceShutdownHook(new HelloShutdownHookHook(5)); + // expect to see + // HelloShutdownHookHook{number=5} + } + + static class HelloShutdownHookHook extends ShutdownHookBase { + + int number; + + + public HelloShutdownHookHook(int number) { + this.number = number; + + } + + @Override + public void run() { + System.out.println(this); + } + + @Override + public String toString() { + return "HelloShutdownHookHook{" + "number=" + number + '}'; + } + } + +} \ No newline at end of file