Skip to content

Commit

Permalink
Improve logging, especially around cleanup (#313)
Browse files Browse the repository at this point in the history
  • Loading branch information
@matt-richardson
matt-richardson authored Sep 13, 2024
1 parent c7f6156 commit 80c0661
Show file tree
Hide file tree
Showing 7 changed files with 41 additions and 23 deletions.
28 changes: 17 additions & 11 deletions server/src/main/java/com/octopus/teamcity/opentelemetry/server/TeamCityBuildListener.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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()))) {

Expand All @@ -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() +
Expand All @@ -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()));
}
}
}
Expand Down Expand Up @@ -183,11 +183,11 @@ 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);
createTestExecutionSpans(build, span);
createTestExecutionSpans(build, span, getBuildName(build));
setArtifactAttributes(build, span);

otelHelper.addAttributeToSpan(span, PluginConstants.ATTRIBUTE_SUCCESS_STATUS, build.getBuildStatus().isSuccessful());
Expand All @@ -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() +
Expand All @@ -212,15 +212,15 @@ 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()));
}
}
}

private void createTestExecutionSpans(SRunningBuild build, Span parentSpan) {
private void createTestExecutionSpans(SRunningBuild build, Span parentSpan, String parentSpanName) {
if (build.isCompositeBuild()) return;

var buildStatistics = build.getBuildStatistics(
Expand All @@ -231,12 +231,18 @@ private void createTestExecutionSpans(SRunningBuild build, Span parentSpan) {

if (!tests.isEmpty()) {
var startTime = build.convertToServerTime(Objects.requireNonNull(build.getClientStartDate())).getTime(); // epoch milliseconds
var testsSpan = otelHelper.createTransientSpan("Tests", parentSpan, startTime);
var spanName = "Tests";
LOG.info("Creating child span '" + spanName + "' under parent " + parentSpanName);

var testsSpan = otelHelper.createTransientSpan(spanName, parentSpan, startTime);
setSpanBuildAttributes(otelHelper, build, testsSpan, spanName, "tests-execution");

try {
LOG.info("Creating " + tests.size() + " test spans under '" + parentSpanName + "' > '" + spanName + "'");
for (var test : tests) {
createTestExecutionSpan(otelHelper, build, test, testsSpan, startTime);
}
LOG.info("Created " + tests.size() + " test spans under '" + parentSpanName + "' > '" + spanName + "'");
} finally {
var finishDate = build.getFinishDate();
if (finishDate != null) {
Expand Down Expand Up @@ -383,7 +389,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 -> {
Expand Down
4 changes: 2 additions & 2 deletions ...va/com/octopus/teamcity/opentelemetry/server/helpers/HelperPerBuildOTELHelperFactory.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand All @@ -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);
}
}
Expand Down
5 changes: 4 additions & 1 deletion ...r/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/NullOTELHelperImpl.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,8 @@

import io.opentelemetry.api.trace.Span;

import javax.annotation.Nullable;

public class NullOTELHelperImpl implements OTELHelper {
@Override
public boolean isReady() {
Expand All @@ -28,6 +30,7 @@ public void removeSpan(String buildId) {
}

@Override
@Nullable
public Span getSpan(String buildId) {
return null;
}
Expand All @@ -37,6 +40,6 @@ public void addAttributeToSpan(Span span, String attributeName, Object attribute
}

@Override
public void release() {
public void release(String helperName) {
}
}
5 changes: 4 additions & 1 deletion server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/OTELHelper.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,8 @@

import io.opentelemetry.api.trace.Span;

import javax.annotation.Nullable;

public interface OTELHelper {
boolean isReady();

Expand All @@ -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);
}
18 changes: 12 additions & 6 deletions server/src/main/java/com/octopus/teamcity/opentelemetry/server/helpers/OTELHelperImpl.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand All @@ -24,8 +25,10 @@ public class OTELHelperImpl implements OTELHelper {
private final Tracer tracer;
private final ConcurrentHashMap<String, Span> 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()
Expand Down Expand Up @@ -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
Expand All @@ -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();
Expand Down
2 changes: 1 addition & 1 deletion server/src/test/java/com/octopus/teamcity/opentelemetry/server/OTELHelperTest.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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");
}


Expand Down
2 changes: 1 addition & 1 deletion ...er/src/test/java/com/octopus/teamcity/opentelemetry/server/TeamCityBuildListenerTest.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,7 @@ class TeamCityBuildListenerTest {
@BeforeEach
void setUp(@Mock EventDispatcher<BuildServerListener> 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);
Expand Down

0 comments on commit 80c0661

Please sign in to comment.