From ccd1c47fe341e37008afacd7034d21d121cd5ff3 Mon Sep 17 00:00:00 2001 From: "tim.quinn@oracle.com" Date: Fri, 28 Oct 2022 14:08:11 -0500 Subject: [PATCH 1/2] Fix problems in tracing e2e test Signed-off-by: tim.quinn@oracle.com --- .../tests/it1/OpentraceableClientE2ETest.java | 57 ++++++++++++++++--- 1 file changed, 50 insertions(+), 7 deletions(-) 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 58d00e10014..55b57e48e6c 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 @@ -16,6 +16,7 @@ package io.helidon.tracing.tests.it1; +import java.lang.System.Logger; import java.time.Duration; import java.util.List; import java.util.Map; @@ -56,8 +57,14 @@ */ class OpentraceableClientE2ETest { - private static final int EXPECTED_TRACE_EVENTS_COUNT = 4; + 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 + + 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 Map EVENTS_MAP = new ConcurrentHashMap<>(); private static WebServer server; private static Client client; @@ -102,16 +109,28 @@ void e2e() throws Exception { start.end(); if (!EVENTS_LATCH.await(10, TimeUnit.SECONDS)) { - fail("Expected " + EXPECTED_TRACE_EVENTS_COUNT + " trace events but received only: " + EVENTS_MAP.size()); + fail("Timed out waiting to detect expected " + + EXPECTED_TRACE_EVENTS_COUNT + + "; remaining latch count: " + + EVENTS_LATCH.getCount()); } + assertThat("Spans reported", EVENTS_MAP.entrySet(), hasSize(EXPECTED_DISTINCT_SPAN_COUNT)); + TraceContext traceContext = ((BraveSpanContext) start.unwrap(io.opentracing.Span.class).context()).unwrap(); - zipkin2.Span reportedSpan = EVENTS_MAP.remove(traceContext.traceIdString()); - assertThat("Span with id " + reportedSpan.traceId() + " was not found in " + 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()); - assertSpanChain(reportedSpan, EVENTS_MAP); - assertThat(EVENTS_MAP.entrySet(), hasSize(0)); + // 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())); + } + assertSpanChain(parentOfReportedSpan, EVENTS_MAP); + assertThat("Remaining EVENTS_MAP entries after ancestry check", EVENTS_MAP.entrySet(), hasSize(0)); } /** @@ -121,8 +140,22 @@ private static io.helidon.tracing.Tracer tracer(String serviceName) { Tracing braveTracing = Tracing.newBuilder() .localServiceName(serviceName) .spanReporter(span -> { - EVENTS_MAP.put(span.traceId(), span); + EVENTS_MAP.put(span.id(), span); EVENTS_LATCH.countDown(); + if (IS_LOGGABLE) { + 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())); + } }) .build(); @@ -160,9 +193,19 @@ private String printSpans(Map spans) { */ 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))), From edb7cffca725ae10ff6598aa6e0f7a7394d98648 Mon Sep 17 00:00:00 2001 From: "tim.quinn@oracle.com" Date: Sat, 29 Oct 2022 07:21:28 -0500 Subject: [PATCH 2/2] Suppress newlines in block text for logging msg --- .../helidon/tracing/tests/it1/OpentraceableClientE2ETest.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) 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 55b57e48e6c..707e6f5ad6c 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 @@ -145,8 +145,8 @@ private static io.helidon.tracing.Tracer tracer(String serviceName) { if (IS_LOGGABLE) { LOGGER.log(LEVEL, String.format( """ - Service %10s recorded span %14s/%s, parent %s, trace %s; - map size: %d; remaining latch count: %d + Service %10s recorded span %14s/%s, parent %s, trace %s; \ + map size: %d; remaining latch count: %d \ """, serviceName, span.name(),