fix LOGBACK-1162

qos-ch · Jan 25, 2018 · 4d705d9 · 4d705d9
1 parent 5a81da1
commit 4d705d9
Show file tree

Hide file tree

Showing 11 changed files with 140 additions and 88 deletions.
diff --git a/logback-classic/src/test/input/joran/issues/logback_1162.xml b/logback-classic/src/test/input/joran/issues/logback_1162.xml
@@ -0,0 +1,19 @@
+<configuration debug="TRUE">
+    <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />
+
+    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
+        <file>${output_dir}/info.log</file>
+        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
+            <fileNamePattern>${output_dir}/info.%d{yyyy-MM-dd}.log.gz</fileNamePattern>
+        </rollingPolicy>
+        <encoder>
+            <pattern>%date %level [%thread] %logger{40} - %msg%n</pattern>
+        </encoder>
+    </appender>
+
+    <root level="DEBUG">
+        <appender-ref ref="FILE" />
+    </root>
+
+    <shutdownHook/>
+</configuration>
diff --git a/logback-classic/src/test/java/ch/qos/logback/classic/issue/logback_1162/Main.java b/logback-classic/src/test/java/ch/qos/logback/classic/issue/logback_1162/Main.java
@@ -0,0 +1,29 @@
+package ch.qos.logback.classic.issue.logback_1162;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+import ch.qos.logback.classic.ClassicTestConstants;
+import ch.qos.logback.classic.LoggerContext;
+import ch.qos.logback.classic.joran.JoranConfigurator;
+import ch.qos.logback.core.joran.spi.JoranException;
+
+import java.util.concurrent.TimeUnit;
+
+public class Main {
+    private static final Logger logger = LoggerFactory.getLogger(Main.class);
+
+    public static void main(String[] args) throws InterruptedException, JoranException {
+        LoggerContext lc = (LoggerContext) LoggerFactory.getILoggerFactory();
+        lc.reset();
+        lc.putProperty("output_dir", ClassicTestConstants.OUTPUT_DIR_PREFIX+"logback_issue_1162/");
+
+        JoranConfigurator configurator = new JoranConfigurator();
+        configurator.setContext(lc);
+        configurator.doConfigure(ClassicTestConstants.JORAN_INPUT_PREFIX+ "issues/logback_1162.xml");
+
+
+        logger.info("Hello, world!");
+
+        TimeUnit.SECONDS.sleep(0);
+    }
+}
diff --git a/logback-classic/src/test/java/ch/qos/logback/classic/issue/logback_1162/reproduce-bug.sh b/logback-classic/src/test/java/ch/qos/logback/classic/issue/logback_1162/reproduce-bug.sh
@@ -0,0 +1,15 @@
+#!/bin/bash
+
+set -e
+
+DD="dd"
+TOUCH="touch"
+
+TARGET_DIR=/home/ceki/logback/logback-classic/target/test-output/logback_issue_1162/
+
+rm -rf $TARGET_DIR && \
+  mkdir -p $TARGET_DIR  && \
+  $DD if=/dev/urandom of=$TARGET_DIR/info.log bs=1M count=50 && \
+  $TOUCH -d "24 hours ago" $TARGET_DIR/info.log 
+#./gradlew run && \
+#du -hs logs/*
diff --git a/logback-classic/src/test/java/ch/qos/logback/classic/joran/JoranConfiguratorTest.java b/logback-classic/src/test/java/ch/qos/logback/classic/joran/JoranConfiguratorTest.java
@@ -440,4 +440,13 @@ public void valueOfConvention() throws JoranException {
         configure(configFileAsStr);
         checker.assertIsWarningOrErrorFree();
     }
