mirrors
/
sonarqube
mirror of https://github.com/SonarSource/sonarqube.git
Watch 1
Star 0
Fork 0
Code Issues 0 Releases 237 Wiki Activity
Browse Source

SONAR-7841 Compute Engine logs in sonar.log + step timing are DEBUG

tags/6.1-RC1
Sébastien Lesaint 7 years ago
parent
df1ae26b7c
commit
657bb8e40b
12 changed files with 162 additions and 317 deletions
Split View Show Diff Stats
  1. 0
    57
      server/sonar-server/src/main/java/org/sonar/ce/log/CeLogging.java
  2. 0
    1
      server/sonar-server/src/main/java/org/sonar/ce/log/CeProcessLogging.java
  3. 16
    4
      server/sonar-server/src/main/java/org/sonar/server/computation/task/projectanalysis/component/VisitorsCrawler.java
  4. 9
    10
      server/sonar-server/src/main/java/org/sonar/server/computation/task/projectanalysis/step/ExecuteVisitorsStep.java
  5. 4
    7
      server/sonar-server/src/main/java/org/sonar/server/computation/task/step/ComputationStepExecutor.java
  6. 5
    5
      server/sonar-server/src/main/java/org/sonar/server/computation/taskprocessor/CeWorkerCallableImpl.java
  7. 0
    197
      server/sonar-server/src/test/java/org/sonar/ce/log/CeLoggingTest.java
  8. 40
    0
      server/sonar-server/src/test/java/org/sonar/server/computation/task/ChangeLogLevel.java
  9. 18
    1
      server/sonar-server/src/test/java/org/sonar/server/computation/task/projectanalysis/component/ReportVisitorsCrawlerTest.java
  10. 19
    2
      server/sonar-server/src/test/java/org/sonar/server/computation/task/projectanalysis/component/ViewsVisitorsCrawlerTest.java
  11. 20
    22
      server/sonar-server/src/test/java/org/sonar/server/computation/task/projectanalysis/step/ExecuteVisitorsStepTest.java
  12. 31
    11
      server/sonar-server/src/test/java/org/sonar/server/computation/task/step/ComputationStepExecutorTest.java

+ 0
- 57
server/sonar-server/src/main/java/org/sonar/ce/log/CeLogging.java View File

@@ -19,31 +19,11 @@
*/
package org.sonar.ce.log;

import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.encoder.PatternLayoutEncoder;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.Appender;
import ch.qos.logback.core.FileAppender;
import java.util.function.Supplier;
import org.apache.log4j.MDC;
import org.sonar.api.utils.log.Logger;
import org.sonar.ce.queue.CeTask;
import org.sonar.process.LogbackHelper;
import org.sonar.process.Props;

/**
* Manages the logs written by Compute Engine:
* <ul>
* <li>access to existing logs</li>
* <li>configure logback when CE worker starts and stops processing a task</li>
* </ul>
*/
public class CeLogging {

private static final String CE_ACTIVITY_APPENDER_NAME = "ce_activity";
private static final String CE_ACTIVITY_FILE_NAME_PREFIX = "ce_activity";
private static final String CE_ACTIVITY_ENCODER_PATTERN = "%d{yyyy.MM.dd HH:mm:ss} %-5level [%X{ceTaskUuid}][%logger{20}] %msg%n";

static final String MDC_CE_ACTIVITY_FLAG = "ceActivityFlag";
static final String MDC_CE_TASK_UUID = "ceTaskUuid";

@@ -55,41 +35,4 @@ public class CeLogging {
MDC.remove(MDC_CE_TASK_UUID);
}

public void logCeActivity(Logger logger, Runnable logProducer) {
MDC.put(MDC_CE_ACTIVITY_FLAG, computeCeActivityFlag(logger));
try {
logProducer.run();
} finally {
MDC.remove(MDC_CE_ACTIVITY_FLAG);
}
}

public <T> T logCeActivity(Logger logger, Supplier<T> logProducer) {
MDC.put(MDC_CE_ACTIVITY_FLAG, computeCeActivityFlag(logger));
try {
return logProducer.get();
} finally {
MDC.remove(MDC_CE_ACTIVITY_FLAG);
}
}

private static String computeCeActivityFlag(Logger logger) {
return logger.isDebugEnabled() || logger.isTraceEnabled() ? "all" : "ce_only";
}

public static Appender<ILoggingEvent> createCeActivityAppenderConfiguration(LogbackHelper helper, LoggerContext ctx, Props processProps) {
LogbackHelper.RollingPolicy rollingPolicy = helper.createRollingPolicy(ctx, processProps, CE_ACTIVITY_FILE_NAME_PREFIX);
FileAppender<ILoggingEvent> fileAppender = rollingPolicy.createAppender(CE_ACTIVITY_APPENDER_NAME);
fileAppender.setContext(ctx);

PatternLayoutEncoder consoleEncoder = new PatternLayoutEncoder();
consoleEncoder.setContext(ctx);
consoleEncoder.setPattern(CE_ACTIVITY_ENCODER_PATTERN);
consoleEncoder.start();
fileAppender.setEncoder(consoleEncoder);
fileAppender.addFilter(new CeActivityLogAcceptFilter<>());
fileAppender.start();

return fileAppender;
}
}

