diff --git a/CHANGELOG.md b/CHANGELOG.md index f0d5c32706..46a7486438 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,10 @@ - Use minSdk compatible `Objects` class ([#2436](https://github.com/getsentry/sentry-java/pull/2436)) +### Features + +- Add logging for OpenTelemetry integration ([#2425](https://github.com/getsentry/sentry-java/pull/2425)) + ### Dependencies - Bump Gradle from v7.5.1 to v7.6.0 ([#2438](https://github.com/getsentry/sentry-java/pull/2438)) diff --git a/sentry-opentelemetry/sentry-opentelemetry-core/src/main/java/io/sentry/opentelemetry/OpenTelemetryLinkErrorEventProcessor.java b/sentry-opentelemetry/sentry-opentelemetry-core/src/main/java/io/sentry/opentelemetry/OpenTelemetryLinkErrorEventProcessor.java index f01d9ec3ed..1e373ece9c 100644 --- a/sentry-opentelemetry/sentry-opentelemetry-core/src/main/java/io/sentry/opentelemetry/OpenTelemetryLinkErrorEventProcessor.java +++ b/sentry-opentelemetry/sentry-opentelemetry-core/src/main/java/io/sentry/opentelemetry/OpenTelemetryLinkErrorEventProcessor.java @@ -6,22 +6,36 @@ import io.sentry.EventProcessor; import io.sentry.Hint; import io.sentry.HubAdapter; +import io.sentry.IHub; import io.sentry.ISpan; import io.sentry.Instrumenter; import io.sentry.SentryEvent; +import io.sentry.SentryLevel; import io.sentry.SentrySpanStorage; import io.sentry.SpanContext; import io.sentry.protocol.SentryId; import org.jetbrains.annotations.NotNull; import org.jetbrains.annotations.Nullable; +import org.jetbrains.annotations.TestOnly; public final class OpenTelemetryLinkErrorEventProcessor implements EventProcessor { + private final @NotNull IHub hub; private final @NotNull SentrySpanStorage spanStorage = SentrySpanStorage.getInstance(); + public OpenTelemetryLinkErrorEventProcessor() { + this(HubAdapter.getInstance()); + } + + @TestOnly + OpenTelemetryLinkErrorEventProcessor(final @NotNull IHub hub) { + this.hub = hub; + } + @Override public @Nullable SentryEvent process(final @NotNull SentryEvent event, final @NotNull Hint hint) { - if (Instrumenter.OTEL.equals(HubAdapter.getInstance().getOptions().getInstrumenter())) { + final @NotNull Instrumenter instrumenter = hub.getOptions().getInstrumenter(); + if (Instrumenter.OTEL.equals(instrumenter)) { @NotNull final Span otelSpan = Span.current(); @NotNull final String traceId = otelSpan.getSpanContext().getTraceId(); @NotNull final String spanId = otelSpan.getSpanContext().getSpanId(); @@ -41,8 +55,42 @@ public final class OpenTelemetryLinkErrorEventProcessor implements EventProcesso null); event.getContexts().setTrace(spanContext); + hub.getOptions() + .getLogger() + .log( + SentryLevel.DEBUG, + "Linking Sentry event %s to span %s created via OpenTelemetry (trace %s).", + event.getEventId(), + spanId, + traceId); + } else { + hub.getOptions() + .getLogger() + .log( + SentryLevel.DEBUG, + "Not linking Sentry event %s to any transaction created via OpenTelemetry as none has been found for span %s (trace %s).", + event.getEventId(), + spanId, + traceId); } + } else { + hub.getOptions() + .getLogger() + .log( + SentryLevel.DEBUG, + "Not linking Sentry event %s to any transaction created via OpenTelemetry as traceId %s or spanId %s are invalid.", + event.getEventId(), + traceId, + spanId); } + } else { + hub.getOptions() + .getLogger() + .log( + SentryLevel.DEBUG, + "Not linking Sentry event %s to any transaction created via OpenTelemetry as instrumenter is set to %s.", + event.getEventId(), + instrumenter); } return event; diff --git a/sentry-opentelemetry/sentry-opentelemetry-core/src/main/java/io/sentry/opentelemetry/SentryPropagator.java b/sentry-opentelemetry/sentry-opentelemetry-core/src/main/java/io/sentry/opentelemetry/SentryPropagator.java index f82f747c85..14ac12323b 100644 --- a/sentry-opentelemetry/sentry-opentelemetry-core/src/main/java/io/sentry/opentelemetry/SentryPropagator.java +++ b/sentry-opentelemetry/sentry-opentelemetry-core/src/main/java/io/sentry/opentelemetry/SentryPropagator.java @@ -10,7 +10,10 @@ import io.opentelemetry.context.propagation.TextMapSetter; import io.sentry.Baggage; import io.sentry.BaggageHeader; +import io.sentry.HubAdapter; +import io.sentry.IHub; import io.sentry.ISpan; +import io.sentry.SentryLevel; import io.sentry.SentrySpanStorage; import io.sentry.SentryTraceHeader; import io.sentry.exception.InvalidSentryTraceHeaderException; @@ -26,6 +29,15 @@ public final class SentryPropagator implements TextMapPropagator { private static final @NotNull List FIELDS = Arrays.asList(SentryTraceHeader.SENTRY_TRACE_HEADER, BaggageHeader.BAGGAGE_HEADER); private final @NotNull SentrySpanStorage spanStorage = SentrySpanStorage.getInstance(); + private final @NotNull IHub hub; + + public SentryPropagator() { + this(HubAdapter.getInstance()); + } + + SentryPropagator(final @NotNull IHub hub) { + this.hub = hub; + } @Override public Collection fields() { @@ -37,10 +49,22 @@ public void inject(final Context context, final C carrier, final TextMapSett final @NotNull Span otelSpan = Span.fromContext(context); final @NotNull SpanContext otelSpanContext = otelSpan.getSpanContext(); if (!otelSpanContext.isValid()) { + hub.getOptions() + .getLogger() + .log( + SentryLevel.DEBUG, + "Not injecting Sentry tracing information for invalid OpenTelemetry span."); return; } final @Nullable ISpan sentrySpan = spanStorage.get(otelSpanContext.getSpanId()); if (sentrySpan == null || sentrySpan.isNoOp()) { + hub.getOptions() + .getLogger() + .log( + SentryLevel.DEBUG, + "Not injecting Sentry tracing information for span %s as no Sentry span has been found or it is a NoOp (trace %s). This might simply mean this is a request to Sentry.", + otelSpanContext.getSpanId(), + otelSpanContext.getTraceId()); return; } @@ -82,8 +106,18 @@ public Context extract( Span wrappedSpan = Span.wrap(otelSpanContext); modifiedContext = modifiedContext.with(wrappedSpan); + hub.getOptions() + .getLogger() + .log(SentryLevel.DEBUG, "Continuing Sentry trace %s", sentryTraceHeader.getTraceId()); + return modifiedContext; } catch (InvalidSentryTraceHeaderException e) { + hub.getOptions() + .getLogger() + .log( + SentryLevel.ERROR, + "Unable to extract Sentry tracing information from invalid header.", + e); return context; } } diff --git a/sentry-opentelemetry/sentry-opentelemetry-core/src/main/java/io/sentry/opentelemetry/SentrySpanProcessor.java b/sentry-opentelemetry/sentry-opentelemetry-core/src/main/java/io/sentry/opentelemetry/SentrySpanProcessor.java index fba597a48c..3a31269109 100644 --- a/sentry-opentelemetry/sentry-opentelemetry-core/src/main/java/io/sentry/opentelemetry/SentrySpanProcessor.java +++ b/sentry-opentelemetry/sentry-opentelemetry-core/src/main/java/io/sentry/opentelemetry/SentrySpanProcessor.java @@ -19,6 +19,7 @@ import io.sentry.ISpan; import io.sentry.ITransaction; import io.sentry.Instrumenter; +import io.sentry.SentryLevel; import io.sentry.SentrySpanStorage; import io.sentry.SentryTraceHeader; import io.sentry.SpanId; @@ -48,7 +49,7 @@ public SentrySpanProcessor() { this(HubAdapter.getInstance()); } - SentrySpanProcessor(@NotNull IHub hub) { + SentrySpanProcessor(final @NotNull IHub hub) { this.hub = hub; } @@ -58,15 +59,30 @@ public void onStart(final @NotNull Context parentContext, final @NotNull ReadWri return; } + final @NotNull TraceData traceData = getTraceData(otelSpan, parentContext); + if (isSentryRequest(otelSpan)) { + hub.getOptions() + .getLogger() + .log( + SentryLevel.DEBUG, + "Not forwarding OpenTelemetry span %s to Sentry as this looks like a span for a request to Sentry (trace %s).", + traceData.getSpanId(), + traceData.getTraceId()); return; } - - final @NotNull TraceData traceData = getTraceData(otelSpan, parentContext); final @Nullable ISpan sentryParentSpan = traceData.getParentSpanId() == null ? null : spanStorage.get(traceData.getParentSpanId()); if (sentryParentSpan != null) { + hub.getOptions() + .getLogger() + .log( + SentryLevel.DEBUG, + "Creating Sentry child span for OpenTelemetry span %s (trace %s). Parent span is %s.", + traceData.getSpanId(), + traceData.getTraceId(), + traceData.getParentSpanId()); final @NotNull Date startDate = DateUtils.nanosToDate(otelSpan.toSpanData().getStartEpochNanos()); final @NotNull ISpan sentryChildSpan = @@ -74,6 +90,13 @@ public void onStart(final @NotNull Context parentContext, final @NotNull ReadWri otelSpan.getName(), otelSpan.getName(), startDate, Instrumenter.OTEL); spanStorage.store(traceData.getSpanId(), sentryChildSpan); } else { + hub.getOptions() + .getLogger() + .log( + SentryLevel.DEBUG, + "Creating Sentry transaction for OpenTelemetry span %s (trace %s).", + traceData.getSpanId(), + traceData.getTraceId()); final @NotNull String transactionName = otelSpan.getName(); final @NotNull TransactionNameSource transactionNameSource = TransactionNameSource.CUSTOM; final @Nullable String op = otelSpan.getName(); @@ -124,18 +147,48 @@ public void onEnd(final @NotNull ReadableSpan otelSpan) { final @Nullable ISpan sentrySpan = spanStorage.removeAndGet(traceData.getSpanId()); if (sentrySpan == null) { + hub.getOptions() + .getLogger() + .log( + SentryLevel.DEBUG, + "Unable to find Sentry span for OpenTelemetry span %s (trace %s).", + traceData.getSpanId(), + traceData.getTraceId()); return; } if (isSentryRequest(otelSpan)) { + hub.getOptions() + .getLogger() + .log( + SentryLevel.DEBUG, + "Not forwarding OpenTelemetry span %s to Sentry as this looks like a span for a request to Sentry (trace %s).", + traceData.getSpanId(), + traceData.getTraceId()); return; } if (sentrySpan instanceof ITransaction) { - ITransaction sentryTransaction = (ITransaction) sentrySpan; + final @NotNull ITransaction sentryTransaction = (ITransaction) sentrySpan; updateTransactionWithOtelData(sentryTransaction, otelSpan); + hub.getOptions() + .getLogger() + .log( + SentryLevel.DEBUG, + "Finishing Sentry transaction %s for OpenTelemetry span %s (trace %s).", + sentryTransaction.getEventId(), + traceData.getSpanId(), + traceData.getTraceId()); } else { updateSpanWithOtelData(sentrySpan, otelSpan); + hub.getOptions() + .getLogger() + .log( + SentryLevel.DEBUG, + "Finishing Sentry span for OpenTelemetry span %s (trace %s). Parent span is %s.", + traceData.getSpanId(), + traceData.getTraceId(), + traceData.getParentSpanId()); } final @NotNull SpanStatus sentryStatus = mapOtelStatus(otelSpan); @@ -151,15 +204,32 @@ public boolean isEndRequired() { private boolean ensurePrerequisites(final @NotNull ReadableSpan otelSpan) { if (!hasSentryBeenInitialized()) { + hub.getOptions() + .getLogger() + .log( + SentryLevel.DEBUG, + "Not forwarding OpenTelemetry span to Sentry as Sentry has not yet been initialized."); return false; } - if (!Instrumenter.OTEL.equals(hub.getOptions().getInstrumenter())) { + final @NotNull Instrumenter instrumenter = hub.getOptions().getInstrumenter(); + if (!Instrumenter.OTEL.equals(instrumenter)) { + hub.getOptions() + .getLogger() + .log( + SentryLevel.DEBUG, + "Not forwarding OpenTelemetry span to Sentry as instrumenter has been set to %s.", + instrumenter); return false; } final @NotNull SpanContext otelSpanContext = otelSpan.getSpanContext(); if (!otelSpanContext.isValid()) { + hub.getOptions() + .getLogger() + .log( + SentryLevel.DEBUG, + "Not forwarding OpenTelemetry span to Sentry as the span is invalid."); return false; } diff --git a/sentry-opentelemetry/sentry-opentelemetry-core/src/test/kotlin/SentrySpanProcessorTest.kt b/sentry-opentelemetry/sentry-opentelemetry-core/src/test/kotlin/SentrySpanProcessorTest.kt index 4c3df4b72b..472cf17f2a 100644 --- a/sentry-opentelemetry/sentry-opentelemetry-core/src/test/kotlin/SentrySpanProcessorTest.kt +++ b/sentry-opentelemetry/sentry-opentelemetry-core/src/test/kotlin/SentrySpanProcessorTest.kt @@ -20,10 +20,12 @@ import io.opentelemetry.sdk.trace.SdkTracerProvider import io.opentelemetry.semconv.trace.attributes.SemanticAttributes import io.sentry.Baggage import io.sentry.BaggageHeader +import io.sentry.Hint import io.sentry.IHub import io.sentry.ISpan import io.sentry.ITransaction import io.sentry.Instrumenter +import io.sentry.SentryEvent import io.sentry.SentryOptions import io.sentry.SentryTraceHeader import io.sentry.SpanStatus @@ -66,6 +68,7 @@ class SentrySpanProcessorTest { val hub = mock() val transaction = mock() val span = mock() + val spanContext = mock() lateinit var openTelemetry: OpenTelemetry lateinit var tracer: Tracer val sentryTrace = SentryTraceHeader(SENTRY_TRACE_HEADER_STRING) @@ -76,6 +79,11 @@ class SentrySpanProcessorTest { whenever(hub.options).thenReturn(options) whenever(hub.startTransaction(any(), any())).thenReturn(transaction) + whenever(spanContext.operation).thenReturn("spanContextOp") + whenever(spanContext.parentSpanId).thenReturn(io.sentry.SpanId("cedf5b7571cb4972")) + + whenever(transaction.spanContext).thenReturn(spanContext) + whenever(span.spanContext).thenReturn(spanContext) whenever(span.toSentryTrace()).thenReturn(sentryTrace) whenever(transaction.toSentryTrace()).thenReturn(sentryTrace) @@ -134,30 +142,32 @@ class SentrySpanProcessorTest { @Test fun `does nothing on start if Sentry has not been initialized`() { - val hub = mock() + fixture.setup() val context = mock() val span = mock() - whenever(hub.isEnabled).thenReturn(false) + whenever(fixture.hub.isEnabled).thenReturn(false) - SentrySpanProcessor(hub).onStart(context, span) + SentrySpanProcessor(fixture.hub).onStart(context, span) - verify(hub).isEnabled - verifyNoMoreInteractions(hub) + verify(fixture.hub).isEnabled + verify(fixture.hub).options + verifyNoMoreInteractions(fixture.hub) verifyNoInteractions(context, span) } @Test fun `does nothing on end if Sentry has not been initialized`() { - val hub = mock() + fixture.setup() val span = mock() - whenever(hub.isEnabled).thenReturn(false) + whenever(fixture.hub.isEnabled).thenReturn(false) - SentrySpanProcessor(hub).onEnd(span) + SentrySpanProcessor(fixture.hub).onEnd(span) - verify(hub).isEnabled - verifyNoMoreInteractions(hub) + verify(fixture.hub).isEnabled + verify(fixture.hub).options + verifyNoMoreInteractions(fixture.hub) verifyNoInteractions(span) } @@ -322,6 +332,40 @@ class SentrySpanProcessorTest { thenTransactionIsFinished() } + @Test + fun `links error to OTEL transaction`() { + fixture.setup() + val extractedContext = whenExtractingHeaders() + + extractedContext.makeCurrent().use { _ -> + val otelSpan = givenSpanBuilder().startSpan() + thenTransactionIsStarted(otelSpan, isContinued = true) + + otelSpan.makeCurrent().use { _ -> + val processedEvent = OpenTelemetryLinkErrorEventProcessor(fixture.hub).process(SentryEvent(), Hint()) + val traceContext = processedEvent!!.contexts.trace!! + + assertEquals("2722d9f6ec019ade60c776169d9a8904", traceContext.traceId.toString()) + assertEquals(otelSpan.spanContext.spanId, traceContext.spanId.toString()) + assertEquals("cedf5b7571cb4972", traceContext.parentSpanId.toString()) + assertEquals("spanContextOp", traceContext.operation) + } + + otelSpan.end() + thenTransactionIsFinished() + } + } + + @Test + fun `does not link error to OTEL transaction if instrumenter does not match`() { + fixture.options.instrumenter = Instrumenter.SENTRY + fixture.setup() + + val processedEvent = OpenTelemetryLinkErrorEventProcessor(fixture.hub).process(SentryEvent(), Hint()) + + thenNoTraceContextHasBeenAddedToEvent(processedEvent) + } + private fun givenSpanBuilder(spanKind: SpanKind = SpanKind.SERVER, parentSpan: Span? = null): SpanBuilder { val spanName = if (parentSpan == null) "testspan" else "childspan" val spanBuilder = fixture.tracer @@ -430,6 +474,11 @@ class SentrySpanProcessorTest { verify(fixture.transaction).setContext(eq("otel"), any()) verify(fixture.transaction).finish(eq(SpanStatus.OK), any()) } + + private fun thenNoTraceContextHasBeenAddedToEvent(event: SentryEvent?) { + assertNotNull(event) + assertNull(event.contexts.trace) + } } class HeaderGetter : TextMapGetter {