diff options
Diffstat (limited to 'vespa-osgi-testrunner/src/main')
7 files changed, 656 insertions, 305 deletions
diff --git a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/AggregateTestRunner.java b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/AggregateTestRunner.java index 15aeef18013..9b8d4a1494b 100644 --- a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/AggregateTestRunner.java +++ b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/AggregateTestRunner.java @@ -88,23 +88,7 @@ public class AggregateTestRunner implements TestRunner { } static TestReport merge(TestReport first, TestReport second) { - return first == null ? second - : second == null ? first - : TestReport.builder() - .withAbortedCount(first.abortedCount + second.abortedCount) - .withFailedCount(first.failedCount + second.failedCount) - .withIgnoredCount(first.ignoredCount + second.ignoredCount) - .withSuccessCount(first.successCount + second.successCount) - .withFailures(merged(first.failures, second.failures)) - .withLogs(merged(first.logLines, second.logLines)) - .build(); - } - - static <T> List<T> merged(List<T> first, List<T> second) { - ArrayList<T> merged = new ArrayList<>(); - merged.addAll(first); - merged.addAll(second); - return merged; + return first == null ? second : second == null ? first : first.mergedWith(second); } } diff --git a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/JunitRunner.java b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/JunitRunner.java index c01c9b571e0..089019111db 100644 --- a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/JunitRunner.java +++ b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/JunitRunner.java @@ -10,6 +10,9 @@ import com.yahoo.component.AbstractComponent; import com.yahoo.component.annotation.Inject; import com.yahoo.jdisc.application.OsgiFramework; import com.yahoo.vespa.defaults.Defaults; +import com.yahoo.vespa.testrunner.TestReport.ContainerNode; +import com.yahoo.vespa.testrunner.TestReport.FailureNode; +import com.yahoo.vespa.testrunner.TestReport.Status; import org.junit.jupiter.engine.JupiterTestEngine; import org.junit.platform.engine.discovery.DiscoverySelectors; import org.junit.platform.launcher.LauncherDiscoveryRequest; @@ -19,8 +22,10 @@ import org.junit.platform.launcher.core.LauncherDiscoveryRequestBuilder; import org.junit.platform.launcher.core.LauncherFactory; import org.junit.platform.launcher.listeners.SummaryGeneratingListener; +import java.time.Clock; import java.util.Collection; import java.util.List; +import java.util.Map; import java.util.Optional; import java.util.SortedMap; import java.util.concurrent.CompletableFuture; @@ -36,12 +41,16 @@ import static java.util.stream.Collectors.toList; /** * @author mortent + * @author jonmv */ public class JunitRunner extends AbstractComponent implements TestRunner { private static final Logger logger = Logger.getLogger(JunitRunner.class.getName()); + private final Clock clock; private final SortedMap<Long, LogRecord> logRecords = new ConcurrentSkipListMap<>(); + private final TeeStream stdoutTee = TeeStream.ofSystemOut(); + private final TeeStream stderrTee = TeeStream.ofSystemErr(); private final TestRuntimeProvider testRuntimeProvider; private final Function<Suite, List<Class<?>>> classLoader; private final BiConsumer<LauncherDiscoveryRequest, TestExecutionListener[]> testExecutor; @@ -52,18 +61,22 @@ public class JunitRunner extends AbstractComponent implements TestRunner { JunitTestRunnerConfig config, TestRuntimeProvider testRuntimeProvider, SystemInfo systemInfo) { - this(testRuntimeProvider, + this(Clock.systemUTC(), + testRuntimeProvider, new TestBundleLoader(osgiFramework)::loadTestClasses, (discoveryRequest, listeners) -> LauncherFactory.create(LauncherConfig.builder() .addTestEngines(new JupiterTestEngine()) .build()).execute(discoveryRequest, listeners)); uglyHackSetCredentialsRootSystemProperty(config, systemInfo.zone()); + } - JunitRunner(TestRuntimeProvider testRuntimeProvider, - Function<Suite, List<Class<?>>> classLoader, - BiConsumer<LauncherDiscoveryRequest, TestExecutionListener[]> testExecutor) { + JunitRunner(Clock clock, + TestRuntimeProvider testRuntimeProvider, + Function<Suite, List<Class<?>>> classLoader, + BiConsumer<LauncherDiscoveryRequest, TestExecutionListener[]> testExecutor) { + this.clock = clock; this.classLoader = classLoader; this.testExecutor = testExecutor; this.testRuntimeProvider = testRuntimeProvider; @@ -76,10 +89,9 @@ public class JunitRunner extends AbstractComponent implements TestRunner { } try { logRecords.clear(); - testRuntimeProvider.initialize(testConfig); - execution = CompletableFuture.supplyAsync(() -> launchJunit(suite)); + execution = CompletableFuture.supplyAsync(() -> launchJunit(suite, testConfig)); } catch (Exception e) { - execution = CompletableFuture.completedFuture(createReportWithFailedInitialization(e)); + execution = CompletableFuture.completedFuture(TestReport.createFailed(clock, suite, e)); } return execution; } @@ -89,52 +101,25 @@ public class JunitRunner extends AbstractComponent implements TestRunner { return logRecords.tailMap(after + 1).values(); } - static TestReport createReportWithFailedInitialization(Exception exception) { - TestReport.Failure failure = new TestReport.Failure("init", exception); - return new TestReport.Builder().withFailures(List.of(failure)) - .withFailedCount(1) - .build(); - } - - - private TestReport launchJunit(Suite suite) { + private TestReport launchJunit(Suite suite, byte[] testConfig) { List<Class<?>> testClasses = classLoader.apply(suite); if (testClasses == null) return null; - VespaJunitLogListener logListener = new VespaJunitLogListener(record -> logRecords.put(record.getSequenceNumber(), record)); - SummaryGeneratingListener summaryListener = new SummaryGeneratingListener(); + testRuntimeProvider.initialize(testConfig); + TestReportGeneratingListener testReportListener = new TestReportGeneratingListener(suite, + record -> logRecords.put(record.getSequenceNumber(), record), + stdoutTee, + stderrTee, + clock); LauncherDiscoveryRequest discoveryRequest = LauncherDiscoveryRequestBuilder.request() .selectors(testClasses.stream() .map(DiscoverySelectors::selectClass) .collect(toList())) .build(); + testExecutor.accept(discoveryRequest, new TestExecutionListener[] { testReportListener }); - testExecutor.accept(discoveryRequest, new TestExecutionListener[] { logListener, summaryListener }); - - var report = summaryListener.getSummary(); - var failures = report.getFailures().stream() - .map(failure -> { - TestReport.trimStackTraces(failure.getException(), JunitRunner.class.getName()); - return new TestReport.Failure(VespaJunitLogListener.toString(failure.getTestIdentifier().getUniqueIdObject()), - failure.getException()); - }) - .collect(toList()); - - // TODO: move to aggregator. - long inconclusive = suite == Suite.PRODUCTION_TEST ? failures.stream() - .filter(failure -> failure.exception() instanceof InconclusiveTestException) - .count() - : 0; - return TestReport.builder() - .withSuccessCount(report.getTestsSucceededCount()) - .withAbortedCount(report.getTestsAbortedCount()) - .withIgnoredCount(report.getTestsSkippedCount()) - .withFailedCount(report.getTestsFailedCount() - inconclusive) - .withInconclusiveCount(inconclusive) - .withFailures(failures) - .withLogs(logRecords.values()) - .build(); + return testReportListener.report(); } @Override @@ -147,13 +132,27 @@ public class JunitRunner extends AbstractComponent implements TestRunner { if (execution == null) return TestRunner.Status.NOT_STARTED; if ( ! execution.isDone()) return TestRunner.Status.RUNNING; try { - return execution.get() == null ? Status.NO_TESTS : execution.get().status(); + return testRunnerStatus(execution.get()); } catch (InterruptedException | ExecutionException e) { logger.log(Level.WARNING, "Error while getting test report", e); return TestRunner.Status.ERROR; } } + static TestRunner.Status testRunnerStatus(TestReport report) { + if (report == null) return Status.NO_TESTS; + switch (report.root().status()) { + case error: + case failed: return Status.FAILURE; + case inconclusive: return Status.INCONCLUSIVE; + case successful: + case skipped: + case aborted: return report.root().tally().containsKey(TestReport.Status.successful) ? Status.SUCCESS + : Status.NO_TESTS; + default: throw new IllegalStateException("unknown status '" + report.root().status() + "'"); + } + } + @Override public TestReport getReport() { if (execution.isDone()) { @@ -163,7 +162,7 @@ public class JunitRunner extends AbstractComponent implements TestRunner { logger.log(Level.WARNING, "Error getting test report", e); // Likely this is something wrong with the provided test bundle. Create a test report // and present in the console to enable tenants to act on it. - return createReportWithFailedInitialization(e); + return TestReport.createFailed(clock, null, e); } } else { return null; diff --git a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TeeStream.java b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TeeStream.java new file mode 100644 index 00000000000..bef4c8de1b6 --- /dev/null +++ b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TeeStream.java @@ -0,0 +1,65 @@ +package com.yahoo.vespa.testrunner; + +import java.io.IOException; +import java.io.OutputStream; +import java.io.PrintStream; +import java.util.concurrent.atomic.AtomicReference; + +/** + * Used to replace System.out and System.err, providing the ability to forward output to an additional sink. + * + * @author jonmv + */ +public class TeeStream extends OutputStream { + + private final AtomicReference<OutputStream> tee = new AtomicReference<>(); + private final OutputStream original; + + private TeeStream(OutputStream original) { + this.original = original; + } + + public static TeeStream ofSystemOut() { + TeeStream teed = new TeeStream(System.out); + System.setOut(new PrintStream(teed)); + return teed; + } + + public static TeeStream ofSystemErr() { + TeeStream teed = new TeeStream(System.err); + System.setErr(new PrintStream(teed)); + return teed; + } + + public void setTee(OutputStream tee) { + if ( ! this.tee.compareAndSet(null, tee)) throw new IllegalStateException("tee already set"); + } + + public OutputStream clearTee() { + OutputStream tee = this.tee.getAndSet(null); + if (tee == null) throw new IllegalStateException("tee not set"); + return tee; + } + + @Override + public void write(int b) throws IOException { + OutputStream maybe = tee.get(); + if (maybe != null) maybe.write(b); + original.write(b); + } + + @Override + public void write(byte[] b, int off, int len) throws IOException { + OutputStream maybe = tee.get(); + if (maybe != null) maybe.write(b, off, len); + original.write(b, off, len); + } + + @Override + public void flush() throws IOException { + OutputStream maybe = tee.get(); + if (maybe != null) maybe.flush(); + original.flush(); + } + +} diff --git a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestReport.java b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestReport.java index 747005f467d..a4fa3e62c50 100644 --- a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestReport.java +++ b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestReport.java @@ -1,125 +1,307 @@ // Copyright Yahoo. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. package com.yahoo.vespa.testrunner; -import java.util.Collection; -import java.util.Collections; +import ai.vespa.hosted.cd.InconclusiveTestException; +import com.yahoo.collections.Comparables; +import com.yahoo.vespa.testrunner.TestRunner.Suite; +import org.junit.platform.engine.UniqueId; +import org.junit.platform.engine.UniqueId.Segment; +import org.junit.platform.launcher.TestIdentifier; +import org.junit.platform.launcher.TestPlan; + +import java.time.Clock; +import java.time.Duration; +import java.time.Instant; +import java.util.ArrayDeque; +import java.util.Deque; +import java.util.EnumMap; +import java.util.HashSet; import java.util.List; +import java.util.Map; +import java.util.Queue; +import java.util.Set; import java.util.logging.LogRecord; -import static com.yahoo.vespa.testrunner.TestRunner.Status.FAILURE; -import static com.yahoo.vespa.testrunner.TestRunner.Status.INCONCLUSIVE; -import static com.yahoo.vespa.testrunner.TestRunner.Status.NO_TESTS; -import static com.yahoo.vespa.testrunner.TestRunner.Status.SUCCESS; import static java.util.Arrays.copyOf; /** - * @author mortent + * @author jonmv */ public class TestReport { - final long successCount; - final long failedCount; - final long inconclusiveCount; - final long ignoredCount; - final long abortedCount; - final List<Failure> failures; - final List<LogRecord> logLines; + private final Object monitor = new Object(); + private final Set<TestIdentifier> complete = new HashSet<>(); + private final Clock clock; + private final ContainerNode root; + private final Suite suite; + private NamedNode current; + private TestPlan plan; + + private TestReport(Clock clock, Suite suite, ContainerNode root) { + this.clock = clock; + this.root = root; + this.current = root; + this.suite = suite; + } + + TestReport(Clock clock, Suite suite) { + this(clock, suite, new ContainerNode(null, toString(suite), clock.instant())); + } + + static TestReport createFailed(Clock clock, Suite suite, Exception exception) { + TestReport failed = new TestReport(clock, suite); + failed.complete(); + failed.root().children.add(new FailureNode(failed.root(), exception, suite)); + return failed; + } + + /** Verify the path from the root to the current node corresponds to the given id. */ + private void verifyStructure(NamedNode node, UniqueId id) { + Deque<String> path = new ArrayDeque<>(); + while (node != root) { + path.push(node.name); + node = node.parent; + } + Deque<String> segments = new ArrayDeque<>(); + if (id != null) for (Segment segment : id.getSegments()) + segments.add(segment.getValue()); + + if ( ! List.copyOf(path).equals(List.copyOf(segments))) + throw new IllegalStateException("test node " + segments + " referenced, but expected " + path); + } - private TestReport(long successCount, long failedCount, long inconclusiveCount, long ignoredCount, long abortedCount, List<Failure> failures, List<LogRecord> logLines) { - this.successCount = successCount; - this.failedCount = failedCount; - this.inconclusiveCount = inconclusiveCount; - this.ignoredCount = ignoredCount; - this.abortedCount = abortedCount; - this.failures = failures; - this.logLines = logLines; + void start(TestPlan plan) { + synchronized (monitor) { + this.plan = plan; + } } - public List<LogRecord> logLines() { - return logLines; + void start(TestIdentifier id) { + synchronized (monitor) { + NamedNode child = id.isTest() ? new TestNode(current, id.getUniqueIdObject().getLastSegment().getValue(), clock.instant()) + : new ContainerNode(current, id.getUniqueIdObject().getLastSegment().getValue(), clock.instant()); + verifyStructure(child, id.getUniqueIdObject()); + current.children.add(child); + current = child; + } } - public TestRunner.Status status() { - return (failures.size() > 0 || failedCount > 0) ? FAILURE : inconclusiveCount > 0 ? INCONCLUSIVE : successCount > 0 ? SUCCESS : NO_TESTS; + ContainerNode complete() { + synchronized (monitor) { + complete(null); + return root(); + } } - public static Builder builder(){ - return new Builder(); + private NamedNode complete(TestIdentifier id) { + verifyStructure(current, id == null ? null : id.getUniqueIdObject()); + + Set<TestIdentifier> incomplete = id != null ? plan.getChildren(id) : plan != null ? plan.getRoots() : Set.of(); + for (TestIdentifier child : incomplete) if ( ! complete.contains(child)) skip(child); + complete.add(id); + + current.end = clock.instant(); + NamedNode node = current; + current = current.parent; + return node; + } + + NamedNode skip(TestIdentifier id) { + synchronized (monitor) { + start(id); + current.status = Status.skipped; + return complete(id); + } + } + + NamedNode abort(TestIdentifier id) { + synchronized (monitor) { + current.status = Status.aborted; + return complete(id); + } + } + + NamedNode complete(TestIdentifier id, Throwable thrown) { + synchronized (monitor) { + Status status = Status.successful; + if (thrown != null) { + FailureNode failure = new FailureNode(current, thrown, suite); + current.children.add(failure); + status = failure.status(); + } + current.status = status; + return complete(id); + } + } + + void log(LogRecord record) { + synchronized (monitor) { + if (record.getThrown() != null) trimStackTraces(record.getThrown(), JunitRunner.class.getName()); + if ( ! (current.children.peekLast() instanceof OutputNode)) + current.children.add(new OutputNode(current)); + + ((OutputNode) current.children.peekLast()).log.add(record); + } + } + + public TestReport mergedWith(TestReport other) { + synchronized (monitor) { + synchronized (other.monitor) { + if (current != null || other.current != null) + throw new IllegalArgumentException("can only merge completed test reports"); + + if (root.start().isBefore(other.root.start())) + throw new IllegalArgumentException("appended test report cannot have started before the one appended to"); + + ContainerNode newRoot = new ContainerNode(null, root.name(), root.start()); + newRoot.children.addAll(root.children); + newRoot.children.addAll(other.root.children); + return new TestReport(clock, suite, newRoot); + } + } + } + + public ContainerNode root() { + synchronized (monitor) { + return root; + } } + public static class Node { - public static class Builder { + final Deque<Node> children = new ArrayDeque<>(); + final NamedNode parent; - private long successCount; - private long failedCount; - private long inconclusiveCount; - private long ignoredCount; - private long abortedCount; - private List<Failure> failures = Collections.emptyList(); - private List<LogRecord> logLines = Collections.emptyList(); + Node(NamedNode parent) { + this.parent = parent; + } + + Status status() { + int status = 0; + for (Node node : children) + status = Math.max(status, node.status().ordinal()); - public TestReport build() { - return new TestReport(successCount, failedCount, inconclusiveCount, ignoredCount, abortedCount, failures, logLines); + return Status.values()[status]; } - public Builder withSuccessCount(long successCount) { - this.successCount = successCount; - return this; + Map<Status, Long> tally() { + Map<Status, Long> tally = new EnumMap<>(Status.class); + for (Node child : children) + child.tally().forEach((status, count) -> tally.merge(status, count, Long::sum)); + + return tally; } - public Builder withFailedCount(long failedCount) { - this.failedCount = failedCount; - return this; + public Queue<Node> children() { + return children; } - public Builder withInconclusiveCount(long inconclusiveCount) { - this.inconclusiveCount = inconclusiveCount; - return this; + } + + static abstract class NamedNode extends Node { + + private final String name; + private final Instant start; + private Status status; + private Instant end; + + NamedNode(NamedNode parent, String name, Instant now) { + super(parent); + this.name = name; + this.start = now; } - public Builder withIgnoredCount(long ignoredCount) { - this.ignoredCount = ignoredCount; - return this; + @Override + public Status status() { + Status aggregate = super.status(); + return status == null ? aggregate : Comparables.max(status, aggregate); } - public Builder withAbortedCount(long abortedCount) { - this.abortedCount = abortedCount; - return this; + public String name() { + return name; } - public Builder withFailures(List<Failure> failures) { - this.failures = List.copyOf(failures); - return this; + public Instant start() { + return start; } - public Builder withLogs(Collection<LogRecord> logRecords) { - this.logLines = List.copyOf(logRecords); - return this; + public Duration duration() { + return Duration.between(start, end); } } + public static class ContainerNode extends NamedNode { + + ContainerNode(NamedNode parent, String name, Instant now) { + super(parent, name, now); + } + + } - public static class Failure { + public static class TestNode extends NamedNode { - private final String testId; - private final Throwable exception; + TestNode(NamedNode parent, String name, Instant now) { + super(parent, name, now); + } - public Failure(String testId, Throwable exception) { - this.testId = testId; - this.exception = exception; + @Override + public Map<Status, Long> tally() { + return Map.of(status(), 1L); } - public String testId() { - return testId; + } + + public static class OutputNode extends Node { + + private final ArrayDeque<LogRecord> log = new ArrayDeque<>(); + + public OutputNode(NamedNode parent) { + super(parent); } - public Throwable exception() { - return exception; + public Queue<LogRecord> log() { + return log; } } + public static class FailureNode extends Node { + + private final Throwable thrown; + private final Suite suite; + + public FailureNode(NamedNode parent, Throwable thrown, Suite suite) { + super(parent); + this.thrown = thrown; + trimStackTraces(thrown, JunitRunner.class.getName()); + this.suite = suite; + } + + public Throwable thrown() { + return thrown; + } + + public Status status() { + return suite == Suite.PRODUCTION_TEST && thrown instanceof InconclusiveTestException + ? Status.inconclusive + : thrown instanceof AssertionError ? Status.failed : Status.error; + } + + } + + public enum Status { + + // Must be kept in order of increasing severity. + successful, + skipped, + aborted, + inconclusive, + failed, + error; + + } + /** * Recursively trims stack traces for the given throwable and its causes/suppressed. * This is based on the assumption that the relevant stack is anything above the first native @@ -130,13 +312,25 @@ public class TestReport { return; StackTraceElement[] stack = thrown.getStackTrace(); - int i = stack.length; + int i = 0; + int previousNativeFrame = -1; + int cutoff = 0; boolean rootedInTestFramework = false; - while (--i > 0 && ! stack[i].isNativeMethod()) // Native method invokes the first user test frame. + while (++i < stack.length) { rootedInTestFramework |= testFrameworkRootClass.equals(stack[i].getClassName()); - - if (rootedInTestFramework && i > 0) - thrown.setStackTrace(copyOf(stack, i)); + if (stack[i].isNativeMethod()) + previousNativeFrame = i; // Native method invokes the first user test frame. + if (rootedInTestFramework && previousNativeFrame > 0) { + cutoff = previousNativeFrame; + break; + } + boolean isDynamicTestInvocation = "org.junit.jupiter.engine.descriptor.DynamicTestTestDescriptor".equals(stack[i].getClassName()); + if (isDynamicTestInvocation) { + cutoff = i; + break; + } + } + thrown.setStackTrace(copyOf(stack, cutoff)); for (Throwable suppressed : thrown.getSuppressed()) trimStackTraces(suppressed, testFrameworkRootClass); @@ -144,4 +338,15 @@ public class TestReport { trimStackTraces(thrown.getCause(), testFrameworkRootClass); } + private static String toString(Suite suite) { + if (suite == null) return "Tests"; + switch (suite) { + case SYSTEM_TEST: return "System test"; + case STAGING_SETUP_TEST: return "Staging setup"; + case STAGING_TEST: return "Staging test"; + case PRODUCTION_TEST: return "Production test"; + default: throw new IllegalArgumentException("unexpected suite '" + suite + "'"); + } + } + } diff --git a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestReportGeneratingListener.java b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestReportGeneratingListener.java new file mode 100644 index 00000000000..0d767f5aa8a --- /dev/null +++ b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestReportGeneratingListener.java @@ -0,0 +1,183 @@ +// Copyright Yahoo. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. + +package com.yahoo.vespa.testrunner; + +import com.yahoo.vespa.testrunner.TestReport.Node; +import com.yahoo.vespa.testrunner.TestReport.Status; +import com.yahoo.vespa.testrunner.TestRunner.Suite; +import org.junit.platform.engine.TestExecutionResult; +import org.junit.platform.engine.reporting.ReportEntry; +import org.junit.platform.launcher.TestExecutionListener; +import org.junit.platform.launcher.TestIdentifier; +import org.junit.platform.launcher.TestPlan; + +import java.io.ByteArrayOutputStream; +import java.io.IOException; +import java.io.OutputStream; +import java.time.Clock; +import java.time.ZoneOffset; +import java.util.HashMap; +import java.util.Map; +import java.util.function.Consumer; +import java.util.logging.Handler; +import java.util.logging.Level; +import java.util.logging.LogRecord; +import java.util.logging.Logger; + +import static java.nio.charset.StandardCharsets.UTF_8; +import static java.util.Objects.requireNonNullElse; +import static java.util.Objects.requireNonNullElseGet; +import static java.util.logging.Level.INFO; +import static java.util.logging.Level.SEVERE; +import static java.util.logging.Level.WARNING; +import static java.util.stream.Collectors.joining; + +class TestReportGeneratingListener implements TestExecutionListener { + + private final TestReport report; // Holds a structured view of the test run. + private final Consumer<LogRecord> logger; // Used to show test output for a plain textual view of the test run. + private final TeeStream stdoutTee; // Captures output from test code. + private final TeeStream stderrTee; // Captures output from test code. + private final Handler handler; // Captures logging from test code. + private final Clock clock; + + TestReportGeneratingListener(Suite suite, Consumer<LogRecord> logger, TeeStream stdoutTee, TeeStream stderrTee, Clock clock) { + this.report = new TestReport(clock, suite); + this.logger = logger; + this.stdoutTee = stdoutTee; + this.stderrTee = stderrTee; + this.handler = new TestReportHandler(); + this.clock = clock; + } + + @Override + public void testPlanExecutionStarted(TestPlan testPlan) { + report.start(testPlan); + stdoutTee.setTee(new LineLoggingOutputStream()); + stderrTee.setTee(new LineLoggingOutputStream()); + Logger.getLogger("").addHandler(handler); + } + + @Override + public void testPlanExecutionFinished(TestPlan testPlan) { + Logger.getLogger("").removeHandler(handler); + try { + stderrTee.clearTee().close(); + stdoutTee.clearTee().close(); + } + catch (IOException ignored) { } // Doesn't happen. + + TestReport.Node root = report.complete(); + Level level = INFO; + switch (root.status()) { + case skipped: case aborted: level = WARNING; break; + case failed: case error: level = SEVERE; + } + Map<Status, Long> tally = root.tally(); + log(level, + "Done running " + tally.values().stream().mapToLong(Long::longValue).sum() + " tests: " + + tally.entrySet().stream() + .map(entry -> entry.getValue() + " " + entry.getKey()) + .collect(joining(", "))); + } + + @Override + public void dynamicTestRegistered(TestIdentifier testIdentifier) { + if (testIdentifier.isContainer() && testIdentifier.getParentId().isPresent()) // Skip root engine level. + log(INFO, "Registered dynamic container: " + testIdentifier.getDisplayName()); + if (testIdentifier.isTest()) + log(INFO, "Registered dynamic test: " + testIdentifier.getDisplayName()); + } + + @Override + public void executionStarted(TestIdentifier testIdentifier) { + if (testIdentifier.isContainer() && testIdentifier.getParentId().isPresent()) // Skip root engine level. + log(INFO, "Running all tests in: " + testIdentifier.getDisplayName()); + if (testIdentifier.isTest()) + log(INFO, "Running test: " + testIdentifier.getDisplayName()); + report.start(testIdentifier); + } + + @Override + public void executionSkipped(TestIdentifier testIdentifier, String reason) { + log(WARNING, "Skipping: " + testIdentifier.getDisplayName() + ": " + reason); + report.skip(testIdentifier); + } + + @Override + public void executionFinished(TestIdentifier testIdentifier, TestExecutionResult testExecutionResult) { + Node node = testExecutionResult.getStatus() == TestExecutionResult.Status.ABORTED + ? report.abort(testIdentifier) + : report.complete(testIdentifier, testExecutionResult.getThrowable().orElse(null)); + Status status = node.status(); + Level level = status.compareTo(Status.failed) >= 0 ? SEVERE : status.compareTo(Status.skipped) >= 0 ? WARNING : INFO; + + if (testIdentifier.isContainer()) { + if (testIdentifier.getParentIdObject().isPresent()) { + log(level, + "Tests in " + testIdentifier.getDisplayName() + " done: " + + node.tally().entrySet().stream().map(entry -> entry.getValue() + " " + entry.getKey()).collect(joining(", "))); + } + } + if (testIdentifier.isTest()) { + testIdentifier.getParentIdObject().ifPresent(parent -> log(level, + "Test " + status + ": " + testIdentifier.getDisplayName(), + testExecutionResult.getThrowable().orElse(null))); + } + } + + @Override + public void reportingEntryPublished(TestIdentifier __, ReportEntry report) { // Note: identifier not needed as long as we run serially. + Map<String, String> entries = new HashMap<>(report.getKeyValuePairs()); + Level level = Level.parse(requireNonNullElse(entries.remove("level"), "INFO")); + String logger = entries.remove("logger"); + String message = requireNonNullElseGet(entries.remove("value"), () -> entries.entrySet().stream() + .map(entry -> entry.getKey() + ": " + entry.getValue()) + .collect(joining("\n"))); + + LogRecord record = new LogRecord(level, message); + record.setInstant(report.getTimestamp().toInstant(ZoneOffset.UTC)); + record.setLoggerName(logger); + handler.publish(record); + } + + TestReport report() { + return report; + } + + private void log(Level level, String message) { + log(level, message, null); + } + + private void log(Level level, String message, Throwable thrown) { + LogRecord record = new LogRecord(level, message); + record.setThrown(thrown); + logger.accept(record); + } + + private class LineLoggingOutputStream extends OutputStream { + final ByteArrayOutputStream buffer = new ByteArrayOutputStream(); + @Override public void write(int b) { + if (b == '\n') { + handler.publish(new LogRecord(INFO, buffer.toString(UTF_8))); + buffer.reset(); + } + else buffer.write(b); + } + @Override public void close() { + if (buffer.size() > 0) write('\n'); + } + } + + private class TestReportHandler extends Handler { + @Override public void publish(LogRecord record) { + if ("html".equals(record.getLevel().getName())) record.setLevel(INFO); + record.setInstant(clock.instant()); + logger.accept(record); + report.log(record); + } + @Override public void flush() { } + @Override public void close() { } + } + +} diff --git a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestRunnerHandler.java b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestRunnerHandler.java index 0fdc88e1ad9..4bf40323193 100644 --- a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestRunnerHandler.java +++ b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/TestRunnerHandler.java @@ -12,6 +12,11 @@ import com.yahoo.restapi.MessageResponse; import com.yahoo.restapi.SlimeJsonResponse; import com.yahoo.slime.Cursor; import com.yahoo.slime.Slime; +import com.yahoo.vespa.testrunner.TestReport.ContainerNode; +import com.yahoo.vespa.testrunner.TestReport.FailureNode; +import com.yahoo.vespa.testrunner.TestReport.Node; +import com.yahoo.vespa.testrunner.TestReport.OutputNode; +import com.yahoo.vespa.testrunner.TestReport.TestNode; import com.yahoo.yolean.Exceptions; import java.io.ByteArrayOutputStream; @@ -20,12 +25,14 @@ import java.io.PrintStream; import java.time.ZoneOffset; import java.time.format.DateTimeFormatter; import java.util.Collection; +import java.util.Map; import java.util.Optional; import java.util.concurrent.Executor; import java.util.logging.Level; import java.util.logging.LogRecord; import static com.yahoo.jdisc.Response.Status; +import static java.nio.charset.StandardCharsets.UTF_8; /** * @author valerijf @@ -74,7 +81,6 @@ public class TestRunnerHandler extends ThreadedHttpRequestHandler { .orElse(-1L); return new SlimeJsonResponse(logToSlime(testRunner.getLog(fetchRecordsAfter))); case "/tester/v1/status": - log.info("Responding with status " + testRunner.getStatus()); return new MessageResponse(testRunner.getStatus().name()); case "/tester/v1/report": TestReport report = testRunner.getReport(); @@ -139,32 +145,91 @@ public class TestRunnerHandler extends ThreadedHttpRequestHandler { : "error"; } - private static Slime toSlime(TestReport testReport) { + private static Slime toSlime(TestReport report) { var slime = new Slime(); var root = slime.setObject(); - if (testReport == null) - return slime; + toSlime(root.setObject("report"), (Node) report.root()); + + // TODO jonmv: remove + Map<TestReport.Status, Long> tally = report.root().tally(); var summary = root.setObject("summary"); - summary.setLong("success", testReport.successCount); - summary.setLong("failed", testReport.failedCount); - summary.setLong("ignored", testReport.ignoredCount); - summary.setLong("aborted", testReport.abortedCount); - summary.setLong("inconclusive", testReport.inconclusiveCount); - var failureRoot = summary.setArray("failures"); - testReport.failures.forEach(failure -> serializeFailure(failure, failureRoot.addObject())); - - var output = root.setArray("output"); - for (LogRecord record : testReport.logLines) - output.addString(formatter.format(record.getInstant().atOffset(ZoneOffset.UTC)) + " " + record.getMessage()); + summary.setLong("success", tally.getOrDefault(TestReport.Status.successful, 0L)); + summary.setLong("failed", tally.getOrDefault(TestReport.Status.failed, 0L) + tally.getOrDefault(TestReport.Status.error, 0L)); + summary.setLong("ignored", tally.getOrDefault(TestReport.Status.skipped, 0L)); + summary.setLong("aborted", tally.getOrDefault(TestReport.Status.aborted, 0L)); + summary.setLong("inconclusive", tally.getOrDefault(TestReport.Status.inconclusive, 0L)); + toSlime(summary.setArray("failures"), root.setArray("output"), report.root()); return slime; } - private static void serializeFailure(TestReport.Failure failure, Cursor slime) { - slime.setString("testName", failure.testId()); - slime.setString("testError",failure.exception().getMessage()); - slime.setString("exception", ExceptionUtils.getStackTraceAsString(failure.exception())); + static void toSlime(Cursor failuresArray, Cursor outputArray, Node node) { + for (Node child : node.children()) + TestRunnerHandler.toSlime(failuresArray, outputArray, child); + + if (node instanceof FailureNode) { + Cursor failureObject = failuresArray.addObject(); + failureObject.setString("testName", node.parent.name()); + failureObject.setString("testError", ((FailureNode) node).thrown().getMessage()); + failureObject.setString("exception", ExceptionUtils.getStackTraceAsString(((FailureNode) node).thrown())); + } + if (node instanceof OutputNode) + for (LogRecord record : ((OutputNode) node).log()) + outputArray.addString(formatter.format(record.getInstant().atOffset(ZoneOffset.UTC)) + " " + record.getMessage()); + } + + static void toSlime(Cursor nodeObject, Node node) { + if (node instanceof ContainerNode) toSlime(nodeObject, (ContainerNode) node); + if (node instanceof TestNode) toSlime(nodeObject, (TestNode) node); + if (node instanceof OutputNode) toSlime(nodeObject, (OutputNode) node); + if (node instanceof FailureNode) toSlime(nodeObject, (FailureNode) node); + + if ( ! node.children().isEmpty()) { + Cursor childrenArray = nodeObject.setArray("children"); + for (Node child : node.children) + toSlime(childrenArray.addObject(), child); + } + } + + static void toSlime(Cursor nodeObject, ContainerNode node) { + nodeObject.setString("type", "container"); + nodeObject.setString("name", node.name()); + nodeObject.setString("status", node.status().name()); + nodeObject.setLong("start", node.start().toEpochMilli()); + nodeObject.setLong("end", node.duration().toMillis()); + } + + static void toSlime(Cursor nodeObject, TestNode node) { + nodeObject.setString("type", "test"); + nodeObject.setString("name", node.name()); + nodeObject.setString("status", node.status().name()); + nodeObject.setLong("start", node.start().toEpochMilli()); + nodeObject.setLong("end", node.duration().toMillis()); + } + + static void toSlime(Cursor nodeObject, OutputNode node) { + nodeObject.setString("type", "output"); + Cursor childrenArray = nodeObject.setArray("children"); + for (LogRecord record : node.log()) { + Cursor recordObject = childrenArray.addObject(); + recordObject.setString("message", (record.getLoggerName() == null ? "" : record.getLoggerName() + ": ") + record.getMessage()); + recordObject.setLong("at", record.getInstant().toEpochMilli()); + recordObject.setString("level", typeOf(record.getLevel())); + if (record.getThrown() != null) recordObject.setString("trace", traceToString(record.getThrown())); + } + } + + static void toSlime(Cursor nodeObject, FailureNode node) { + nodeObject.setString("type", "failure"); + nodeObject.setString("status", node.status().name()); + nodeObject.setString("trace", traceToString(node.thrown())); + } + + private static String traceToString(Throwable thrown) { + ByteArrayOutputStream buffer = new ByteArrayOutputStream(); + thrown.printStackTrace(new PrintStream(buffer)); + return buffer.toString(UTF_8); } } diff --git a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/VespaJunitLogListener.java b/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/VespaJunitLogListener.java deleted file mode 100644 index b49f4e5e431..00000000000 --- a/vespa-osgi-testrunner/src/main/java/com/yahoo/vespa/testrunner/VespaJunitLogListener.java +++ /dev/null @@ -1,150 +0,0 @@ -// Copyright Yahoo. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. - -package com.yahoo.vespa.testrunner; - -import ai.vespa.hosted.cd.InconclusiveTestException; -import org.junit.platform.engine.TestExecutionResult; -import org.junit.platform.engine.UniqueId; -import org.junit.platform.engine.reporting.ReportEntry; -import org.junit.platform.launcher.TestExecutionListener; -import org.junit.platform.launcher.TestIdentifier; - -import java.time.ZoneOffset; -import java.util.ArrayList; -import java.util.HashMap; -import java.util.List; -import java.util.Map; -import java.util.NavigableMap; -import java.util.Set; -import java.util.concurrent.ConcurrentSkipListMap; -import java.util.concurrent.CopyOnWriteArrayList; -import java.util.function.Consumer; -import java.util.logging.Level; -import java.util.logging.LogRecord; - -import static java.util.Collections.emptyNavigableMap; -import static java.util.Objects.requireNonNull; -import static java.util.logging.Level.INFO; -import static java.util.logging.Level.SEVERE; -import static java.util.logging.Level.WARNING; -import static java.util.stream.Collectors.joining; - -class VespaJunitLogListener implements TestExecutionListener { - - private final Map<String, NavigableMap<Status, List<UniqueId>>> results = new ConcurrentSkipListMap<>(); - private final Consumer<LogRecord> logger; - - VespaJunitLogListener(Consumer<LogRecord> logger) { - this.logger = requireNonNull(logger); - } - - @Override - public void dynamicTestRegistered(TestIdentifier testIdentifier) { - if (testIdentifier.isContainer() && testIdentifier.getParentId().isPresent()) // Skip root engine level. - log(INFO, "Registered dynamic container: " + testIdentifier.getDisplayName()); - if (testIdentifier.isTest()) - log(INFO, "Registered dynamic test: " + testIdentifier.getDisplayName()); - } - - @Override - public void executionStarted(TestIdentifier testIdentifier) { - if (testIdentifier.isContainer() && testIdentifier.getParentId().isPresent()) // Skip root engine level. - log(INFO, "Running all tests in: " + testIdentifier.getDisplayName()); - if (testIdentifier.isTest()) - log(INFO, "Running test: " + testIdentifier.getDisplayName()); - } - - @Override - public void executionSkipped(TestIdentifier testIdentifier, String reason) { - log(WARNING, "Skipped: " + testIdentifier.getDisplayName() + ": " + reason); - if (testIdentifier.isTest()) - testIdentifier.getParentId().ifPresent(parent -> { - results.computeIfAbsent(parent, __ -> new ConcurrentSkipListMap<>()) - .computeIfAbsent(Status.skipped, __ -> new CopyOnWriteArrayList<>()) - .add(testIdentifier.getUniqueIdObject()); - }); - } - - @Override - public void executionFinished(TestIdentifier testIdentifier, TestExecutionResult testExecutionResult) { - if (testIdentifier.isContainer()) { - if (testIdentifier.getParentIdObject().isPresent()) { - NavigableMap<Status, List<UniqueId>> children = results.getOrDefault(testIdentifier.getUniqueId(), emptyNavigableMap()); - Level level = children.containsKey(Status.failed) ? SEVERE : INFO; - log(level, - "Tests in " + testIdentifier.getDisplayName() + " done: " + - children.entrySet().stream().map(entry -> entry.getValue().size() + " " + entry.getKey()).collect(joining(", "))); - } - else { - Map<Status, List<String>> testResults = new HashMap<>(); - results.forEach((__, results) -> results.forEach((status, tests) -> tests.forEach(test -> testResults.computeIfAbsent(status, ___ -> new ArrayList<>()) - .add(toString(test))))); - log(INFO, "Done running " + testResults.values().stream().mapToInt(List::size).sum() + " tests."); - testResults.forEach((status, tests) -> { - if (status != Status.successful) - log(status == Status.failed ? SEVERE : status == Status.inconclusive ? INFO : WARNING, - status.name().substring(0, 1).toUpperCase() + status.name().substring(1) + " tests:\n" + String.join("\n", tests)); - }); - } - } - if (testIdentifier.isTest()) { - Level level; - Status status; - if (testExecutionResult.getThrowable().map(InconclusiveTestException.class::isInstance).orElse(false)) { - level = INFO; - status = Status.inconclusive; - } - else { - switch (testExecutionResult.getStatus()) { - case SUCCESSFUL: level = INFO; status = Status.successful; break; - case ABORTED: level = WARNING; status = Status.aborted; break; - case FAILED: - default: level = SEVERE; status = Status.failed; break; - } - } - testIdentifier.getParentId().ifPresent(parent -> { - results.computeIfAbsent(parent, __ -> new ConcurrentSkipListMap<>()) - .computeIfAbsent(status, __ -> new CopyOnWriteArrayList<>()) - .add(testIdentifier.getUniqueIdObject()); - }); - log(level, "Test " + status + ": " + testIdentifier.getDisplayName(), testExecutionResult.getThrowable().orElse(null)); - } - } - - static String toString(UniqueId testId) { - return testId.getSegments().stream().skip(1).map(UniqueId.Segment::getValue).collect(joining(".")); - } - - @Override - public void reportingEntryPublished(TestIdentifier testIdentifier, ReportEntry report) { - String message = report.getKeyValuePairs().keySet().equals(Set.of("value")) - ? report.getKeyValuePairs().get("value") - : report.getKeyValuePairs().entrySet().stream() - .map(entry -> entry.getKey() + ": " + entry.getValue()) - .collect(joining("\n")); - LogRecord record = new LogRecord(INFO, message); - record.setInstant(report.getTimestamp().toInstant(ZoneOffset.UTC)); - logger.accept(record); - } - - private void log(Level level, String message) { - log(level, message, null); - } - - private void log(Level level, String message, Throwable thrown) { - LogRecord record = new LogRecord(level, message); - record.setThrown(thrown); - logger.accept(record); - } - - private enum Status { - - successful, - inconclusive, - failed, - aborted, - skipped; - - } - -} |