+ 0
- 1
server/sonar-server/src/main/java/org/sonar/ce/log/CeProcessLogging.java View File

@@ -43,7 +43,6 @@ public class CeProcessLogging extends ServerProcessLogging {
protected void configureAppenders(String logFormat, LoggerContext ctx, LogbackHelper helper, Props props) {
ConsoleAppender<ILoggingEvent> consoleAppender = helper.newConsoleAppender(ctx, "CONSOLE", logFormat, new CeActivityLogConsoleFilter());
ctx.getLogger(ROOT_LOGGER_NAME).addAppender(consoleAppender);
ctx.getLogger(ROOT_LOGGER_NAME).addAppender(CeLogging.createCeActivityAppenderConfiguration(helper, ctx, props));
}

}

+ 16
- 4
server/sonar-server/src/main/java/org/sonar/server/computation/task/projectanalysis/component/VisitorsCrawler.java View File

@@ -23,6 +23,7 @@ import com.google.common.base.Function;
import com.google.common.base.Predicate;
import com.google.common.collect.ImmutableMap;
import com.google.common.collect.Maps;
import java.util.Collections;
import java.util.List;
import java.util.Map;
import javax.annotation.Nonnull;
@@ -39,21 +40,30 @@ import static java.util.Objects.requireNonNull;
*/
public class VisitorsCrawler implements ComponentCrawler {

private final boolean computeDuration;
private final Map<ComponentVisitor, VisitorDuration> visitorCumulativeDurations;
private final List<VisitorWrapper> preOrderVisitorWrappers;
private final List<VisitorWrapper> postOrderVisitorWrappers;

public VisitorsCrawler(Iterable<ComponentVisitor> visitors) {
this(visitors, false);
}

public VisitorsCrawler(Iterable<ComponentVisitor> visitors, boolean computeDuration) {
List<VisitorWrapper> visitorWrappers = from(visitors).transform(ToVisitorWrapper.INSTANCE).toList();
this.preOrderVisitorWrappers = from(visitorWrappers).filter(MathPreOrderVisitor.INSTANCE).toList();
this.postOrderVisitorWrappers = from(visitorWrappers).filter(MatchPostOrderVisitor.INSTANCE).toList();
this.visitorCumulativeDurations = from(visitors).toMap(VisitorWrapperToInitialDuration.INSTANCE);
this.computeDuration = computeDuration;
this.visitorCumulativeDurations = computeDuration ? from(visitors).toMap(VisitorWrapperToInitialDuration.INSTANCE) : Collections.emptyMap();
}

public Map<ComponentVisitor, Long> getCumulativeDurations() {
return ImmutableMap.copyOf(
Maps.transformValues(this.visitorCumulativeDurations, VisitorDurationToDuration.INSTANCE)
if (computeDuration) {
return ImmutableMap.copyOf(
Maps.transformValues(this.visitorCumulativeDurations, VisitorDurationToDuration.INSTANCE)
);
}
return Collections.emptyMap();
}

@Override
@@ -135,7 +145,9 @@ public class VisitorsCrawler implements ComponentCrawler {
}

private void incrementDuration(VisitorWrapper visitorWrapper, long duration) {
visitorCumulativeDurations.get(visitorWrapper.getWrappedVisitor()).increment(duration);
if (computeDuration) {
visitorCumulativeDurations.get(visitorWrapper.getWrappedVisitor()).increment(duration);
}
}

private enum ToVisitorWrapper implements Function<ComponentVisitor, VisitorWrapper> {

+ 9
- 10
server/sonar-server/src/main/java/org/sonar/server/computation/task/projectanalysis/step/ExecuteVisitorsStep.java View File

@@ -23,7 +23,6 @@ import java.util.List;
import java.util.Map;
import org.sonar.api.utils.log.Logger;
import org.sonar.api.utils.log.Loggers;
import org.sonar.ce.log.CeLogging;
import org.sonar.server.computation.task.projectanalysis.component.ComponentVisitor;
import org.sonar.server.computation.task.projectanalysis.component.TreeRootHolder;
import org.sonar.server.computation.task.projectanalysis.component.VisitorsCrawler;
@@ -35,12 +34,10 @@ public class ExecuteVisitorsStep implements ComputationStep {

private final TreeRootHolder treeRootHolder;
private final List<ComponentVisitor> visitors;
private final CeLogging ceLogging;

public ExecuteVisitorsStep(TreeRootHolder treeRootHolder, List<ComponentVisitor> visitors, CeLogging ceLogging) {
public ExecuteVisitorsStep(TreeRootHolder treeRootHolder, List<ComponentVisitor> visitors) {
this.treeRootHolder = treeRootHolder;
this.visitors = visitors;
this.ceLogging = ceLogging;
}

@Override
@@ -50,16 +47,18 @@ public class ExecuteVisitorsStep implements ComputationStep {

@Override
public void execute() {
VisitorsCrawler visitorsCrawler = new VisitorsCrawler(visitors);
VisitorsCrawler visitorsCrawler = new VisitorsCrawler(visitors, LOGGER.isDebugEnabled());
visitorsCrawler.visit(treeRootHolder.getRoot());
ceLogging.logCeActivity(LOGGER, () -> logVisitorExecutionDurations(visitors, visitorsCrawler));
logVisitorExecutionDurations(visitors, visitorsCrawler);
}

private static void logVisitorExecutionDurations(List<ComponentVisitor> visitors, VisitorsCrawler visitorsCrawler) {
LOGGER.info(" Execution time for each component visitor:");
Map<ComponentVisitor, Long> cumulativeDurations = visitorsCrawler.getCumulativeDurations();
for (ComponentVisitor visitor : visitors) {
LOGGER.info(" - {} | time={}ms", visitor.getClass().getSimpleName(), cumulativeDurations.get(visitor));
if (LOGGER.isDebugEnabled()) {
LOGGER.debug(" Execution time for each component visitor:");
Map<ComponentVisitor, Long> cumulativeDurations = visitorsCrawler.getCumulativeDurations();
for (ComponentVisitor visitor : visitors) {
LOGGER.debug(" - {} | time={}ms", visitor.getClass().getSimpleName(), cumulativeDurations.get(visitor));
}
}
}
}

+ 4
- 7
server/sonar-server/src/main/java/org/sonar/server/computation/task/step/ComputationStepExecutor.java View File

@@ -23,14 +23,12 @@ import javax.annotation.CheckForNull;
import javax.annotation.Nullable;
import org.sonar.api.utils.log.Logger;
import org.sonar.api.utils.log.Loggers;
import org.sonar.ce.log.CeLogging;
import org.sonar.core.util.logs.Profiler;

public final class ComputationStepExecutor {
private static final Logger LOGGER = Loggers.get(ComputationStepExecutor.class);

private final ComputationSteps steps;
private final CeLogging ceLogging;
@CheckForNull
private final Listener listener;

@@ -38,13 +36,12 @@ public final class ComputationStepExecutor {
* Used when no {@link ComputationStepExecutor.Listener} is available in pico
* container.
*/
public ComputationStepExecutor(ComputationSteps steps, CeLogging ceLogging) {
this(steps, ceLogging, null);
public ComputationStepExecutor(ComputationSteps steps) {
this(steps, null);
}

public ComputationStepExecutor(ComputationSteps steps, CeLogging ceLogging, @Nullable Listener listener) {
public ComputationStepExecutor(ComputationSteps steps, @Nullable Listener listener) {
this.steps = steps;
this.ceLogging = ceLogging;
this.listener = listener;
}

@@ -65,7 +62,7 @@ public final class ComputationStepExecutor {
for (ComputationStep step : steps.instances()) {
stepProfiler.start();
step.execute();
ceLogging.logCeActivity(LOGGER, () -> stepProfiler.stopInfo(step.getDescription()));
stepProfiler.stopDebug(step.getDescription());
}
}


+ 5
- 5
server/sonar-server/src/main/java/org/sonar/server/computation/taskprocessor/CeWorkerCallableImpl.java View File

@@ -97,18 +97,18 @@ public class CeWorkerCallableImpl implements CeWorkerCallable {
}
}

private Profiler startActivityProfiler(CeTask task) {
private static Profiler startActivityProfiler(CeTask task) {
Profiler profiler = Profiler.create(LOG);
addContext(profiler, task);
return ceLogging.logCeActivity(LOG, () -> profiler.startInfo("Execute task"));
return profiler.startInfo("Execute task");
}

private void stopActivityProfiler(Profiler profiler, CeTask task, CeActivityDto.Status status) {
private static void stopActivityProfiler(Profiler profiler, CeTask task, CeActivityDto.Status status) {
addContext(profiler, task);
if (status == CeActivityDto.Status.FAILED) {
ceLogging.logCeActivity(LOG, () -> profiler.stopError("Executed task"));
profiler.stopError("Executed task");
} else {
ceLogging.logCeActivity(LOG, () -> profiler.stopInfo("Executed task"));
profiler.stopInfo("Executed task");
}
}


+ 0
- 197
server/sonar-server/src/test/java/org/sonar/ce/log/CeLoggingTest.java View File

@@ -19,61 +19,28 @@
*/
package org.sonar.ce.log;

import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.encoder.PatternLayoutEncoder;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.Appender;
import ch.qos.logback.core.FileAppender;
import ch.qos.logback.core.filter.Filter;
import ch.qos.logback.core.joran.spi.JoranException;
import java.io.File;
import java.util.List;
import java.util.Properties;
import java.util.concurrent.atomic.AtomicBoolean;
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.mockito.Mockito;
import org.slf4j.MDC;
import org.sonar.api.utils.log.Logger;
import org.sonar.ce.queue.CeTask;
import org.sonar.process.LogbackHelper;
import org.sonar.process.ProcessProperties;
import org.sonar.process.Props;

import static ch.qos.logback.classic.Level.DEBUG;
import static ch.qos.logback.classic.Level.ERROR;
import static ch.qos.logback.classic.Level.INFO;
import static ch.qos.logback.classic.Level.TRACE;
import static ch.qos.logback.classic.Level.WARN;
import static junit.framework.TestCase.fail;
import static org.assertj.core.api.Assertions.assertThat;
import static org.mockito.Mockito.mock;
import static org.mockito.Mockito.when;
import static org.sonar.ce.log.CeLogging.MDC_CE_ACTIVITY_FLAG;
import static org.sonar.ce.log.CeLogging.MDC_CE_TASK_UUID;

public class CeLoggingTest {

@Rule
public ExpectedException expectedException = ExpectedException.none();
@Rule
public TemporaryFolder temp = new TemporaryFolder();

private LogbackHelper helper = new LogbackHelper();
private File logDir;

private CeLogging underTest = new CeLogging();

@Before
public void setUp() throws Exception {
this.logDir = temp.newFolder();
}

@After
public void resetLogback() throws JoranException {
helper.resetFromXml("/logback-test.xml");
@@ -108,168 +75,4 @@ public class CeLoggingTest {
assertThat(MDC.get(MDC_CE_TASK_UUID)).isNull();
}

@Test
public void createCeConfigurationConfiguration_fails_if_log_directory_is_not_set_in_Props() {
LogbackHelper helper = new LogbackHelper();
LoggerContext ctx = new LoggerContext();
Props processProps = new Props(new Properties());

expectedException.expect(IllegalArgumentException.class);
expectedException.expectMessage("Property sonar.path.logs is not set");

CeLogging.createCeActivityAppenderConfiguration(helper, ctx, processProps);
}

@Test
public void createCeConfigurationConfiguration() {
Properties props = new Properties();
props.setProperty(ProcessProperties.PATH_LOGS, logDir.getAbsolutePath());
Appender<ILoggingEvent> appender = CeLogging.createCeActivityAppenderConfiguration(new LogbackHelper(), new LoggerContext(), new Props(props));

// filter on CE logs
List<Filter<ILoggingEvent>> filters = appender.getCopyOfAttachedFiltersList();
assertThat(filters).hasSize(1);
assertThat(filters.get(0)).isInstanceOf(CeActivityLogAcceptFilter.class);

assertThat(appender).isInstanceOf(FileAppender.class);
assertThat(appender.getName()).isEqualTo("ce_activity");
FileAppender fileAppender = (FileAppender) appender;
assertThat(fileAppender.getEncoder())
.isInstanceOf(PatternLayoutEncoder.class);
assertThat(fileAppender.getFile()).isEqualTo(new File(logDir, "ce_activity.log").getAbsolutePath());
}

@Test
public void logCeActivity_of_Runnable_set_flag_in_MDC_to_ce_only_when_log_level_is_ERROR_and_calls_Runnable_and_remove_flag_even_if_Runnable_throws_exception() {
callLogCeActivityOfRunnableAndVerify("ce_only", ERROR);
callLogCeActivityOfFailingRunnableAndVerify("ce_only", ERROR);
}

@Test
public void logCeActivity_of_Runnable_set_flag_in_MDC_to_ce_only_when_log_level_is_WARN_and_calls_Runnable_and_remove_flag_even_if_Runnable_throws_exception() {
callLogCeActivityOfRunnableAndVerify("ce_only", WARN);
callLogCeActivityOfFailingRunnableAndVerify("ce_only", WARN);
}

@Test
public void logCeActivity_of_Runnable_set_flag_in_MDC_to_ce_only_when_log_level_is_INFO_and_calls_Runnable_and_remove_flag_even_if_Runnable_throws_exception() {
callLogCeActivityOfRunnableAndVerify("ce_only", INFO);
}

@Test
public void logCeActivity_of_Runnable_set_flag_in_MDC_to_all_when_log_level_is_DEBUG_and_calls_Runnable_and_remove_flag_even_if_Runnable_throws_exception() {
callLogCeActivityOfRunnableAndVerify("all", DEBUG);
callLogCeActivityOfFailingRunnableAndVerify("all", DEBUG);
}

@Test
public void logCeActivity_of_Runnable_set_flag_in_MDC_to_all_when_log_level_is_TRACE_and_calls_Runnable_and_remove_flag_even_if_Runnable_throws_exception() {
callLogCeActivityOfRunnableAndVerify("all", TRACE);
callLogCeActivityOfFailingRunnableAndVerify("all", TRACE);
}

private void callLogCeActivityOfRunnableAndVerify(String expectedMdcValue, Level logLevel) {
AtomicBoolean called = new AtomicBoolean(false);
underTest.logCeActivity(
createLogger(logLevel),
() -> {
assertThat(MDC.get(MDC_CE_ACTIVITY_FLAG)).isEqualTo(expectedMdcValue);
called.compareAndSet(false, true);
});
assertThat(MDC.get(MDC_CE_ACTIVITY_FLAG)).isNull();
assertThat(called.get()).isTrue();
}

private void callLogCeActivityOfFailingRunnableAndVerify(String expectedMdcValue, Level logLevel) {
RuntimeException exception = new RuntimeException("Simulates a failing Runnable");

AtomicBoolean called = new AtomicBoolean(false);
try {
underTest.logCeActivity(
createLogger(logLevel),
() -> {
assertThat(MDC.get(MDC_CE_ACTIVITY_FLAG)).isEqualTo(expectedMdcValue);
called.compareAndSet(false, true);
throw exception;
});
fail("exception should have been raised");
} catch (Exception e) {
assertThat(e).isSameAs(exception);
} finally {
assertThat(MDC.get(MDC_CE_ACTIVITY_FLAG)).isNull();
assertThat(called.get()).isTrue();
}
}

private static Logger createLogger(Level info) {
Logger logger = mock(Logger.class);
when(logger.isDebugEnabled()).thenReturn(DEBUG.isGreaterOrEqual(info));
when(logger.isTraceEnabled()).thenReturn(TRACE.isGreaterOrEqual(info));
return logger;
}

@Test
public void logCeActivity_of_Supplier_set_flag_in_MDC_to_ce_only_when_log_level_is_ERROR_and_calls_Supplier_and_remove_flag_even_if_Supplier_throws_exception() {
callLogCeActivityOfSupplierAndVerify(ERROR, "ce_only");
callLogCeActivityOfFailingSupplierAndVerify(ERROR, "ce_only");
}

@Test
public void logCeActivity_of_Supplier_set_flag_in_MDC_to_ce_only_when_log_level_is_WARN_and_calls_Supplier_and_remove_flag_even_if_Supplier_throws_exception() {
callLogCeActivityOfSupplierAndVerify(WARN, "ce_only");
callLogCeActivityOfFailingSupplierAndVerify(WARN, "ce_only");
}

@Test
public void logCeActivity_of_Supplier_set_flag_in_MDC_to_ce_only_when_log_level_is_INFO_and_calls_Supplier_and_remove_flag_even_if_Supplier_throws_exception() {
callLogCeActivityOfSupplierAndVerify(INFO, "ce_only");
callLogCeActivityOfFailingSupplierAndVerify(INFO, "ce_only");
}

@Test
public void logCeActivity_of_Supplier_set_flag_in_MDC_to_all_when_log_level_is_DEBUG_and_calls_Supplier_and_remove_flag_even_if_Supplier_throws_exception() {
callLogCeActivityOfSupplierAndVerify(DEBUG, "all");
callLogCeActivityOfFailingSupplierAndVerify(DEBUG, "all");
}

@Test
public void logCeActivity_of_Supplier_set_flag_in_MDC_to_all_when_log_level_is_TRACE_and_calls_Supplier_and_remove_flag_even_if_Supplier_throws_exception() {
callLogCeActivityOfSupplierAndVerify(TRACE, "all");
callLogCeActivityOfFailingSupplierAndVerify(TRACE, "all");
}

private void callLogCeActivityOfSupplierAndVerify(Level logLevel, String expectedFlag) {
AtomicBoolean called = new AtomicBoolean(false);
underTest.logCeActivity(
createLogger(logLevel),
() -> {
assertThat(MDC.get(MDC_CE_ACTIVITY_FLAG)).isEqualTo(expectedFlag);
called.compareAndSet(false, true);
return 1;
});
assertThat(MDC.get(MDC_CE_ACTIVITY_FLAG)).isNull();
assertThat(called.get()).isTrue();
}

private void callLogCeActivityOfFailingSupplierAndVerify(Level logLevel, String expectedFlag) {
RuntimeException exception = new RuntimeException("Simulates a failing Supplier");

AtomicBoolean called = new AtomicBoolean(false);
try {
underTest.logCeActivity(
createLogger(logLevel),
() -> {
assertThat(MDC.get(MDC_CE_ACTIVITY_FLAG)).isEqualTo(expectedFlag);
called.compareAndSet(false, true);
throw exception;
});
fail("exception should have been raised");
} catch (Exception e) {
assertThat(e).isSameAs(exception);
} finally {
assertThat(MDC.get(MDC_CE_ACTIVITY_FLAG)).isNull();
assertThat(called.get()).isTrue();
}
}

}

+ 40
- 0
server/sonar-server/src/test/java/org/sonar/server/computation/task/ChangeLogLevel.java View File

@@ -0,0 +1,40 @@
/*
* SonarQube
* Copyright (C) 2009-2016 SonarSource SA
* mailto:contact AT sonarsource DOT com
*
* This program is free software; you can redistribute it and/or
* modify it under the terms of the GNU Lesser General Public
* License as published by the Free Software Foundation; either
* version 3 of the License, or (at your option) any later version.
*
* This program is distributed in the hope that it will be useful,
* but WITHOUT ANY WARRANTY; without even the implied warranty of
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
* Lesser General Public License for more details.
*
* You should have received a copy of the GNU Lesser General Public License
* along with this program; if not, write to the Free Software Foundation,
* Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA.
*/
package org.sonar.server.computation.task;

import org.sonar.api.utils.log.Logger;
import org.sonar.api.utils.log.LoggerLevel;
import org.sonar.api.utils.log.Loggers;

public final class ChangeLogLevel implements AutoCloseable {
private final Logger logger;
private final LoggerLevel previous;

public ChangeLogLevel(Class<?> clazz, LoggerLevel newLevel) {
this.logger = Loggers.get(clazz);
this.previous = logger.getLevel();
logger.setLevel(newLevel);
}

@Override
public void close() {
logger.setLevel(previous);
}
}

+ 18
- 1
server/sonar-server/src/test/java/org/sonar/server/computation/task/projectanalysis/component/ReportVisitorsCrawlerTest.java View File

@@ -25,6 +25,7 @@ import org.junit.Test;
import org.junit.rules.ExpectedException;
import org.mockito.InOrder;

import static org.assertj.core.api.Assertions.assertThat;
import static org.mockito.Matchers.any;
import static org.mockito.Matchers.eq;
import static org.mockito.Mockito.inOrder;
@@ -86,7 +87,7 @@ public class ReportVisitorsCrawlerTest {
@Test
public void execute_pre_visitor_before_post_visitor() throws Exception {
InOrder inOrder = inOrder(spyPreOrderTypeAwareVisitor, spyPostOrderTypeAwareVisitor);
VisitorsCrawler underTest = new VisitorsCrawler(Arrays.<ComponentVisitor>asList(spyPreOrderTypeAwareVisitor, spyPostOrderTypeAwareVisitor));
VisitorsCrawler underTest = new VisitorsCrawler(Arrays.asList(spyPreOrderTypeAwareVisitor, spyPostOrderTypeAwareVisitor));
underTest.visit(COMPONENT_TREE);

inOrder.verify(spyPreOrderTypeAwareVisitor).visitProject(COMPONENT_TREE);
@@ -102,6 +103,22 @@ public class ReportVisitorsCrawlerTest {
inOrder.verify(spyPostOrderTypeAwareVisitor).visitProject(COMPONENT_TREE);
}

@Test
public void getCumulativeDurations_returns_an_empty_map_when_computation_is_disabled_in_constructor() {
VisitorsCrawler underTest = new VisitorsCrawler(Arrays.asList(spyPreOrderTypeAwareVisitor, spyPostOrderTypeAwareVisitor), false);
underTest.visit(COMPONENT_TREE);

assertThat(underTest.getCumulativeDurations()).isEmpty();
}

@Test
public void getCumulativeDurations_returns_an_non_empty_map_when_computation_is_enabled_in_constructor() {
VisitorsCrawler underTest = new VisitorsCrawler(Arrays.asList(spyPreOrderTypeAwareVisitor, spyPostOrderTypeAwareVisitor), true);
underTest.visit(COMPONENT_TREE);

assertThat(underTest.getCumulativeDurations()).hasSize(2);
}

@Test
public void fail_with_IAE_when_visitor_is_not_path_aware_or_type_aware() throws Exception {
thrown.expect(IllegalArgumentException.class);

+ 19
- 2
server/sonar-server/src/test/java/org/sonar/server/computation/task/projectanalysis/component/ViewsVisitorsCrawlerTest.java View File

@@ -25,6 +25,7 @@ import org.junit.Test;
import org.junit.rules.ExpectedException;
import org.mockito.InOrder;

import static org.assertj.core.api.Assertions.assertThat;
import static org.mockito.Matchers.any;
import static org.mockito.Matchers.eq;
import static org.mockito.Mockito.inOrder;
@@ -53,7 +54,7 @@ public class ViewsVisitorsCrawlerTest {
@Test
public void execute_each_visitor_on_each_level() throws Exception {
InOrder inOrder = inOrder(spyPostOrderTypeAwareVisitor, spyPathAwareVisitor);
VisitorsCrawler underTest = new VisitorsCrawler(Arrays.asList(spyPostOrderTypeAwareVisitor, spyPathAwareVisitor));
VisitorsCrawler underTest = new VisitorsCrawler(Arrays.asList(spyPostOrderTypeAwareVisitor, spyPathAwareVisitor), false);
underTest.visit(COMPONENT_TREE);

inOrder.verify(spyPostOrderTypeAwareVisitor).visitAny(PROJECT_VIEW_5);
@@ -85,7 +86,7 @@ public class ViewsVisitorsCrawlerTest {
@Test
public void execute_pre_visitor_before_post_visitor() throws Exception {
InOrder inOrder = inOrder(spyPreOrderTypeAwareVisitor, spyPostOrderTypeAwareVisitor);
VisitorsCrawler underTest = new VisitorsCrawler(Arrays.<ComponentVisitor>asList(spyPreOrderTypeAwareVisitor, spyPostOrderTypeAwareVisitor));
VisitorsCrawler underTest = new VisitorsCrawler(Arrays.<ComponentVisitor>asList(spyPreOrderTypeAwareVisitor, spyPostOrderTypeAwareVisitor), false);
underTest.visit(COMPONENT_TREE);

inOrder.verify(spyPreOrderTypeAwareVisitor).visitView(COMPONENT_TREE);
@@ -120,6 +121,22 @@ public class ViewsVisitorsCrawlerTest {
new VisitorsCrawler(Arrays.asList(componentVisitor));
}

@Test
public void getCumulativeDurations_returns_an_empty_map_when_computation_is_disabled_in_constructor() {
VisitorsCrawler underTest = new VisitorsCrawler(Arrays.asList(spyPreOrderTypeAwareVisitor, spyPostOrderTypeAwareVisitor), false);
underTest.visit(COMPONENT_TREE);

assertThat(underTest.getCumulativeDurations()).isEmpty();
}

@Test
public void getCumulativeDurations_returns_an_non_empty_map_when_computation_is_enabled_in_constructor() {
VisitorsCrawler underTest = new VisitorsCrawler(Arrays.asList(spyPreOrderTypeAwareVisitor, spyPostOrderTypeAwareVisitor), true);
underTest.visit(COMPONENT_TREE);

assertThat(underTest.getCumulativeDurations()).hasSize(2);
}

private static Component component(final Component.Type type, final int ref, final Component... children) {
return ViewsComponent.builder(type, ref).addChildren(children).build();
}

+ 20
- 22
server/sonar-server/src/test/java/org/sonar/server/computation/task/projectanalysis/step/ExecuteVisitorsStepTest.java View File

@@ -24,9 +24,8 @@ import org.junit.Before;
import org.junit.Rule;
import org.junit.Test;
import org.sonar.api.utils.log.LogTester;
import org.sonar.api.utils.log.Logger;
import org.sonar.api.utils.log.LoggerLevel;
import org.sonar.ce.log.CeLogging;
import org.sonar.server.computation.task.ChangeLogLevel;
import org.sonar.server.computation.task.projectanalysis.component.Component;
import org.sonar.server.computation.task.projectanalysis.component.ComponentVisitor;
import org.sonar.server.computation.task.projectanalysis.component.CrawlerDepthLimit;
@@ -41,9 +40,6 @@ import org.sonar.server.computation.task.projectanalysis.metric.MetricRepository
import static java.util.Arrays.asList;
import static java.util.Collections.singletonList;
import static org.assertj.core.api.Assertions.assertThat;
import static org.mockito.Matchers.any;
import static org.mockito.Mockito.spy;
import static org.mockito.Mockito.verify;
import static org.sonar.api.measures.CoreMetrics.NCLOC;
import static org.sonar.api.measures.CoreMetrics.NCLOC_KEY;
import static org.sonar.server.computation.task.projectanalysis.component.Component.Type.DIRECTORY;
@@ -74,8 +70,6 @@ public class ExecuteVisitorsStepTest {
@Rule
public LogTester logTester = new LogTester();

private CeLogging ceLogging = spy(new CeLogging());

@Before
public void setUp() throws Exception {
treeRootHolder.setRoot(
@@ -94,7 +88,7 @@ public class ExecuteVisitorsStepTest {

@Test
public void execute_with_type_aware_visitor() throws Exception {
ExecuteVisitorsStep underStep = new ExecuteVisitorsStep(treeRootHolder, singletonList(new TestTypeAwareVisitor()), ceLogging);
ExecuteVisitorsStep underStep = new ExecuteVisitorsStep(treeRootHolder, singletonList(new TestTypeAwareVisitor()));

measureRepository.addRawMeasure(FILE_1_REF, NCLOC_KEY, newMeasureBuilder().create(1));
measureRepository.addRawMeasure(FILE_2_REF, NCLOC_KEY, newMeasureBuilder().create(2));
@@ -113,7 +107,7 @@ public class ExecuteVisitorsStepTest {

@Test
public void execute_with_path_aware_visitor() throws Exception {
ExecuteVisitorsStep underStep = new ExecuteVisitorsStep(treeRootHolder, singletonList(new TestPathAwareVisitor()), ceLogging);
ExecuteVisitorsStep underStep = new ExecuteVisitorsStep(treeRootHolder, singletonList(new TestPathAwareVisitor()));

measureRepository.addRawMeasure(FILE_1_REF, NCLOC_KEY, newMeasureBuilder().create(1));
measureRepository.addRawMeasure(FILE_2_REF, NCLOC_KEY, newMeasureBuilder().create(1));
@@ -129,20 +123,24 @@ public class ExecuteVisitorsStepTest {

@Test
public void execute_logs_at_info_level_all_execution_duration_of_all_visitors() {
ExecuteVisitorsStep underStep = new ExecuteVisitorsStep(
treeRootHolder,
asList(new VisitorA(), new VisitorB(), new VisitorC()),
ceLogging);

underStep.execute();
try (ChangeLogLevel executor = new ChangeLogLevel(ExecuteVisitorsStep.class, LoggerLevel.DEBUG);
ChangeLogLevel step1 = new ChangeLogLevel(VisitorA.class, LoggerLevel.DEBUG);
ChangeLogLevel step2 = new ChangeLogLevel(VisitorB.class, LoggerLevel.DEBUG);
ChangeLogLevel step3 = new ChangeLogLevel(VisitorB.class, LoggerLevel.DEBUG)) {
ExecuteVisitorsStep underStep = new ExecuteVisitorsStep(
treeRootHolder,
asList(new VisitorA(), new VisitorB(), new VisitorC()));

underStep.execute();

List<String> logs = logTester.logs(LoggerLevel.DEBUG);
assertThat(logs).hasSize(4);
assertThat(logs.get(0)).isEqualTo(" Execution time for each component visitor:");
assertThat(logs.get(1)).startsWith(" - VisitorA | time=");
assertThat(logs.get(2)).startsWith(" - VisitorB | time=");
assertThat(logs.get(3)).startsWith(" - VisitorC | time=");

verify(ceLogging).logCeActivity(any(Logger.class), any(Runnable.class));
List<String> logs = logTester.logs(LoggerLevel.INFO);
assertThat(logs).hasSize(4);
assertThat(logs.get(0)).isEqualTo(" Execution time for each component visitor:");
assertThat(logs.get(1)).startsWith(" - VisitorA | time=");
assertThat(logs.get(2)).startsWith(" - VisitorB | time=");
assertThat(logs.get(3)).startsWith(" - VisitorC | time=");
}
}

private static class VisitorA extends TypeAwareVisitorAdapter {

+ 31
- 11
server/sonar-server/src/test/java/org/sonar/server/computation/task/step/ComputationStepExecutorTest.java View File

@@ -27,7 +27,7 @@ import org.junit.rules.ExpectedException;
import org.mockito.InOrder;
import org.sonar.api.utils.log.LogTester;
import org.sonar.api.utils.log.LoggerLevel;
import org.sonar.ce.log.CeLogging;
import org.sonar.server.computation.task.ChangeLogLevel;

import static org.assertj.core.api.Assertions.assertThat;
import static org.assertj.core.api.Assertions.fail;
@@ -49,11 +49,9 @@ public class ComputationStepExecutorTest {
private final ComputationStep computationStep2 = mockComputationStep("step2");
private final ComputationStep computationStep3 = mockComputationStep("step3");

private CeLogging ceLogging = new CeLogging();

@Test
public void execute_call_execute_on_each_ComputationStep_in_order_returned_by_instances_method() {
new ComputationStepExecutor(mockComputationSteps(computationStep1, computationStep2, computationStep3), ceLogging)
new ComputationStepExecutor(mockComputationSteps(computationStep1, computationStep2, computationStep3))
.execute();

InOrder inOrder = inOrder(computationStep1, computationStep2, computationStep3);
@@ -75,7 +73,7 @@ public class ComputationStepExecutorTest {
.when(computationStep)
.execute();

ComputationStepExecutor computationStepExecutor = new ComputationStepExecutor(mockComputationSteps(computationStep), ceLogging);
ComputationStepExecutor computationStepExecutor = new ComputationStepExecutor(mockComputationSteps(computationStep));

expectedException.expect(RuntimeException.class);
expectedException.expectMessage(message);
@@ -84,19 +82,41 @@ public class ComputationStepExecutorTest {
}

@Test
public void execute_logs_end_timing_for_each_ComputationStep_called() {
new ComputationStepExecutor(mockComputationSteps(computationStep1, computationStep2), ceLogging)
.execute();
public void execute_does_not_log_end_timing_for_each_ComputationStep_called_when_level_is_INFO() {
List<String> infoLogs = execute_logs_end_timing_for_each_ComputationStep_called_when_(LoggerLevel.INFO);
assertThat(infoLogs).isEmpty();
}

List<String> infoLogs = logTester.logs(LoggerLevel.INFO);
@Test
public void execute_logs_end_timing_for_each_ComputationStep_called_when_level_is_DEBUG() {
List<String> infoLogs = execute_logs_end_timing_for_each_ComputationStep_called_when_(LoggerLevel.DEBUG);
assertThat(infoLogs).hasSize(2);
assertThat(infoLogs.get(0)).contains("step1 | time=");
assertThat(infoLogs.get(1)).contains("step2 | time=");
}

@Test
public void execute_logs_end_timing_for_each_ComputationStep_called_when_level_is_TRACE() {
List<String> infoLogs = execute_logs_end_timing_for_each_ComputationStep_called_when_(LoggerLevel.TRACE);
assertThat(infoLogs).hasSize(2);
assertThat(infoLogs.get(0)).contains("step1 | time=");
assertThat(infoLogs.get(1)).contains("step2 | time=");
}

private List<String> execute_logs_end_timing_for_each_ComputationStep_called_when_(LoggerLevel level) {
try (ChangeLogLevel executor = new ChangeLogLevel(ComputationStepExecutor.class, level);
ChangeLogLevel step1 = new ChangeLogLevel(computationStep1.getClass(), level);
ChangeLogLevel step2 = new ChangeLogLevel(computationStep2.getClass(), level)) {
new ComputationStepExecutor(mockComputationSteps(computationStep1, computationStep2))
.execute();

return logTester.logs(LoggerLevel.DEBUG);
}
}

@Test
public void execute_calls_listener_finished_method_with_all_step_runs() {
new ComputationStepExecutor(mockComputationSteps(computationStep1, computationStep2), ceLogging, listener)
new ComputationStepExecutor(mockComputationSteps(computationStep1, computationStep2), listener)
.execute();

verify(listener).finished(true);
@@ -111,7 +131,7 @@ public class ComputationStepExecutorTest {
.execute();

try {
new ComputationStepExecutor(mockComputationSteps(computationStep1, computationStep2), ceLogging, listener)
new ComputationStepExecutor(mockComputationSteps(computationStep1, computationStep2), listener)
.execute();
fail("exception toBeThrown should have been raised");
} catch (RuntimeException e) {

Write Preview
Loading…
Cancel
Save