SONAR-7311 fix file leak because CE appenders are closed too late

2 files changed, 187 insertions, 30 deletions

diff --git a/server/sonar-server/src/main/java/org/sonar/server/computation/log/CeLogging.java b/server/sonar-server/src/main/java/org/sonar/server/computation/log/CeLogging.java
index 948949af205..1b746df41ea 100644
--- a/server/sonar-server/src/main/java/org/sonar/server/computation/log/CeLogging.java
+++ b/server/sonar-server/src/main/java/org/sonar/server/computation/log/CeLogging.java
@@ -19,11 +19,14 @@
  */
 package org.sonar.server.computation.log;
 
+import ch.qos.logback.classic.Logger;
 import ch.qos.logback.classic.LoggerContext;
 import ch.qos.logback.classic.sift.MDCBasedDiscriminator;
 import ch.qos.logback.classic.sift.SiftingAppender;
 import ch.qos.logback.classic.spi.ILoggingEvent;
 import ch.qos.logback.core.Appender;
+import ch.qos.logback.core.sift.AppenderTracker;
+import ch.qos.logback.core.util.Duration;
 import com.google.common.annotations.VisibleForTesting;
 import com.google.common.base.Optional;
 import java.io.File;
@@ -34,11 +37,13 @@ import org.apache.commons.io.comparator.LastModifiedFileComparator;
 import org.apache.commons.io.filefilter.FileFilterUtils;
 import org.apache.log4j.MDC;
 import org.sonar.api.config.Settings;
+import org.sonar.process.LogbackHelper;
 import org.sonar.process.ProcessProperties;
 import org.sonar.process.Props;
 import org.sonar.server.computation.queue.CeTask;
 
 import static com.google.common.base.Preconditions.checkArgument;
+import static com.google.common.base.Preconditions.checkState;
 import static com.google.common.collect.FluentIterable.from;
 import static com.google.common.collect.Lists.newArrayList;
 import static java.lang.String.format;
