From 65820cf1d1c7c8c12b143c2a5aa6d3d3f6048479 Mon Sep 17 00:00:00 2001 From: =?utf8?q?S=C3=A9bastien=20Lesaint?= Date: Wed, 10 Feb 2016 12:06:07 +0100 Subject: [PATCH] SONAR-7311 fix file leak because CE appenders are closed too late --- .../server/computation/log/CeLogging.java | 22 +- .../server/computation/log/CeLoggingTest.java | 195 +++++++++++++++--- 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 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 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 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> 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> allAppenders = getAllAppenders(rootLogger); + assertThat(allAppenders).isEmpty(); + } + + private void verifyAllAppenderStarted(Logger rootLogger, int expectedSize) { + Collection> allAppenders = getAllAppenders(rootLogger); + assertThat(allAppenders).hasSize(expectedSize); + for (Appender appender : allAppenders) { + assertThat(appender.isStarted()).isTrue(); + } + } + + private Appender verifySingleAppenderIsStopped(Logger rootLogger, int expectedSize) { + Collection> allAppenders = getAllAppenders(rootLogger); + assertThat(allAppenders).hasSize(expectedSize); + Appender res = null; + for (Appender 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> getAllAppenders(Logger rootLogger) { + Appender 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(); + } } -- 2.39.5