Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve logging, especially around cleanup #313

Merged
merged 2 commits into from
Sep 13, 2024
Merged

Improve logging, especially around cleanup #313

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
e86f129
Improve logging, especially around cleanup
matt-richardson Sep 13, 2024
dbdd2bc
Update TeamCityBuildListener.java
matt-richardson Sep 13, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
28 changes: 17 additions & 11 deletions server/src/main/java/com/octopus/teamcity/opentelemetry/server/TeamCityBuildListener.java
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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
Open in desktop
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