@@ -52,10 +57,16 @@ import static java.lang.String.format;
  */
 public class CeLogging {
 
+  private static final long TIMEOUT_2_MINUTES = 1000 * 60 * 2L;
+  private static final String CE_APPENDER_NAME = "ce";
+  // using 0L as timestamp when retrieving appender to stop it will make it instantly eligible for removal
+  private static final long STOPPING_TRACKER_TIMESTAMP = 0L;
+
   @VisibleForTesting
   static final String MDC_LOG_PATH = "ceLogPath";
   public static final String MAX_LOGS_PROPERTY = "sonar.ce.maxLogsPerTask";
 
+  private final LogbackHelper helper = new LogbackHelper();
   private final File logsDir;
   private final Settings settings;
 
@@ -107,10 +118,18 @@ public class CeLogging {
     MDC.remove(MDC_LOG_PATH);
 
     if (relativePath != null) {
+      stopAppender(relativePath);
       purgeDir(new File(logsDir, relativePath).getParentFile());
     }
   }
 
+  private void stopAppender(String relativePath) {
+    Appender<ILoggingEvent> appender = helper.getRootContext().getLogger(Logger.ROOT_LOGGER_NAME).getAppender(CE_APPENDER_NAME);
+    checkState(appender instanceof SiftingAppender, "Appender with name %s is null or not a SiftingAppender", CE_APPENDER_NAME);
+    AppenderTracker<ILoggingEvent> ceAppender = ((SiftingAppender) appender).getAppenderTracker();
+    ceAppender.getOrCreate(relativePath, STOPPING_TRACKER_TIMESTAMP).stop();
+  }
+
   @VisibleForTesting
   void purgeDir(File dir) {
     if (dir.exists()) {
@@ -161,7 +180,8 @@ public class CeLogging {
     siftingAppender.setContext(ctx);
     siftingAppender.setDiscriminator(mdcDiscriminator);
     siftingAppender.setAppenderFactory(new CeFileAppenderFactory(logsDir));
-    siftingAppender.setName("ce");
+    siftingAppender.setName(CE_APPENDER_NAME);
+    siftingAppender.setTimeout(new Duration(TIMEOUT_2_MINUTES));
     siftingAppender.start();
     return siftingAppender;
   }
diff --git a/server/sonar-server/src/test/java/org/sonar/server/computation/log/CeLoggingTest.java b/server/sonar-server/src/test/java/org/sonar/server/computation/log/CeLoggingTest.java
index d10df360754..7df4d130dc6 100644
--- a/server/sonar-server/src/test/java/org/sonar/server/computation/log/CeLoggingTest.java
+++ b/server/sonar-server/src/test/java/org/sonar/server/computation/log/CeLoggingTest.java
@@ -19,38 +19,65 @@
  */
 package org.sonar.server.computation.log;
 
+import ch.qos.logback.classic.Logger;
 import ch.qos.logback.classic.LoggerContext;
 import ch.qos.logback.classic.sift.SiftingAppender;
 import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.Appender;
 import ch.qos.logback.core.filter.Filter;
+import ch.qos.logback.core.joran.spi.JoranException;
 import com.google.common.base.Optional;
 import java.io.File;
 import java.io.IOException;
+import java.util.Collection;
 import java.util.List;
 import org.apache.commons.io.FileUtils;
+import org.junit.After;
+import org.junit.Before;
 import org.junit.Rule;
 import org.junit.Test;
 import org.junit.rules.ExpectedException;
 import org.junit.rules.TemporaryFolder;
+import org.slf4j.LoggerFactory;
 import org.slf4j.MDC;
 import org.sonar.api.config.Settings;
+import org.sonar.process.LogbackHelper;
 import org.sonar.process.ProcessProperties;
 import org.sonar.server.computation.queue.CeTask;
 
 import static java.lang.String.format;
 import static org.assertj.core.api.Assertions.assertThat;
+import static org.mockito.Mockito.mock;
+import static org.mockito.Mockito.when;
+import static org.sonar.server.computation.log.CeLogging.MDC_LOG_PATH;
 
 public class CeLoggingTest {
 
   @Rule
   public ExpectedException expectedException = ExpectedException.none();
-
   @Rule
   public TemporaryFolder temp = new TemporaryFolder();
 
+  private LogbackHelper helper = new LogbackHelper();
+  private File dataDir;
+
+  @Before
+  public void setUp() throws Exception {
+    this.dataDir = temp.newFolder();
+  }
+
+  @After
+  public void resetLogback() throws JoranException {
+    helper.resetFromXml("/logback-test.xml");
+  }
+
+  @After
+  public void cleanMDC() throws Exception {
+    MDC.clear();
+  }
+
   @Test
   public void getFile() throws IOException {
-    File dataDir = temp.newFolder();
     Settings settings = newSettings(dataDir, 10);
 
     CeLogging underTest = new CeLogging(settings);
@@ -73,57 +100,124 @@ public class CeLoggingTest {
   }
 
   @Test
-  public void use_MDC_to_store_path_to_in_progress_task_logs() throws IOException {
-    CeLogging underTest = new CeLogging(newSettings(temp.newFolder(), 5));
+  public void initForTask_adds_path_of_ce_log_file_in_MDC() throws IOException {
+    CeLogging underTest = new CeLogging(newSettings(dataDir, 5));
+
+    CeTask task = createCeTask("TYPE1", "U1");
+    underTest.initForTask(task);
+    assertThat(MDC.get(MDC_LOG_PATH)).isNotEmpty().isEqualTo(LogFileRef.from(task).getRelativePath());
+  }
+
+  @Test
+  public void clearForTask_throws_ISE_if_CE_appender_is_not_configured() throws IOException {
+    CeLogging underTest = new CeLogging(newSettings(dataDir, 5));
+
+    CeTask task = createCeTask("TYPE1", "U1");
+    underTest.initForTask(task);
+
+    expectedException.expect(IllegalStateException.class);
+    expectedException.expectMessage("Appender with name ce is null or not a SiftingAppender");
+
+    underTest.clearForTask();
+  }
+
+  @Test
+  public void clearForTask_throws_ISE_if_CE_appender_is_not_a_SiftingAppender() throws IOException {
+    Appender<ILoggingEvent> mockCeAppender = mock(Appender.class);
+    when(mockCeAppender.getName()).thenReturn("ce");
+    helper.getRootContext().getLogger(Logger.ROOT_LOGGER_NAME).addAppender(mockCeAppender);
+
+    CeLogging underTest = new CeLogging(newSettings(dataDir, 5));
+
+    CeTask task = createCeTask("TYPE1", "U1");
+    underTest.initForTask(task);
+
+    expectedException.expect(IllegalStateException.class);
+    expectedException.expectMessage("Appender with name ce is null or not a SiftingAppender");
+
+    underTest.clearForTask();
+  }
+
+  @Test
+  public void clearForTask_clears_MDC() throws IOException {
+    setupCeAppender();
 
-    CeTask task = new CeTask.Builder().setType("TYPE1").setUuid("U1").build();
+    CeLogging underTest = new CeLogging(newSettings(dataDir, 5));
+
+    CeTask task = createCeTask("TYPE1", "U1");
     underTest.initForTask(task);
-    assertThat(MDC.get(CeLogging.MDC_LOG_PATH)).isNotEmpty().isEqualTo(LogFileRef.from(task).getRelativePath());
+    assertThat(MDC.get(MDC_LOG_PATH)).isNotEmpty().isEqualTo(LogFileRef.from(task).getRelativePath());
+
+    underTest.clearForTask();
+    assertThat(MDC.get(MDC_LOG_PATH)).isNull();
+  }
+
+  @Test
+  public void cleanForTask_stops_only_appender_for_MDC_value() throws IOException {
+    Logger rootLogger = setupCeAppender();
+
+    CeLogging underTest = new CeLogging(newSettings(dataDir, 5));
+
+    // init MDC
+    underTest.initForTask(createCeTask("TYPE1", "U1"));
+    verifyNoAppender(rootLogger);
+
+    // logging will create and start the appender
+    LoggerFactory.getLogger(getClass()).info("some log!");
+    verifyAllAppenderStarted(rootLogger, 1);
+
+    // init MDC and create appender for another task
+    // (in the same thread, which should not happen, but it's good enough for our test)
+    CeTask ceTask = createCeTask("TYPE1", "U2");
+    underTest.initForTask(ceTask);
+    LoggerFactory.getLogger(getClass()).info("some other log!");
+    verifyAllAppenderStarted(rootLogger, 2);
+
+    // stop appender which is currently referenced in MDC
     underTest.clearForTask();
-    assertThat(MDC.get(CeLogging.MDC_LOG_PATH)).isNull();
+
+    Appender appender = verifySingleAppenderIsStopped(rootLogger, 2);
+    assertThat(appender.getName()).isEqualTo("ce-" + LogFileRef.from(ceTask).getRelativePath());
   }
 
   @Test
   public void delete_oldest_files_of_same_directory_to_keep_only_max_allowed_files() throws IOException {
-    File dir = temp.newFolder();
     for (int i = 1; i <= 5; i++) {
-      File file = new File(dir, format("U%d.log", i));
+      File file = new File(dataDir, format("U%d.log", i));
       FileUtils.touch(file);
       // see javadoc: "all platforms support file-modification times to the nearest second,
       // but some provide more precision" --> increment by second, not by millisecond
       file.setLastModified(1_450_000_000_000L + i * 1000);
     }
-    assertThat(dir.listFiles()).hasSize(5);
+    assertThat(dataDir.listFiles()).hasSize(5);
 
     // keep 3 files in each dir
-    CeLogging underTest = new CeLogging(newSettings(dir, 3));
-    underTest.purgeDir(dir);
+    CeLogging underTest = new CeLogging(newSettings(dataDir, 3));
+    underTest.purgeDir(dataDir);
 
-    assertThat(dir.listFiles()).hasSize(3);
-    assertThat(dir.listFiles()).extracting("name")
+    assertThat(dataDir.listFiles()).hasSize(3);
+    assertThat(dataDir.listFiles()).extracting("name")
       .containsOnly("U3.log", "U4.log", "U5.log");
   }
 
   @Test
   public void do_not_delete_files_if_dir_has_less_files_than_max_allowed() throws IOException {
-    File dir = temp.newFolder();
-    FileUtils.touch(new File(dir, "U1.log"));
+    FileUtils.touch(new File(dataDir, "U1.log"));
 
-    CeLogging underTest = new CeLogging(newSettings(dir, 5));
-    underTest.purgeDir(dir);
+    CeLogging underTest = new CeLogging(newSettings(dataDir, 5));
+    underTest.purgeDir(dataDir);
 
-    assertThat(dir.listFiles()).extracting("name").containsOnly("U1.log");
+    assertThat(dataDir.listFiles()).extracting("name").containsOnly("U1.log");
   }
 
   @Test
   public void do_not_keep_any_logs() throws IOException {
-    File dir = temp.newFolder();
-    FileUtils.touch(new File(dir, "U1.log"));
+    FileUtils.touch(new File(dataDir, "U1.log"));
 
-    CeLogging underTest = new CeLogging(newSettings(temp.newFolder(), 0));
-    underTest.purgeDir(dir);
+    CeLogging underTest = new CeLogging(newSettings(dataDir, 0));
+    underTest.purgeDir(dataDir);
 
-    assertThat(dir.listFiles()).isEmpty();
+    assertThat(dataDir.listFiles()).isEmpty();
   }
 
   @Test
@@ -131,22 +225,61 @@ public class CeLoggingTest {
     expectedException.expect(IllegalArgumentException.class);
     expectedException.expectMessage("Property sonar.ce.maxLogsPerTask must be positive. Got: -1");
 
-    Settings settings = newSettings(temp.newFolder(), -1);
+    Settings settings = newSettings(dataDir, -1);
     CeLogging logging = new CeLogging(settings);
-    logging.purgeDir(temp.newFolder());
+    logging.purgeDir(dataDir);
   }
 
   @Test
   public void createConfiguration() throws Exception {
-    File logsDir = temp.newFolder();
-    SiftingAppender siftingAppender = CeLogging.createAppenderConfiguration(new LoggerContext(), logsDir);
+    SiftingAppender siftingAppender = CeLogging.createAppenderConfiguration(new LoggerContext(), dataDir);
 
     // filter on CE logs
     List<Filter<ILoggingEvent>> filters = siftingAppender.getCopyOfAttachedFiltersList();
     assertThat(filters).hasSize(1);
     assertThat(filters.get(0)).isInstanceOf(CeLogAcceptFilter.class);
 
-    assertThat(siftingAppender.getDiscriminator().getKey()).isEqualTo(CeLogging.MDC_LOG_PATH);
+    assertThat(siftingAppender.getDiscriminator().getKey()).isEqualTo(MDC_LOG_PATH);
+    assertThat(siftingAppender.getTimeout().getMilliseconds()).isEqualTo(1000 * 60 * 2);
+  }
+
+  private Logger setupCeAppender() {
+    Logger rootLogger = helper.getRootContext().getLogger(Logger.ROOT_LOGGER_NAME);
+    rootLogger.addAppender(CeLogging.createAppenderConfiguration(helper.getRootContext(), dataDir));
+    return rootLogger;
+  }
+
+  private void verifyNoAppender(Logger rootLogger) {
+    Collection<Appender<ILoggingEvent>> allAppenders = getAllAppenders(rootLogger);
+    assertThat(allAppenders).isEmpty();
+  }
+
+  private void verifyAllAppenderStarted(Logger rootLogger, int expectedSize) {
+    Collection<Appender<ILoggingEvent>> allAppenders = getAllAppenders(rootLogger);
+    assertThat(allAppenders).hasSize(expectedSize);
+    for (Appender<ILoggingEvent> appender : allAppenders) {
+      assertThat(appender.isStarted()).isTrue();
+    }
+  }
+
+  private Appender verifySingleAppenderIsStopped(Logger rootLogger, int expectedSize) {
+    Collection<Appender<ILoggingEvent>> allAppenders = getAllAppenders(rootLogger);
+    assertThat(allAppenders).hasSize(expectedSize);
+    Appender res = null;
+    for (Appender<ILoggingEvent> appender : allAppenders) {
+      if (!appender.isStarted()) {
+        assertThat(res).describedAs("More than one appender found stopped").isNull();
+        res = appender;
+      }
+    }
+    assertThat(res).describedAs("There should be one stopped appender").isNotNull();
+    return res;
+  }
+
+  private Collection<Appender<ILoggingEvent>> getAllAppenders(Logger rootLogger) {
+    Appender<ILoggingEvent> ceAppender = rootLogger.getAppender("ce");
+    assertThat(ceAppender).isInstanceOf(SiftingAppender.class);
+    return ((SiftingAppender) ceAppender).getAppenderTracker().allComponents();
   }
 
   private static Settings newSettings(File dataDir, int maxLogs) {
@@ -155,4 +288,8 @@ public class CeLoggingTest {
     settings.setProperty(CeLogging.MAX_LOGS_PROPERTY, maxLogs);
     return settings;
   }
+
+  private static CeTask createCeTask(String type, String uuid) {
+    return new CeTask.Builder().setType(type).setUuid(uuid).build();
+  }
 }