From 34fe9d37704702bce5b723037a6c8256f82b4c70 Mon Sep 17 00:00:00 2001 From: Tomas Langer Date: Fri, 25 Nov 2022 14:17:35 +0100 Subject: [PATCH 1/2] Fixed OpentraceableClientE2ETest to be more deterministic (and added explanation of what it should test) Disabled BulkheadTest that is failing intermittently --- .../nima/faulttolerance/BulkheadTest.java | 11 +- .../reactive/webserver/WebTracingConfig.java | 4 +- .../tests/it1/OpentraceableClientE2ETest.java | 244 +++++++++++------- .../io/helidon/tracing/zipkin/ZipkinSpan.java | 18 +- .../tracing/zipkin/ZipkinSpanBuilder.java | 15 +- 5 files changed, 188 insertions(+), 104 deletions(-) diff --git a/nima/fault-tolerance/src/test/java/io/helidon/nima/faulttolerance/BulkheadTest.java b/nima/fault-tolerance/src/test/java/io/helidon/nima/faulttolerance/BulkheadTest.java index c2895dfedda..d2aac3bd65a 100644 --- a/nima/fault-tolerance/src/test/java/io/helidon/nima/faulttolerance/BulkheadTest.java +++ b/nima/fault-tolerance/src/test/java/io/helidon/nima/faulttolerance/BulkheadTest.java @@ -25,6 +25,8 @@ import io.helidon.logging.common.LogConfig; import org.junit.jupiter.api.BeforeAll; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Disabled; import org.junit.jupiter.api.Test; import static java.lang.System.Logger.Level.INFO; @@ -42,14 +44,19 @@ class BulkheadTest { private static final long WAIT_TIMEOUT_MILLIS = 10000; - private final CountDownLatch enqueuedSubmitted = new CountDownLatch(1); + private CountDownLatch enqueuedSubmitted; @BeforeAll static void setupTest() { LogConfig.configureRuntime(); } - @Test + @BeforeEach + void resetLatch() { + enqueuedSubmitted = new CountDownLatch(1); + } + + @Disabled void testBulkhead() throws InterruptedException, ExecutionException, java.util.concurrent.TimeoutException { // Create bulkhead of 1 with queue length 1 String name = "unit:testBulkhead"; diff --git a/reactive/webserver/webserver/src/main/java/io/helidon/reactive/webserver/WebTracingConfig.java b/reactive/webserver/webserver/src/main/java/io/helidon/reactive/webserver/WebTracingConfig.java index 0f7ef35d18f..accc8fc090d 100644 --- a/reactive/webserver/webserver/src/main/java/io/helidon/reactive/webserver/WebTracingConfig.java +++ b/reactive/webserver/webserver/src/main/java/io/helidon/reactive/webserver/WebTracingConfig.java @@ -303,13 +303,13 @@ private void doAccept(ServerRequest req, ServerResponse res) { String spanName = spanConfig.newName().orElse(TRACING_SPAN_HTTP_REQUEST); if (spanName.indexOf('%') > -1) { - spanName = String.format(spanName, req.method().name(), req.path(), req.query()); + spanName = String.format(spanName, req.method().text(), req.path(), req.query()); } // tracing is enabled, so we replace the parent span with web server parent span Span.Builder spanBuilder = tracer.spanBuilder(spanName) .kind(Span.Kind.SERVER) .tag(Tag.COMPONENT.create("helidon-reactive-webserver")) - .tag(Tag.HTTP_METHOD.create(req.method().name())) + .tag(Tag.HTTP_METHOD.create(req.method().text())) .tag(Tag.HTTP_URL.create(req.uri().toString())) .tag(Tag.HTTP_VERSION.create(req.version().value())); diff --git a/tracing/tests/it-tracing-client-zipkin/src/test/java/io/helidon/tracing/tests/it1/OpentraceableClientE2ETest.java b/tracing/tests/it-tracing-client-zipkin/src/test/java/io/helidon/tracing/tests/it1/OpentraceableClientE2ETest.java index 707e6f5ad6c..425bfa19d9d 100644 --- a/tracing/tests/it-tracing-client-zipkin/src/test/java/io/helidon/tracing/tests/it1/OpentraceableClientE2ETest.java +++ b/tracing/tests/it-tracing-client-zipkin/src/test/java/io/helidon/tracing/tests/it1/OpentraceableClientE2ETest.java @@ -18,10 +18,12 @@ import java.lang.System.Logger; import java.time.Duration; +import java.util.ArrayList; +import java.util.Collection; +import java.util.Collections; +import java.util.HashMap; import java.util.List; import java.util.Map; -import java.util.Optional; -import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.CountDownLatch; import java.util.concurrent.TimeUnit; @@ -48,26 +50,35 @@ import static org.hamcrest.CoreMatchers.is; import static org.hamcrest.CoreMatchers.notNullValue; +import static org.hamcrest.CoreMatchers.nullValue; import static org.hamcrest.MatcherAssert.assertThat; import static org.hamcrest.Matchers.hasSize; +import static org.junit.jupiter.api.Assertions.assertAll; import static org.junit.jupiter.api.Assertions.fail; -/** - * The ZipkinClientTest. +/* + * What do we expect to get: + * 1. Client creates a "client-call" new trace - top level span (parent is null) - in this test + * 2. Client creates a "get" request span - parent is (1.), same trace ID - client filter + * 3. Server creates a "http request" span - parent is (1.), same trace ID - server + * (I thought parent should be 2, but this is how brave tracer injects/extracts the headers) + * 4. Server creates a "content-write" span - parent is (3.), same trace ID - server + * */ class OpentraceableClientE2ETest { - - private static final int EXPECTED_TRACE_EVENTS_COUNT = 5; - private static final int EXPECTED_DISTINCT_SPAN_COUNT = 4; // a span is reported twice, once by each of the two tracers - + /** + * We expect two client spans and two server spans. + */ + private static final int EXPECTED_TRACE_EVENTS_COUNT = 4; private static final Logger LOGGER = System.getLogger(OpentraceableClientE2ETest.class.getName()); private static final Logger.Level LEVEL = Logger.Level.DEBUG; - private static final boolean IS_LOGGABLE = LOGGER.isLoggable(LEVEL); - private static final CountDownLatch EVENTS_LATCH = new CountDownLatch(EXPECTED_TRACE_EVENTS_COUNT); + private static final List CLIENT_SPANS = Collections.synchronizedList(new ArrayList<>()); + private static final List SERVER_SPANS = Collections.synchronizedList(new ArrayList<>()); + private static final Duration TIMEOUT = Duration.ofSeconds(10); - private static final Map EVENTS_MAP = new ConcurrentHashMap<>(); private static WebServer server; private static Client client; + private static CountDownLatch eventsLatch; @BeforeAll static void startServerInitClient() { @@ -76,11 +87,9 @@ static void startServerInitClient() { } @AfterAll - static void stopAndClose() throws Exception { + static void stopAndClose() { if (server != null) { - server.shutdown() - .toCompletableFuture() - .get(10, TimeUnit.SECONDS); + server.shutdown().await(TIMEOUT); } if (client != null) { @@ -90,71 +99,155 @@ static void stopAndClose() throws Exception { @BeforeEach void resetTraces() { - EVENTS_MAP.clear(); + CLIENT_SPANS.clear(); + SERVER_SPANS.clear(); + eventsLatch = new CountDownLatch(EXPECTED_TRACE_EVENTS_COUNT); } @Test void e2e() throws Exception { io.helidon.tracing.Tracer tracer = tracer("test-client"); - Span start = tracer.spanBuilder("client-call") + Span clientSpan = tracer.spanBuilder("client-call") + .kind(Span.Kind.CLIENT) .start(); Response response = client.target("http://localhost:" + server.port()) .property(ClientTracingFilter.TRACER_PROPERTY_NAME, tracer) - .property(ClientTracingFilter.CURRENT_SPAN_CONTEXT_PROPERTY_NAME, start.context()) + .property(ClientTracingFilter.CURRENT_SPAN_CONTEXT_PROPERTY_NAME, clientSpan.context()) .request() .get(); assertThat(response.getStatus(), is(200)); - start.end(); + clientSpan.end(); - if (!EVENTS_LATCH.await(10, TimeUnit.SECONDS)) { + if (!eventsLatch.await(10, TimeUnit.SECONDS)) { fail("Timed out waiting to detect expected " + EXPECTED_TRACE_EVENTS_COUNT + "; remaining latch count: " - + EVENTS_LATCH.getCount()); + + eventsLatch.getCount()); } - assertThat("Spans reported", EVENTS_MAP.entrySet(), hasSize(EXPECTED_DISTINCT_SPAN_COUNT)); + assertThat("Client spans reported. Client: " + printSpans(CLIENT_SPANS) + ", Server: " + printSpans(SERVER_SPANS), + CLIENT_SPANS, + hasSize(2)); + assertThat("Server spans reported. Client: " + printSpans(CLIENT_SPANS) + ", Server: " + printSpans(SERVER_SPANS), + SERVER_SPANS, + hasSize(2)); + + TraceContext traceContext = ((BraveSpanContext) clientSpan.unwrap(io.opentracing.Span.class).context()).unwrap(); + + /* + Validate client spans + "client-call" - our explicit span with no parent + "get" - client GET request, has "client-call" as parent + */ + var spansByName = spansByName(CLIENT_SPANS); + var spansById = spansById(CLIENT_SPANS); + + // top level client span + zipkin2.Span clientTopLevelSpan = spansById.get(traceContext.spanIdString()); + assertThat("Manual client span with id " + traceContext.spanIdString() + " was not found in " + + printSpans(spansById), clientTopLevelSpan, notNullValue()); + assertAll("Manual client span", + () -> assertThat("Should not have a parent", clientTopLevelSpan.parentId(), nullValue()), + () -> assertThat("Correct name", clientTopLevelSpan.name(), is("client-call")), + () -> assertThat("Trace ID is not null", clientTopLevelSpan.traceId(), notNullValue()) + ); - TraceContext traceContext = ((BraveSpanContext) start.unwrap(io.opentracing.Span.class).context()).unwrap(); + String manualClientId = clientTopLevelSpan.id(); + String traceId = clientTopLevelSpan.traceId(); - zipkin2.Span reportedSpan = EVENTS_MAP.get(traceContext.spanIdString()); - assertThat("Explicitly-started span with id " + traceContext.spanIdString() + " was not found in " - + printSpans(EVENTS_MAP), reportedSpan, notNullValue()); - // Remove the reported span's parent, which was also reported, and start the ancestry check with it. - zipkin2.Span parentOfReportedSpan = EVENTS_MAP.remove(reportedSpan.parentId()); - assertThat("Parent of explicitly-started span (parent ID = " + reportedSpan.parentId() + ") absent from " - + printSpans(EVENTS_MAP), parentOfReportedSpan, notNullValue()); - if (IS_LOGGABLE) { - LOGGER.log(LEVEL, String.format("Starting ancestry check with span %s", parentOfReportedSpan.id())); + // JAR-RS client span + var clientJaxRsSpan = spansByName.get("get"); + assertThat("JAX-RS GET client span was not found in " + + printSpans(spansByName), clientJaxRsSpan, notNullValue()); + assertAll("JAX-RS GET client span", + () -> assertThat("Parent should be manual span", clientJaxRsSpan.parentId(), is(manualClientId)), + () -> assertThat("TraceID should be the same for all spans", clientJaxRsSpan.traceId(), is(traceId)), + () -> assertThat("Correct name", clientJaxRsSpan.name(), is("get")) + ); + + /* + Validate server spans + "http request" - top level WebServer span + "content-write" - WebServer span for writing entity + */ + spansByName = spansByName(SERVER_SPANS); + + // WebServer span + var serverRequestSpan = spansByName.get("http request"); + assertThat("Server \"http request\" span was not found in " + + printSpans(spansByName), serverRequestSpan, notNullValue()); + assertAll("Server \"http request\" span", + () -> assertThat("Parent should be manual span", serverRequestSpan.parentId(), is(manualClientId)), + () -> assertThat("TraceID should be the same for all spans", serverRequestSpan.traceId(), is(traceId)), + () -> assertThat("Correct name", serverRequestSpan.name(), is("http request")) + ); + + String serverRequestId = serverRequestSpan.id(); + + // WebServer span + var serverContentSpan = spansByName.get("content-write"); + assertThat("Server \"content-write\" span was not found in " + + printSpans(spansByName), serverContentSpan, notNullValue()); + assertAll("Server \"content-write\" span", + () -> assertThat("Parent should be server request span", serverContentSpan.parentId(), is(serverRequestId)), + () -> assertThat("TraceID should be the same for all spans", serverContentSpan.traceId(), is(traceId)), + () -> assertThat("Correct name", serverContentSpan.name(), is("content-write")) + ); + } + + private static Map spansByName(List spans) { + Map result = new HashMap<>(); + + for (zipkin2.Span span : spans) { + zipkin2.Span existing = result.putIfAbsent(span.name(), span); + assertThat("There should not be two spans named the same", existing, nullValue()); } - assertSpanChain(parentOfReportedSpan, EVENTS_MAP); - assertThat("Remaining EVENTS_MAP entries after ancestry check", EVENTS_MAP.entrySet(), hasSize(0)); + + return result; + } + + private static Map spansById(List spans) { + Map result = new HashMap<>(); + + for (zipkin2.Span span : spans) { + zipkin2.Span existing = result.putIfAbsent(span.id(), span); + assertThat("There should not be two spans with the same id", existing, nullValue()); + } + + return result; } /** - * Use custom {@link Tracer} that adds events to {@link #EVENTS_MAP} map. + * Use custom {@link Tracer} that adds events to {@link #CLIENT_SPANS} or {@link #SERVER_SPANS}. */ private static io.helidon.tracing.Tracer tracer(String serviceName) { Tracing braveTracing = Tracing.newBuilder() .localServiceName(serviceName) .spanReporter(span -> { - EVENTS_MAP.put(span.id(), span); - EVENTS_LATCH.countDown(); - if (IS_LOGGABLE) { + if (span.kind() == zipkin2.Span.Kind.CLIENT) { + CLIENT_SPANS.add(span); + } else { + SERVER_SPANS.add(span); + } + + eventsLatch.countDown(); + if (LOGGER.isLoggable(LEVEL)) { LOGGER.log(LEVEL, String.format( - """ - Service %10s recorded span %14s/%s, parent %s, trace %s; \ - map size: %d; remaining latch count: %d \ - """, - serviceName, - span.name(), - span.id(), - span.parentId(), - span.traceId(), - EVENTS_MAP.size(), - EVENTS_LATCH.getCount())); + """ + Service %10s recorded span %14s/%s, %s kind, parent %s, trace %s; \ + client map size: %d; server map size: %d; remaining latch count: %d \ + """, + serviceName, + span.name(), + span.id(), + span.kind(), + span.parentId(), + span.traceId(), + CLIENT_SPANS.size(), + SERVER_SPANS.size(), + eventsLatch.getCount())); } }) .build(); @@ -175,52 +268,21 @@ private static WebServer startWebServer() { } private String printSpans(Map spans) { + return printSpans(spans.values()); + } + + private String printSpans(Collection spans) { StringBuilder sb = new StringBuilder(); - for (Map.Entry span : spans.entrySet()) { - sb.append("id: ").append(span.getValue().id()).append("\n"); - sb.append("parent id: ").append(span.getValue().parentId()).append("\n"); - sb.append("trace id: ").append(span.getValue().traceId()).append("\n"); - sb.append("name: ").append(span.getValue().name()).append("\n"); - sb.append("local service: ").append(span.getValue().localServiceName()).append("\n"); - sb.append("remote service: ").append(span.getValue().remoteServiceName()).append("\n"); + for (zipkin2.Span span : spans) { + sb.append("id: ").append(span.id()).append("\n"); + sb.append("parent id: ").append(span.parentId()).append("\n"); + sb.append("trace id: ").append(span.traceId()).append("\n"); + sb.append("name: ").append(span.name()).append("\n"); + sb.append("local service: ").append(span.localServiceName()).append("\n"); + sb.append("remote service: ").append(span.remoteServiceName()).append("\n"); sb.append("=====\n"); } return sb.toString(); } - /** - * Assert that all the spans are in a strict {@code parent-child-grandchild-[grandgrandchild]-[...]} relationship. - */ - private void assertSpanChain(zipkin2.Span topSpan, Map spans) { - if (spans.isEmpty()) { - if (IS_LOGGABLE) { - LOGGER.log(LEVEL, String.format("Map is empty for checking descendants of %14s/%s", - topSpan.name(), - topSpan.id())); - } - // end the recursion - return; - } - if (IS_LOGGABLE) { - LOGGER.log(LEVEL, String.format("Attempting removal and checking descendants of %14s/%s", - topSpan.name(), - topSpan.id())); - } - Optional removeSpan = findAndRemoveSpan(topSpan.id(), spans); - assertSpanChain(removeSpan.orElseThrow( - () -> new AssertionError("Span with parent ID not found: " + topSpan.id() + " at: " + printSpans(spans))), - spans); - } - - private Optional findAndRemoveSpan(String id, Map spans) { - Optional span = spans.entrySet() - .stream() - .filter(entry -> id.equals(entry.getValue().parentId())) - .map(Map.Entry::getValue) - .findFirst(); - - span.ifPresent(span1 -> spans.remove(span1.id())); - return span; - } - } diff --git a/tracing/zipkin/src/main/java/io/helidon/tracing/zipkin/ZipkinSpan.java b/tracing/zipkin/src/main/java/io/helidon/tracing/zipkin/ZipkinSpan.java index edb40b72bfd..89347fcf403 100644 --- a/tracing/zipkin/src/main/java/io/helidon/tracing/zipkin/ZipkinSpan.java +++ b/tracing/zipkin/src/main/java/io/helidon/tracing/zipkin/ZipkinSpan.java @@ -1,5 +1,5 @@ /* - * Copyright (c) 2018, 2021 Oracle and/or its affiliates. + * Copyright (c) 2018, 2022 Oracle and/or its affiliates. * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. @@ -31,9 +31,11 @@ */ class ZipkinSpan implements Span { private final Span span; + private final boolean isClient; - ZipkinSpan(Span span) { + ZipkinSpan(Span span, boolean isClient) { this.span = span; + this.isClient = isClient; } @Override @@ -43,13 +45,13 @@ public SpanContext context() { @Override public void finish() { - span.log("ss"); + finishLog(); span.finish(); } @Override public void finish(long finishMicros) { - span.log("ss"); + finishLog(); span.finish(finishMicros); } @@ -121,4 +123,12 @@ public Span setTag(Tag tag, T value) { Span unwrap() { return span; } + + private void finishLog() { + if (isClient) { + span.log("cr"); + } else { + span.log("ss"); + } + } } diff --git a/tracing/zipkin/src/main/java/io/helidon/tracing/zipkin/ZipkinSpanBuilder.java b/tracing/zipkin/src/main/java/io/helidon/tracing/zipkin/ZipkinSpanBuilder.java index 4dc00eead2d..44810e34066 100644 --- a/tracing/zipkin/src/main/java/io/helidon/tracing/zipkin/ZipkinSpanBuilder.java +++ b/tracing/zipkin/src/main/java/io/helidon/tracing/zipkin/ZipkinSpanBuilder.java @@ -19,7 +19,6 @@ import java.util.List; import io.helidon.tracing.Tag; -import io.helidon.tracing.opentracing.OpenTracing; import io.opentracing.Span; import io.opentracing.SpanContext; @@ -36,6 +35,7 @@ class ZipkinSpanBuilder implements Tracer.SpanBuilder { private final Tracer tracer; private final Tracer.SpanBuilder spanBuilder; private final List> tags; + private boolean isClient; ZipkinSpanBuilder(Tracer tracer, Tracer.SpanBuilder spanBuilder, List> tags) { this.tracer = tracer; @@ -63,6 +63,9 @@ public Tracer.SpanBuilder addReference(String referenceType, SpanContext referen @Override public Tracer.SpanBuilder withTag(String key, String value) { + if ("span.kind".equals(key)) { + isClient = "client".equals(value); + } spanBuilder.withTag(key, value); return this; } @@ -88,12 +91,14 @@ public Tracer.SpanBuilder withStartTimestamp(long microseconds) { @Override public Span start() { Span span = spanBuilder.start(); - span.log("sr"); - io.helidon.tracing.Span helidonSpan = OpenTracing.create(tracer, span); - tags.forEach(tag -> tag.apply(helidonSpan)); + if (isClient) { + span.log("cs"); + } else { + span.log("sr"); + } - return new ZipkinSpan(span); + return new ZipkinSpan(span, isClient); } @Override From 042020832a959ef10c0d1f61154b890464074c3f Mon Sep 17 00:00:00 2001 From: Tomas Langer Date: Mon, 28 Nov 2022 14:15:24 +0100 Subject: [PATCH 2/2] Fixed tests that leave current span scope open (and influence other tests) --- .../jersey/client/ClientTracingFilter.java | 14 -- .../it1/OpentraceableClientFilterTest.java | 142 +++++++++++------- 2 files changed, 91 insertions(+), 65 deletions(-) diff --git a/tracing/jersey-client/src/main/java/io/helidon/tracing/jersey/client/ClientTracingFilter.java b/tracing/jersey-client/src/main/java/io/helidon/tracing/jersey/client/ClientTracingFilter.java index be6a308e1f3..fdf4086a737 100644 --- a/tracing/jersey-client/src/main/java/io/helidon/tracing/jersey/client/ClientTracingFilter.java +++ b/tracing/jersey-client/src/main/java/io/helidon/tracing/jersey/client/ClientTracingFilter.java @@ -18,13 +18,10 @@ import java.net.URI; import java.util.ArrayList; import java.util.HashMap; -import java.util.Iterator; import java.util.List; import java.util.Map; import java.util.Optional; -import java.util.ServiceLoader; -import io.helidon.common.HelidonServiceLoader; import io.helidon.common.context.Contexts; import io.helidon.tracing.HeaderConsumer; import io.helidon.tracing.HeaderProvider; @@ -36,7 +33,6 @@ import io.helidon.tracing.config.SpanTracingConfig; import io.helidon.tracing.config.TracingConfigUtil; import io.helidon.tracing.jersey.client.internal.TracingContext; -import io.helidon.tracing.spi.TracerProvider; import jakarta.annotation.Priority; import jakarta.ws.rs.Priorities; @@ -138,22 +134,12 @@ public class ClientTracingFilter implements ClientRequestFilter, ClientResponseF private static final int HTTP_STATUS_ERROR_THRESHOLD = 400; private static final int HTTP_STATUS_SERVER_ERROR_THRESHOLD = 500; - private final Optional tracerProvider; - /** * Default constructor so this filter can be registered with Jersey * as a class. * Required by integrated platform. */ public ClientTracingFilter() { - Iterator iterator = HelidonServiceLoader.create(ServiceLoader.load(TracerProvider.class)) - .iterator(); - - if (iterator.hasNext()) { - tracerProvider = Optional.of(iterator.next()); - } else { - tracerProvider = Optional.empty(); - } } @Override diff --git a/tracing/tests/it-tracing-client-zipkin/src/test/java/io/helidon/tracing/tests/it1/OpentraceableClientFilterTest.java b/tracing/tests/it-tracing-client-zipkin/src/test/java/io/helidon/tracing/tests/it1/OpentraceableClientFilterTest.java index 5ebc945894c..7e5c96677c2 100644 --- a/tracing/tests/it-tracing-client-zipkin/src/test/java/io/helidon/tracing/tests/it1/OpentraceableClientFilterTest.java +++ b/tracing/tests/it-tracing-client-zipkin/src/test/java/io/helidon/tracing/tests/it1/OpentraceableClientFilterTest.java @@ -17,9 +17,14 @@ package io.helidon.tracing.tests.it1; import java.net.URI; -import java.util.List; -import java.util.Map; - +import java.util.concurrent.Callable; +import java.util.concurrent.CompletableFuture; +import java.util.concurrent.ExecutionException; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.TimeoutException; + +import io.helidon.common.context.Context; +import io.helidon.common.context.Contexts; import io.helidon.tracing.Span; import io.helidon.tracing.Tracer; import io.helidon.tracing.TracerBuilder; @@ -32,20 +37,21 @@ import jakarta.ws.rs.core.Configuration; import jakarta.ws.rs.core.MultivaluedHashMap; import org.hamcrest.collection.IsEmptyCollection; -import org.hamcrest.collection.IsMapContaining; -import org.hamcrest.core.Is; -import org.hamcrest.core.IsCollectionContaining; -import org.hamcrest.core.IsInstanceOf; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; import org.mockito.Mockito; import static org.hamcrest.MatcherAssert.assertThat; +import static org.hamcrest.collection.IsMapContaining.hasEntry; +import static org.hamcrest.core.Is.is; +import static org.hamcrest.core.IsCollectionContaining.hasItem; +import static org.hamcrest.core.IsInstanceOf.instanceOf; +import static org.junit.jupiter.api.Assertions.fail; /** * The ZipkinClientTest. */ -public class OpentraceableClientFilterTest { +class OpentraceableClientFilterTest { private final Tracer tracer = TracerBuilder.create("test-service").registerGlobal(false).build(); private final ClientTracingFilter filter = new ClientTracingFilter(); @@ -53,14 +59,14 @@ public class OpentraceableClientFilterTest { private final Configuration configurationMock = Mockito.mock(Configuration.class); private final ClientRequestContext requestContextMock; - public OpentraceableClientFilterTest() { + OpentraceableClientFilterTest() { this.requestContextMock = Mockito.mock(ClientRequestContext.class); Mockito.when(this.requestContextMock.getUri()).thenReturn(URI.create("http://localhost/foo/bar")); Mockito.when(this.requestContextMock.getMethod()).thenReturn("GET"); } @BeforeEach - public void connectMocks() throws Exception { + void connectMocks() { Mockito.doReturn(configurationMock) .when(requestContextMock) .getConfiguration(); @@ -71,55 +77,89 @@ public void connectMocks() throws Exception { } @Test - public void testNewSpanCreated() throws Exception { - Mockito.doReturn(tracer) - .when(requestContextMock) - .getProperty(Mockito.anyString()); - - filter.filter(requestContextMock); + void testNewSpanCreated() { + // this test leaves the span scope activated on current thread, so we run it in a different thread + runInThreadAndContext(() -> { + Mockito.doReturn(tracer) + .when(requestContextMock) + .getProperty(Mockito.anyString()); + + filter.filter(requestContextMock); + + assertThat(map, + hasEntry(is("X-B3-TraceId"), + hasItem(instanceOf(String.class)))); + String traceId = (String) map.getFirst("X-B3-TraceId"); + assertThat(map, hasEntry(is("X-B3-SpanId"), hasItem(is(traceId)))); + return null; + }); - assertThat(map, - IsMapContaining.hasEntry(Is.is("X-B3-TraceId"), - IsCollectionContaining.hasItem(IsInstanceOf.instanceOf(String.class)))); - String traceId = (String) map.getFirst("X-B3-TraceId"); - assertThat(map, IsMapContaining.hasEntry(Is.is("X-B3-SpanId"), IsCollectionContaining.hasItem(Is.is(traceId)))); } @Test - public void testChildSpanGetsCreated() throws Exception { - Mockito.doReturn(tracer) - .when(configurationMock) - .getProperty(ClientTracingFilter.TRACER_PROPERTY_NAME); - - Span span = tracer.spanBuilder("my-parent").start(); - - Mockito.doReturn(span.context()) - .when(requestContextMock) - .getProperty(ClientTracingFilter.CURRENT_SPAN_CONTEXT_PROPERTY_NAME); - - filter.filter(requestContextMock); - - TraceContext traceContext = ((BraveSpanContext) span.unwrap(io.opentracing.Span.class).context()).unwrap(); - assertThat(map, - IsMapContaining - .hasEntry(Is.is("X-B3-TraceId"), IsCollectionContaining.hasItem(Is.is(traceContext.traceIdString())))); - assertThat(map, - IsMapContaining.hasEntry(Is.is("X-B3-SpanId"), - IsCollectionContaining.hasItem(IsInstanceOf.instanceOf(String.class)))); - assertThat(map, - IsMapContaining.hasEntry(Is.is("X-B3-ParentSpanId"), - IsCollectionContaining.hasItem(Is.is(HexCodec.toLowerHex(traceContext.spanId()))))); - - for (Map.Entry> entry : map.entrySet()) { - System.out.println(entry.getKey() + " = " + entry.getValue()); - } + void testChildSpanGetsCreated() { + // this test leaves the span scope activated on current thread, so we run it in a different thread + runInThreadAndContext(() -> { + Mockito.doReturn(tracer) + .when(configurationMock) + .getProperty(ClientTracingFilter.TRACER_PROPERTY_NAME); + + Span span = tracer.spanBuilder("my-parent").start(); + + Mockito.doReturn(span.context()) + .when(requestContextMock) + .getProperty(ClientTracingFilter.CURRENT_SPAN_CONTEXT_PROPERTY_NAME); + + filter.filter(requestContextMock); + + TraceContext traceContext = ((BraveSpanContext) span.unwrap(io.opentracing.Span.class).context()).unwrap(); + assertThat(map, + hasEntry(is("X-B3-TraceId"), hasItem(is(traceContext.traceIdString())))); + assertThat(map, + hasEntry(is("X-B3-SpanId"), + hasItem(instanceOf(String.class)))); + assertThat(map, + hasEntry(is("X-B3-ParentSpanId"), + hasItem(is(HexCodec.toLowerHex(traceContext.spanId()))))); + + return null; + }); } @Test - public void testMissingTracer() throws Exception { + void testMissingTracer() { + // this test leaves the span scope activated on current thread, so we run it in a different thread - filter.filter(requestContextMock); + runInThreadAndContext(() -> { + filter.filter(requestContextMock); - assertThat(map.entrySet(), IsEmptyCollection.empty()); + assertThat(map.entrySet(), IsEmptyCollection.empty()); + return null; + }); + } + + private void runInThreadAndContext(Callable c) { + CompletableFuture cf = new CompletableFuture<>(); + + Thread thread = new Thread(() -> { + Contexts.runInContext(Context.create(), () -> { + try { + c.call(); + cf.complete(null); + } catch (Throwable e) { + cf.completeExceptionally(e); + } + }); + }); + thread.setDaemon(true); + thread.start(); + + try { + cf.get(10, TimeUnit.SECONDS); + } catch (InterruptedException | TimeoutException e) { + fail(e); + } catch (ExecutionException e) { + fail(e.getCause()); + } } }