From e86f129d6d8a2b363050925440e530e863c5d7dd Mon Sep 17 00:00:00 2001 From: Matt Richardson Date: Fri, 13 Sep 2024 10:42:50 +1000 Subject: [PATCH] Improve logging, especially around cleanup --- .../server/TeamCityBuildListener.java | 16 ++++++++-------- .../HelperPerBuildOTELHelperFactory.java | 4 ++-- .../server/helpers/NullOTELHelperImpl.java | 5 ++++- .../server/helpers/OTELHelper.java | 5 ++++- .../server/helpers/OTELHelperImpl.java | 18 ++++++++++++------ .../opentelemetry/server/OTELHelperTest.java | 2 +- .../server/TeamCityBuildListenerTest.java | 2 +- 7 files changed, 32 insertions(+), 20 deletions(-) diff --git a/server/src/main/java/com/octopus/teamcity/opentelemetry/server/TeamCityBuildListener.java b/server/src/main/java/com/octopus/teamcity/opentelemetry/server/TeamCityBuildListener.java index b322269..13ae7de 100644 --- a/server/src/main/java/com/octopus/teamcity/opentelemetry/server/TeamCityBuildListener.java +++ b/server/src/main/java/com/octopus/teamcity/opentelemetry/server/TeamCityBuildListener.java @@ -60,7 +60,7 @@ public void buildStarted(@NotNull SRunningBuild build) { var rootBuildInChain = getRootBuildInChain(build); try (var ignored1 = CloseableThreadContext.put("teamcity.build.id", String.valueOf(build.getBuildId()))) { - LOG.debug(String.format("Build started method triggered for %s, id %d", getBuildName(build), build.getBuildId())); + LOG.debug(String.format("Build started method triggered for '%s', id %d", getBuildName(build), build.getBuildId())); try (var ignored2 = CloseableThreadContext.put("teamcity.root.build.id", String.valueOf(rootBuildInChain.getId()))) { @@ -77,7 +77,7 @@ public void buildStarted(@NotNull SRunningBuild build) { try (Scope ignored3 = rootSpan.makeCurrent()) { setSpanBuildAttributes(otelHelper, build, span, getBuildName(build), BUILD_SERVICE_NAME); span.addEvent(PluginConstants.EVENT_STARTED); - LOG.debug(String.format("%s event added to span for build %s, id %d", PluginConstants.EVENT_STARTED, getBuildName(build), build.getBuildId())); + LOG.debug(String.format("%s event added to span for build '%s', id %d", PluginConstants.EVENT_STARTED, getBuildName(build), build.getBuildId())); } catch (Exception e) { LOG.error("Exception in Build Start caused by: " + e + e.getCause() + ", with message: " + e.getMessage() + @@ -87,7 +87,7 @@ public void buildStarted(@NotNull SRunningBuild build) { } } } else { - LOG.info(String.format("Build start triggered for %s, id %d and plugin not ready. This build will not be traced.", getBuildName(build), build.getBuildId())); + LOG.info(String.format("Build start triggered for '%s', id %d and plugin not ready. This build will not be traced.", getBuildName(build), build.getBuildId())); } } } @@ -183,7 +183,7 @@ private void buildFinishedOrInterrupted (SRunningBuild build) { if (otelHelper.isReady()) { var span = otelHelper.getSpan(getBuildId(build)); if (span != null) { - LOG.debug("Build finished and span found for " + getBuildName(build)); + LOG.debug("Build finished and span found for '" + getBuildName(build) + "'"); try (Scope ignored3 = span.makeCurrent()) { createQueuedEventsSpans(build, span); createBuildStepSpans(build, span); @@ -198,7 +198,7 @@ private void buildFinishedOrInterrupted (SRunningBuild build) { this.checkoutTimeMap.remove(span.getSpanContext().getSpanId()); } span.addEvent(PluginConstants.EVENT_FINISHED); - LOG.debug(PluginConstants.EVENT_FINISHED + " event added to span for build " + getBuildName(build)); + LOG.debug(PluginConstants.EVENT_FINISHED + " event added to span for build '" + getBuildName(build) + "' id " + build.getBuildId()); } catch (Exception e) { LOG.error("Exception in Build Finish caused by: " + e + e.getCause() + ", with message: " + e.getMessage() + @@ -212,10 +212,10 @@ private void buildFinishedOrInterrupted (SRunningBuild build) { otelHelperFactory.release(build.getBuildId()); } } else { - LOG.warn("Build end triggered but span not found for build " + getBuildName(build) + " id " + build.getBuildId()); + LOG.warn("Build end triggered but span not found for build '" + getBuildName(build) + "' id " + build.getBuildId()); } } else { - LOG.warn(String.format("Build finished (or interrupted) for %s, id %d and plugin not ready.", getBuildName(build), build.getBuildId())); + LOG.warn(String.format("Build finished (or interrupted) for '%s', id %d and plugin not ready.", getBuildName(build), build.getBuildId())); } } } @@ -383,7 +383,7 @@ public boolean acceptMessage(@NotNull LogMessage message, boolean lastMessageInP private void setArtifactAttributes(SRunningBuild build, Span span) { if (build.isCompositeBuild()) return; - LOG.debug("Retrieving build artifact attributes for build: " + getBuildName(build) + " with id: " + getBuildId(build)); + LOG.debug("Retrieving build artifact attributes for build '" + getBuildName(build) + "' with id: " + getBuildId(build)); AtomicLong buildTotalArtifactSize = new AtomicLong(); BuildArtifacts buildArtifacts = build.getArtifacts(BuildArtifactsViewMode.VIEW_DEFAULT); buildArtifacts.iterateArtifacts(artifact -> { diff --git a/server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/HelperPerBuildOTELHelperFactory.java b/server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/HelperPerBuildOTELHelperFactory.java index f742b71..02c53ee 100644 --- a/server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/HelperPerBuildOTELHelperFactory.java +++ b/server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/HelperPerBuildOTELHelperFactory.java @@ -49,7 +49,7 @@ public OTELHelper getOTELHelper(BuildPromotion build) { spanProcessor = otelHandler.buildSpanProcessor(endpoint, params); long startTime = System.nanoTime(); - var otelHelper = new OTELHelperImpl(spanProcessor); + var otelHelper = new OTELHelperImpl(spanProcessor, String.valueOf(buildId)); long endTime = System.nanoTime(); long duration = (endTime - startTime); @@ -67,7 +67,7 @@ public OTELHelper getOTELHelper(BuildPromotion build) { public void release(Long buildId) { var helper = otelHelpers.get(buildId); if (helper != null) { - helper.release(); + helper.release(String.valueOf(buildId)); otelHelpers.remove(buildId); } } diff --git a/server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/NullOTELHelperImpl.java b/server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/NullOTELHelperImpl.java index a2bdb13..a95fe9f 100644 --- a/server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/NullOTELHelperImpl.java +++ b/server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/NullOTELHelperImpl.java @@ -2,6 +2,8 @@ import io.opentelemetry.api.trace.Span; +import javax.annotation.Nullable; + public class NullOTELHelperImpl implements OTELHelper { @Override public boolean isReady() { @@ -28,6 +30,7 @@ public void removeSpan(String buildId) { } @Override + @Nullable public Span getSpan(String buildId) { return null; } @@ -37,6 +40,6 @@ public void addAttributeToSpan(Span span, String attributeName, Object attribute } @Override - public void release() { + public void release(String helperName) { } } diff --git a/server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/OTELHelper.java b/server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/OTELHelper.java index 54b63cf..7be0134 100644 --- a/server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/OTELHelper.java +++ b/server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/OTELHelper.java @@ -2,6 +2,8 @@ import io.opentelemetry.api.trace.Span; +import javax.annotation.Nullable; + public interface OTELHelper { boolean isReady(); @@ -13,9 +15,10 @@ public interface OTELHelper { void removeSpan(String buildId); + @Nullable Span getSpan(String buildId); void addAttributeToSpan(Span span, String attributeName, Object attributeValue); - void release(); + void release(String helperName); } diff --git a/server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/OTELHelperImpl.java b/server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/OTELHelperImpl.java index 14badd9..9d87b58 100644 --- a/server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/OTELHelperImpl.java +++ b/server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/OTELHelperImpl.java @@ -15,6 +15,7 @@ import io.opentelemetry.semconv.resource.attributes.ResourceAttributes; import org.apache.log4j.Logger; +import javax.annotation.Nullable; import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.TimeUnit; @@ -24,8 +25,10 @@ public class OTELHelperImpl implements OTELHelper { private final Tracer tracer; private final ConcurrentHashMap spanMap; private final SdkTracerProvider sdkTracerProvider; + private final String helperName; - public OTELHelperImpl(SpanProcessor spanProcessor) { + public OTELHelperImpl(SpanProcessor spanProcessor, String helperName) { + this.helperName = helperName; Resource serviceNameResource = Resource .create(Attributes.of(ResourceAttributes.SERVICE_NAME, PluginConstants.SERVICE_NAME)); this.sdkTracerProvider = SdkTracerProvider.builder() @@ -68,13 +71,14 @@ public Span createTransientSpan(String spanName, Span parentSpan, long startTime } @Override - public void removeSpan(String buildId) { - this.spanMap.remove(buildId); + public void removeSpan(String spanName) { + this.spanMap.remove(spanName); } @Override - public Span getSpan(String buildId) { - return this.spanMap.get(buildId); + @Nullable + public Span getSpan(String spanName) { + return this.spanMap.get(spanName); } @Override @@ -83,7 +87,9 @@ public void addAttributeToSpan(Span span, String attributeName, Object attribute } @Override - public void release() { + public void release(String helperName) { + LOG.info("Cleaning up OTELHelperImpl named '" + helperName + "'; there are still " + this.spanMap.size() + " spans in the map"); + this.sdkTracerProvider.forceFlush(); this.sdkTracerProvider.close(); this.spanMap.clear(); diff --git a/server/src/test/java/com/octopus/teamcity/opentelemetry/server/OTELHelperTest.java b/server/src/test/java/com/octopus/teamcity/opentelemetry/server/OTELHelperTest.java index 183212f..a681496 100644 --- a/server/src/test/java/com/octopus/teamcity/opentelemetry/server/OTELHelperTest.java +++ b/server/src/test/java/com/octopus/teamcity/opentelemetry/server/OTELHelperTest.java @@ -32,7 +32,7 @@ class OTELHelperTest { @BeforeEach void setUp() { GlobalOpenTelemetry.resetForTest(); - this.otelHelper = new OTELHelperImpl(mock(SpanProcessor.class, RETURNS_DEEP_STUBS)); + this.otelHelper = new OTELHelperImpl(mock(SpanProcessor.class, RETURNS_DEEP_STUBS), "helperNamr"); } diff --git a/server/src/test/java/com/octopus/teamcity/opentelemetry/server/TeamCityBuildListenerTest.java b/server/src/test/java/com/octopus/teamcity/opentelemetry/server/TeamCityBuildListenerTest.java index 55c4d8a..edab60a 100644 --- a/server/src/test/java/com/octopus/teamcity/opentelemetry/server/TeamCityBuildListenerTest.java +++ b/server/src/test/java/com/octopus/teamcity/opentelemetry/server/TeamCityBuildListenerTest.java @@ -33,7 +33,7 @@ class TeamCityBuildListenerTest { @BeforeEach void setUp(@Mock EventDispatcher buildServerListenerEventDispatcher) { GlobalOpenTelemetry.resetForTest(); - this.otelHelper = new OTELHelperImpl(mock(SpanProcessor.class, RETURNS_DEEP_STUBS)); + this.otelHelper = new OTELHelperImpl(mock(SpanProcessor.class, RETURNS_DEEP_STUBS), "helper"); this.factory = mock(OTELHelperFactory.class, RETURNS_DEEP_STUBS); var buildStorageManager = mock(BuildStorageManager.class, RETURNS_DEEP_STUBS);