propagate okhttp status to parent spans (#2872)

* status of OkHttp calls now gets propagated to parent span
* when OkHttp call finishes, status of unfinished spans is not overridden and is set to INTERNAL_ERROR

CHANGELOG.md

@@ -1,5 +1,11 @@
 # Changelog
 
+## Unreleased
+
+- propagate okhttp status to parent spans ([#2872](https://github.com/getsentry/sentry-java/pull/2872))
+
+### Fixes
+
 ## 6.27.0
 
 ### Features

sentry-android-okhttp/src/main/java/io/sentry/android/okhttp/SentryOkHttpEvent.kt

@@ -63,7 +63,6 @@ internal class SentryOkHttpEvent(private val hub: IHub, private val request: Req
         breadcrumb.setData("status_code", response.code)
         callRootSpan?.setData(PROTOCOL_KEY, response.protocol.name)
         callRootSpan?.setData(SpanDataConvention.HTTP_STATUS_CODE_KEY, response.code)
-        callRootSpan?.status = SpanStatus.fromHttpStatusCode(response.code)
     }
 
     fun setProtocol(protocolName: String?) {
@@ -98,24 +97,20 @@ internal class SentryOkHttpEvent(private val hub: IHub, private val request: Req
     /** Starts a span, if the callRootSpan is not null. */
     fun startSpan(event: String) {
         // Find the parent of the span being created. E.g. secureConnect is child of connect
-        val parentSpan = when (event) {
-            // PROXY_SELECT, DNS, CONNECT and CONNECTION are not children of one another
-            SECURE_CONNECT_EVENT -> eventSpans[CONNECT_EVENT]
-            REQUEST_HEADERS_EVENT -> eventSpans[CONNECTION_EVENT]
-            REQUEST_BODY_EVENT -> eventSpans[CONNECTION_EVENT]
-            RESPONSE_HEADERS_EVENT -> eventSpans[CONNECTION_EVENT]
-            RESPONSE_BODY_EVENT -> eventSpans[CONNECTION_EVENT]
-            else -> callRootSpan
-        } ?: callRootSpan
+        val parentSpan = findParentSpan(event)
         val span = parentSpan?.startChild("http.client.$event") ?: return
         span.spanContext.origin = TRACE_ORIGIN
         eventSpans[event] = span
     }
 
-    /** Finishes a previously started span, and runs [beforeFinish] on it and on the call root span. */
+    /** Finishes a previously started span, and runs [beforeFinish] on it, on its parent and on the call root span. */
     fun finishSpan(event: String, beforeFinish: ((span: ISpan) -> Unit)? = null) {
         val span = eventSpans[event] ?: return
+        val parentSpan = findParentSpan(event)
         beforeFinish?.invoke(span)
+        if (parentSpan != null && parentSpan != callRootSpan) {
+            beforeFinish?.invoke(parentSpan)
+        }
         callRootSpan?.let { beforeFinish?.invoke(it) }
         span.finish()
     }
@@ -125,7 +120,10 @@ internal class SentryOkHttpEvent(private val hub: IHub, private val request: Req
         callRootSpan ?: return
 
         // We forcefully finish all spans, even if they should already have been finished through finishSpan()
-        eventSpans.values.filter { !it.isFinished }.forEach { it.finish(SpanStatus.DEADLINE_EXCEEDED) }
+        eventSpans.values.filter { !it.isFinished }.forEach {
+            // If a status was set on the span, we use that, otherwise we set its status as error.
+            it.finish(it.status ?: SpanStatus.INTERNAL_ERROR)
+        }
         beforeFinish?.invoke(callRootSpan)
         callRootSpan.finish()
 
@@ -137,4 +135,14 @@ internal class SentryOkHttpEvent(private val hub: IHub, private val request: Req
         hub.addBreadcrumb(breadcrumb, hint)
         return
     }
+
+    private fun findParentSpan(event: String): ISpan? = when (event) {
+        // PROXY_SELECT, DNS, CONNECT and CONNECTION are not children of one another
+        SECURE_CONNECT_EVENT -> eventSpans[CONNECT_EVENT]
+        REQUEST_HEADERS_EVENT -> eventSpans[CONNECTION_EVENT]
+        REQUEST_BODY_EVENT -> eventSpans[CONNECTION_EVENT]
+        RESPONSE_HEADERS_EVENT -> eventSpans[CONNECTION_EVENT]
+        RESPONSE_BODY_EVENT -> eventSpans[CONNECTION_EVENT]
+        else -> callRootSpan
+    } ?: callRootSpan
 }

sentry-android-okhttp/src/main/java/io/sentry/android/okhttp/SentryOkHttpEventListener.kt

@@ -313,7 +313,10 @@ class SentryOkHttpEventListener(
         okHttpEvent.setResponse(response)
         okHttpEvent.finishSpan(RESPONSE_HEADERS_EVENT) {
             it.setData(SpanDataConvention.HTTP_STATUS_CODE_KEY, response.code)
-            it.status = SpanStatus.fromHttpStatusCode(response.code)
+            // Let's not override the status of a span that was set
+            if (it.status == null) {
+                it.status = SpanStatus.fromHttpStatusCode(response.code)
+            }
         }
     }
 

sentry-android-okhttp/src/test/java/io/sentry/android/okhttp/SentryOkHttpEventListenerTest.kt

@@ -19,6 +19,7 @@ import okhttp3.mockwebserver.MockResponse
 import okhttp3.mockwebserver.MockWebServer
 import okhttp3.mockwebserver.SocketPolicy
 import org.mockito.kotlin.any
+import org.mockito.kotlin.anyOrNull
 import org.mockito.kotlin.eq
 import org.mockito.kotlin.mock
 import org.mockito.kotlin.spy
@@ -249,7 +250,7 @@ class SentryOkHttpEventListenerTest {
 
     @Test
     fun `propagate all calls to the event listener passed in the ctor`() {
-        val sut = fixture.getSut(eventListener = fixture.mockEventListener, httpStatusCode = 500)
+        val sut = fixture.getSut(eventListener = fixture.mockEventListener)
         val listener = fixture.sentryOkHttpEventListener
         val request = postRequest(body = "requestBody")
         val call = sut.newCall(request)
@@ -260,7 +261,7 @@ class SentryOkHttpEventListenerTest {
 
     @Test
     fun `propagate all calls to the event listener factory passed in the ctor`() {
-        val sut = fixture.getSut(eventListenerFactory = fixture.mockEventListenerFactory, httpStatusCode = 500)
+        val sut = fixture.getSut(eventListenerFactory = fixture.mockEventListenerFactory)
         val listener = fixture.sentryOkHttpEventListener
         val request = postRequest(body = "requestBody")
         val call = sut.newCall(request)
@@ -272,7 +273,7 @@ class SentryOkHttpEventListenerTest {
     @Test
     fun `propagate all calls to the SentryOkHttpEventListener passed in the ctor`() {
         val originalListener = spy(SentryOkHttpEventListener(fixture.hub, fixture.mockEventListener))
-        val sut = fixture.getSut(eventListener = originalListener, httpStatusCode = 500)
+        val sut = fixture.getSut(eventListener = originalListener)
         val listener = fixture.sentryOkHttpEventListener
         val request = postRequest(body = "requestBody")
         val call = sut.newCall(request)
@@ -284,7 +285,7 @@ class SentryOkHttpEventListenerTest {
     @Test
     fun `propagate all calls to the SentryOkHttpEventListener factory passed in the ctor`() {
         val originalListener = spy(SentryOkHttpEventListener(fixture.hub, fixture.mockEventListener))
-        val sut = fixture.getSut(eventListenerFactory = { originalListener }, httpStatusCode = 500)
+        val sut = fixture.getSut(eventListenerFactory = { originalListener })
         val listener = fixture.sentryOkHttpEventListener
         val request = postRequest(body = "requestBody")
         val call = sut.newCall(request)
@@ -305,6 +306,49 @@ class SentryOkHttpEventListenerTest {
         assertEquals(9, fixture.sentryTracer.children.size)
     }
 
+    @Test
+    fun `status propagates to parent span and call root span`() {
+        val sut = fixture.getSut(httpStatusCode = 500)
+        val request = getRequest()
+        val call = sut.newCall(request)
+        val response = call.execute()
+        val okHttpEvent = SentryOkHttpEventListener.eventMap[call]
+        val callSpan = okHttpEvent?.callRootSpan
+        val responseHeaderSpan =
+            fixture.sentryTracer.children.firstOrNull { it.operation == "http.client.response_headers" }
+        val connectionSpan = fixture.sentryTracer.children.firstOrNull { it.operation == "http.client.connection" }
+        response.close()
+        assertNotNull(callSpan)
+        assertNotNull(responseHeaderSpan)
+        assertNotNull(connectionSpan)
+        assertEquals(SpanStatus.fromHttpStatusCode(500), callSpan.status)
+        assertEquals(SpanStatus.fromHttpStatusCode(500), responseHeaderSpan.status)
+        assertEquals(SpanStatus.fromHttpStatusCode(500), connectionSpan.status)
+    }
+
+    @Test
+    fun `call root span status is not overridden if not null`() {
+        val mockListener = mock<EventListener>()
+        lateinit var call: Call
+        whenever(mockListener.connectStart(any(), anyOrNull(), anyOrNull())).then {
+            val okHttpEvent = SentryOkHttpEventListener.eventMap[call]
+            val callSpan = okHttpEvent?.callRootSpan
+            assertNotNull(callSpan)
+            assertNull(callSpan.status)
+            callSpan.status = SpanStatus.UNKNOWN
+            it
+        }
+        val sut = fixture.getSut(eventListener = mockListener)
+        val request = getRequest()
+        call = sut.newCall(request)
+        val response = call.execute()
+        val okHttpEvent = SentryOkHttpEventListener.eventMap[call]
+        val callSpan = okHttpEvent?.callRootSpan
+        assertNotNull(callSpan)
+        response.close()
+        assertEquals(SpanStatus.UNKNOWN, callSpan.status)
+    }
+
     private fun verifyDelegation(
         listener: SentryOkHttpEventListener,
         originalListener: EventListener,

sentry-android-okhttp/src/test/java/io/sentry/android/okhttp/SentryOkHttpEventTest.kt

@@ -8,6 +8,7 @@ import io.sentry.SentryTracer
 import io.sentry.Span
 import io.sentry.SpanDataConvention
 import io.sentry.SpanOptions
+import io.sentry.SpanStatus
 import io.sentry.TracesSamplingDecision
 import io.sentry.TransactionContext
 import io.sentry.TypeCheckHint
@@ -242,6 +243,28 @@ class SentryOkHttpEventTest {
         )
     }
 
+    @Test
+    fun `when finishEvent, all running spans are finished with internal_error status`() {
+        val sut = fixture.getSut()
+        sut.startSpan("span")
+        val spans = sut.getEventSpans()
+        assertNull(spans["span"]!!.status)
+        sut.finishEvent()
+        assertEquals(SpanStatus.INTERNAL_ERROR, spans["span"]!!.status)
+    }
+
+    @Test
+    fun `when finishEvent, does not override running spans status if set`() {
+        val sut = fixture.getSut()
+        sut.startSpan("span")
+        val spans = sut.getEventSpans()
+        assertNull(spans["span"]!!.status)
+        spans["span"]!!.status = SpanStatus.OK
+        assertEquals(SpanStatus.OK, spans["span"]!!.status)
+        sut.finishEvent()
+        assertEquals(SpanStatus.OK, spans["span"]!!.status)
+    }
+
     @Test
     fun `setResponse set protocol and code in the breadcrumb and root span, and response in the hint`() {
         val sut = fixture.getSut()
@@ -443,6 +466,32 @@ class SentryOkHttpEventTest {
         assertEquals(rootSpan.spanId, responseBodySpan?.parentSpanId)
     }
 
+    @Test
+    fun `finishSpan beforeFinish is called on span, parent and call root span`() {
+        val sut = fixture.getSut()
+        sut.startSpan(CONNECTION_EVENT)
+        sut.startSpan(REQUEST_HEADERS_EVENT)
+        sut.startSpan("random event")
+        sut.finishSpan(REQUEST_HEADERS_EVENT) { it.status = SpanStatus.INTERNAL_ERROR }
+        sut.finishSpan("random event") { it.status = SpanStatus.DEADLINE_EXCEEDED }
+        sut.finishSpan(CONNECTION_EVENT)
+        val spans = sut.getEventSpans()
+        val connectionSpan = spans[CONNECTION_EVENT] as Span?
+        val requestHeadersSpan = spans[REQUEST_HEADERS_EVENT] as Span?
+        val randomEventSpan = spans["random event"] as Span?
+        assertNotNull(connectionSpan)
+        assertNotNull(requestHeadersSpan)
+        assertNotNull(randomEventSpan)
+        // requestHeadersSpan was finished with INTERNAL_ERROR
+        assertEquals(SpanStatus.INTERNAL_ERROR, requestHeadersSpan.status)
+        // randomEventSpan was finished with DEADLINE_EXCEEDED
+        assertEquals(SpanStatus.DEADLINE_EXCEEDED, randomEventSpan.status)
+        // requestHeadersSpan was finished with INTERNAL_ERROR, and it propagates to its parent
+        assertEquals(SpanStatus.INTERNAL_ERROR, connectionSpan.status)
+        // random event was finished last with DEADLINE_EXCEEDED, and it propagates to root call
+        assertEquals(SpanStatus.DEADLINE_EXCEEDED, sut.callRootSpan!!.status)
+    }
+
     /** Retrieve all the spans started in the event using reflection. */
     private fun SentryOkHttpEvent.getEventSpans() = getProperty<MutableMap<String, ISpan>>("eventSpans")
 }