+
+    @Test
+    public void shutdownHookTest() throws JoranException {
+        String configFileAsStr = ClassicTestConstants.JORAN_INPUT_PREFIX + "issues/logback_1162.xml";
+        loggerContext.putProperty("output_dir", ClassicTestConstants.OUTPUT_DIR_PREFIX+"logback_issue_1162/");
+        configure(configFileAsStr);
+        assertNotNull(loggerContext.getObject(CoreConstants.SHUTDOWN_HOOK_THREAD));
+    }
+
 }
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
@@ -166,8 +166,8 @@ public boolean isStarted() {
     }
 
     /**
-     * Clear the internal objectMap and all properties. Removes registered
-     * shutdown hook
+     * Clear the internal objectMap and all properties. Removes any registered
+     * shutdown hook.
      */
     public void reset() {
 

diff --git a/...gback/core/hook/DelayingShutdownHook.java → ...ogback/core/hook/DefaultShutdownHook.java b/...gback/core/hook/DelayingShutdownHook.java → ...ogback/core/hook/DefaultShutdownHook.java
@@ -16,12 +16,14 @@
 import ch.qos.logback.core.util.Duration;
 
 /**
- * ShutdownHook implementation that stops the Logback context after a specified
+ * ShutdownHook implementation that <b>stops</b> the Logback context after a specified
  * delay.  The default delay is 0 ms (zero).
+ * 
+ * <p>Stopping the logback context
  *
  * @author Mike Reinhold
  */
-public class DelayingShutdownHook extends ShutdownHookBase {
+public class DefaultShutdownHook extends ShutdownHookBase {
     /**
      * The default is no delay before shutdown.
      */
@@ -32,7 +34,7 @@ public class DelayingShutdownHook extends ShutdownHookBase {
      */
     private Duration delay = DEFAULT_DELAY;
 
-    public DelayingShutdownHook() {
+    public DefaultShutdownHook() {
     }
 
     public Duration getDelay() {
@@ -49,10 +51,12 @@ public void setDelay(Duration delay) {
     }
 
     public void run() {
-        addInfo("Sleeping for "+delay);
-        try {
-            Thread.sleep(delay.getMilliseconds());
-        } catch (InterruptedException e) {
+        if (delay.getMilliseconds() > 0) {
+            addInfo("Sleeping for " + delay);
+            try {
+                Thread.sleep(delay.getMilliseconds());
+            } catch (InterruptedException e) {
+            }
         }
         super.stop();
     }

diff --git a/logback-core/src/main/java/ch/qos/logback/core/joran/action/ShutdownHookAction.java b/logback-core/src/main/java/ch/qos/logback/core/joran/action/ShutdownHookAction.java
@@ -16,6 +16,7 @@
 import org.xml.sax.Attributes;
 
 import ch.qos.logback.core.CoreConstants;
+import ch.qos.logback.core.hook.DefaultShutdownHook;
 import ch.qos.logback.core.hook.ShutdownHookBase;
 import ch.qos.logback.core.joran.spi.ActionException;
 import ch.qos.logback.core.joran.spi.InterpretationContext;
@@ -44,9 +45,8 @@ public void begin(InterpretationContext ic, String name, Attributes attributes)
 
         String className = attributes.getValue(CLASS_ATTRIBUTE);
         if (OptionHelper.isEmpty(className)) {
-            addError("Missing class name for shutdown hook. Near [" + name + "] line " + getLineNumber(ic));
-            inError = true;
-            return;
+            className = DefaultShutdownHook.class.getName();
+            addInfo("Assuming className [" + className + "]");
         }
 
         try {
@@ -80,7 +80,7 @@ public void end(InterpretationContext ic, String name) throws ActionException {
             ic.popObject();
 
             Thread hookThread = new Thread(hook, "Logback shutdown hook [" + context.getName() + "]");
-
+            addInfo("Registeting shuthown hook with JVM runtime.");
             context.putObject(CoreConstants.SHUTDOWN_HOOK_THREAD, hookThread);
             Runtime.getRuntime().addShutdownHook(hookThread);
         }

diff --git a/logback-core/src/main/java/ch/qos/logback/core/rolling/helper/Compressor.java b/logback-core/src/main/java/ch/qos/logback/core/rolling/helper/Compressor.java
@@ -27,6 +27,7 @@
 import ch.qos.logback.core.rolling.RolloverFailure;
 import ch.qos.logback.core.spi.ContextAwareBase;
 import ch.qos.logback.core.status.ErrorStatus;
+import ch.qos.logback.core.status.InfoStatus;
 import ch.qos.logback.core.status.WarnStatus;
 import ch.qos.logback.core.util.FileUtil;
 
@@ -94,11 +95,8 @@ private void zipCompress(String nameOfFile2zip, String nameOfZippedFile, String
         addInfo("ZIP compressing [" + file2zip + "] as [" + zippedFile + "]");
         createMissingTargetDirsIfNecessary(zippedFile);
 
-        BufferedInputStream bis = null;
-        ZipOutputStream zos = null;
-        try {
-            bis = new BufferedInputStream(new FileInputStream(nameOfFile2zip));
-            zos = new ZipOutputStream(new FileOutputStream(nameOfZippedFile));
+        try (BufferedInputStream bis = new BufferedInputStream(new FileInputStream(nameOfFile2zip));
+                        ZipOutputStream zos = new ZipOutputStream(new FileOutputStream(nameOfZippedFile))) {
 
             ZipEntry zipEntry = computeZipEntry(innerEntryName);
             zos.putNextEntry(zipEntry);
@@ -110,33 +108,13 @@ private void zipCompress(String nameOfFile2zip, String nameOfZippedFile, String
                 zos.write(inbuf, 0, n);
             }
 
-            bis.close();
-            bis = null;
-            zos.close();
-            zos = null;
-
-            if (!file2zip.delete()) {
-                addStatus(new WarnStatus("Could not delete [" + nameOfFile2zip + "].", this));
-            }
+            addInfo("Done ZIP compressing [" + file2zip + "] as [" + zippedFile + "]");
         } catch (Exception e) {
             addStatus(new ErrorStatus("Error occurred while compressing [" + nameOfFile2zip + "] into [" + nameOfZippedFile + "].", this, e));
-        } finally {
-            if (bis != null) {
-                try {
-                    bis.close();
-                } catch (IOException e) {
-                    // ignore
-                }
-            }
-            if (zos != null) {
-                try {
-                    zos.close();
-                } catch (IOException e) {
-                    // ignore
-                }
-            }
         }
-
+        if (!file2zip.delete()) {
+            addStatus(new WarnStatus("Could not delete [" + nameOfFile2zip + "].", this));
+        }
     }
 
     // http://jira.qos.ch/browse/LBCORE-98
@@ -186,44 +164,25 @@ private void gzCompress(String nameOfFile2gz, String nameOfgzedFile) {
         addInfo("GZ compressing [" + file2gz + "] as [" + gzedFile + "]");
         createMissingTargetDirsIfNecessary(gzedFile);
 
-        BufferedInputStream bis = null;
-        GZIPOutputStream gzos = null;
-        try {
-            bis = new BufferedInputStream(new FileInputStream(nameOfFile2gz));
-            gzos = new GZIPOutputStream(new FileOutputStream(nameOfgzedFile));
+        try (BufferedInputStream bis = new BufferedInputStream(new FileInputStream(nameOfFile2gz));
+                        GZIPOutputStream gzos = new GZIPOutputStream(new FileOutputStream(nameOfgzedFile))) {
+
             byte[] inbuf = new byte[BUFFER_SIZE];
             int n;
 
             while ((n = bis.read(inbuf)) != -1) {
                 gzos.write(inbuf, 0, n);
             }
 
-            bis.close();
-            bis = null;
-            gzos.close();
-            gzos = null;
-
-            if (!file2gz.delete()) {
-                addStatus(new WarnStatus("Could not delete [" + nameOfFile2gz + "].", this));
-            }
+            addInfo("Done ZIP compressing [" + file2gz + "] as [" + gzedFile + "]");
         } catch (Exception e) {
             addStatus(new ErrorStatus("Error occurred while compressing [" + nameOfFile2gz + "] into [" + nameOfgzedFile + "].", this, e));
-        } finally {
-            if (bis != null) {
-                try {
-                    bis.close();
-                } catch (IOException e) {
-                    // ignore
-                }
-            }
-            if (gzos != null) {
-                try {
-                    gzos.close();
-                } catch (IOException e) {
-                    // ignore
-                }
-            }
         }
+
+        if (!file2gz.delete()) {
+            addStatus(new WarnStatus("Could not delete [" + nameOfFile2gz + "].", this));
+        }
+
     }
 
     static public String computeFileNameStrWithoutCompSuffix(String fileNamePatternStr, CompressionMode compressionMode) {
@@ -251,21 +210,19 @@ void createMissingTargetDirsIfNecessary(File file) {
             addError("Failed to create parent directories for [" + file.getAbsolutePath() + "]");
         }
     }
-    
+
     @Override
     public String toString() {
         return this.getClass().getName();
     }
 
-
     public Future<?> asyncCompress(String nameOfFile2Compress, String nameOfCompressedFile, String innerEntryName) throws RolloverFailure {
         CompressionRunnable runnable = new CompressionRunnable(nameOfFile2Compress, nameOfCompressedFile, innerEntryName);
         ExecutorService executorService = context.getScheduledExecutorService();
         Future<?> future = executorService.submit(runnable);
         return future;
     }
 
-
     class CompressionRunnable implements Runnable {
         final String nameOfFile2Compress;
         final String nameOfCompressedFile;
@@ -278,10 +235,9 @@ public CompressionRunnable(String nameOfFile2Compress, String nameOfCompressedFi
         }
 
         public void run() {
-            
+
             Compressor.this.compress(nameOfFile2Compress, nameOfCompressedFile, innerEntryName);
         }
     }
 
-
 }
diff --git a/...ck-core/src/test/java/ch/qos/logback/core/rolling/JVMExitBeforeCompressionISDoneTest.java b/...ck-core/src/test/java/ch/qos/logback/core/rolling/JVMExitBeforeCompressionISDoneTest.java
@@ -13,7 +13,7 @@
 
 import ch.qos.logback.core.CoreConstants;
 import ch.qos.logback.core.encoder.EchoEncoder;
-import ch.qos.logback.core.hook.DelayingShutdownHook;
+import ch.qos.logback.core.hook.DefaultShutdownHook;
 import ch.qos.logback.core.rolling.testUtil.ScaffoldingForRollingTests;
 import ch.qos.logback.core.status.OnConsoleStatusListener;
 import ch.qos.logback.core.testUtil.RandomUtil;
@@ -24,7 +24,7 @@ public class JVMExitBeforeCompressionISDoneTest extends ScaffoldingForRollingTes
 
     RollingFileAppender<Object> rfa = new RollingFileAppender<Object>();
     TimeBasedRollingPolicy<Object> tbrp = new TimeBasedRollingPolicy<Object>();
-    DelayingShutdownHook delayingShutdownHook = new DelayingShutdownHook();
+    DefaultShutdownHook delayingShutdownHook = new DefaultShutdownHook();
 
     static final long FRI_2016_05_13_T_170415_GMT = 1463159055630L;
 

diff --git a/logback-site/src/site/pages/manual/configuration.html b/logback-site/src/site/pages/manual/configuration.html
@@ -763,8 +763,8 @@ <h2 class="doAnchor" name="stopContext">Stopping
    <p>In order to release the resources used by logback-classic, it is
    always a good idea to stop the logback context. Stopping the
    context will close all appenders attached to loggers defined by the
-   context and stop any active threads.
-   </p>
+   context and stop any active threads in an orderly way. Please also
+   read the section on "shutdown hooks" just below.</p>
 
 <pre class="prettyprint lang-java source">
 import org.sflf4j.LoggerFactory;
@@ -788,25 +788,37 @@ <h4 class="doAnchor" name="shutdownHook">Stopping logback-classic
    via a shutdown hook</h4>
 
    <p>Installing a JVM shutdown hook is a convenient way for shutting
-   down logback and releasing associated resources.
+   down logback and releasing associated resources. 
    </p>
 
 
    <pre class="prettyprint source">&lt;configuration debug="true">
    &lt;!-- in the absence of the class attribute, assume 
-   ch.qos.logback.core.hook.DelayingShutdownHook --&gt;
+   ch.qos.logback.core.hook.DefaultShutdownHook --&gt;
    <b>&lt;shutdownHook/></b>
   .... 
 &lt;/configuration></pre>
-
+
+   <p>Note that you may install a shutdown hook of your own making by
+   setting the <span class="attr">class</span> attribute to correspond
+   to your shutdown hook's class name.</p>
+
    <p>The default shutdown hook, namely <a
-   href="../apidocs/ch/qos/logback/core/hook/DelayingShutdownHook.html">DelayingShutdownHook</a>,
-   can delay shutdown by a user specified duration. Note that you may
-   install a shutdown hook of your own making by setting the <span
-   class="attr">class</span> attribute to correspond to your shutdown
-   hook's class name.</p>
+   href="../apidocs/ch/qos/logback/core/hook/DefaultShutdownHook.html">DefaultShutdownHook</a>,
+   will <b>stop</b> the logback context after a specified delay (0 by
+   default). Stopping the context will allow up to 30 seconds for any
+   log file compression tasks running in the background to finish. In
+   standalone Java applications, adding a
+   <code>&lt;shutdownHook/></code> directive to your configuration
+   file is an easy way to ensure that any ongoing compression tasks
+   are allowed to finish before JVM exit. In applications within a Web
+   server, <a href="#webShutdownHook">webShutdownHook</a> will be
+   installed automatically making <code>&lt;shutdownHook/></code>
+   directive quite redundant and unnecessary. </p>
+
 
-    <h4 class="doAnchor" name="webShutdownHook">Stopping logback-classic 
+
+    <h4 class="doAnchor" name="webShutdownHook">WebShutdownHook or stopping logback-classic 
    in web-applications</h4>
 
    <p><span class="label">since 1.1.10</span> Logback-classic will