[andr] Augment http logs with extra fields for gql requests (#141)

* Augment http logs with extra fields for gql requests

* lint

* fix

* add test coverage

* add check for span name

* remove

Author: murki

platform/jvm/capture-apollo3/src/main/kotlin/io/bitdrift/capture/apollo3/CaptureApollo3Interceptor.kt

@@ -0,0 +1,53 @@
+// capture-sdk - bitdrift's client SDK
+// Copyright Bitdrift, Inc. All rights reserved.
+//
+// Use of this source code is governed by a source available license that can be found in the
+// LICENSE file or at:
+// https://polyformproject.org/wp-content/uploads/2020/06/PolyForm-Shield-1.0.0.txt
+
+package io.bitdrift.capture.apollo3
+
+import com.apollographql.apollo3.api.ApolloRequest
+import com.apollographql.apollo3.api.ApolloResponse
+import com.apollographql.apollo3.api.Mutation
+import com.apollographql.apollo3.api.Operation
+import com.apollographql.apollo3.api.Query
+import com.apollographql.apollo3.api.Subscription
+import com.apollographql.apollo3.interceptor.ApolloInterceptor
+import com.apollographql.apollo3.interceptor.ApolloInterceptorChain
+import io.bitdrift.capture.Capture
+import kotlinx.coroutines.flow.Flow
+
+/**
+ * An [ApolloInterceptor] that logs request and response events to the [Capture.Logger].
+ */
+class CaptureApolloInterceptor: ApolloInterceptor {
+
+    override fun <D : Operation.Data> intercept(request: ApolloRequest<D>, chain: ApolloInterceptorChain): Flow<ApolloResponse<D>> {
+        // Use special header format that is recognized by the CaptureOkHttpEventListener to be transformed into a span
+        val requestBuilder = request.newBuilder()
+            .addHttpHeader("x-capture-span-key", "gql")
+            .addHttpHeader("x-capture-span-gql-name", "graphql")
+            .addHttpHeader("x-capture-span-gql-field-operation-name", request.operation.name())
+            .addHttpHeader("x-capture-span-gql-field-operation-id", request.operation.id())
+            .addHttpHeader("x-capture-span-gql-field-operation-type", request.operation.type())
+        // TODO(murki): Augment request logs with
+        //  request.executionContext[CustomScalarAdapters]?.let {
+        //    addHttpHeader("x-capture-span-gql-field-operation-variables", request.operation.variables(it).valueMap.toString())
+        //  }
+
+        val modifiedRequest = requestBuilder.build()
+
+        // TODO(murki): Augment response logs with response.errors
+        return chain.proceed(modifiedRequest)
+    }
+
+    private fun <D : Operation.Data> Operation<D>.type(): String {
+        return when (this) {
+            is Query        -> "query"
+            is Mutation     -> "mutation"
+            is Subscription -> "subscription"
+            else            -> this.javaClass.simpleName
+        }
+    }
+}

platform/jvm/capture-apollo3/src/main/kotlin/io/bitdrift/capture/apollo3/CaptureApolloInterceptor.kt

@@ -45,9 +45,10 @@ data class HttpRequestInfo @JvmOverloads constructor(
     }
 
     internal val commonFields: InternalFieldsMap by lazy {
-        extraFields.toFields() + buildMap {
+        buildMap {
+            putAll(extraFields.toFields())
+            putOptionalHeaderSpanFields(headers)
             put(SpanField.Key.ID, FieldValue.StringField(spanId.toString()))
-            put(SpanField.Key.NAME, FieldValue.StringField("_http"))
             put(SpanField.Key.TYPE, FieldValue.StringField(SpanField.Value.TYPE_START))
             put("_method", FieldValue.StringField(method))
             putOptional(HttpFieldKey.HOST, host)
@@ -62,4 +63,31 @@ data class HttpRequestInfo @JvmOverloads constructor(
     }
 
     internal val matchingFields: InternalFieldsMap = headers?.let { HTTPHeaders.normalizeHeaders(it) }.toFields()
+
+    /**
+     * Adds optional fields to the mutable map based on the provided headers.
+     *
+     * This function checks for the presence of the "x-capture-span-key" header.
+     * If the header is present, it constructs a span name and additional fields from other headers
+     * and adds them to the map. If the header is not present, it adds a default span name.
+     *
+     * @param headers The map of headers from which fields are extracted.
+     */
+    private fun MutableMap<String, FieldValue>.putOptionalHeaderSpanFields(headers: Map<String, String>?) {
+        headers?.get("x-capture-span-key")?.let { spanKey ->
+            val prefix = "x-capture-span-$spanKey"
+            val spanName = "_" + headers["$prefix-name"]
+            put(SpanField.Key.NAME, FieldValue.StringField(spanName))
+            val fieldPrefix = "$prefix-field"
+            headers.forEach { (key, value) ->
+                if (key.startsWith(fieldPrefix)) {
+                    val fieldKey = key.removePrefix(fieldPrefix).replace('-', '_')
+                    put(fieldKey, FieldValue.StringField(value))
+                }
+            }
+        } ?: run {
+            // Default span name is simply http
+            put(SpanField.Key.NAME, FieldValue.StringField("_http"))
+        }
+    }
 }

platform/jvm/capture/src/main/kotlin/io/bitdrift/capture/network/HttpRequestInfo.kt

@@ -17,6 +17,7 @@ import io.bitdrift.capture.network.HttpRequestInfo
 import io.bitdrift.capture.network.HttpResponseInfo
 import io.bitdrift.capture.network.okhttp.CaptureOkHttpEventListenerFactory
 import okhttp3.Call
+import okhttp3.Headers.Companion.toHeaders
 import okhttp3.Protocol
 import okhttp3.Request
 import okhttp3.RequestBody.Companion.toRequestBody
@@ -85,6 +86,7 @@ class CaptureOkHttpEventListenerFactoryTest {
         val httpRequestInfo = httpRequestInfoCapture.firstValue
         val httpResponseInfo = httpResponseInfoCapture.firstValue
         // common request fields
+        assertThat(httpRequestInfo.fields["_span_name"].toString()).isEqualTo("_http")
         assertThat(httpRequestInfo.fields["_host"].toString()).isEqualTo("api.bitdrift.io")
         assertThat(httpRequestInfo.fields["_host"].toString())
             .isEqualTo(httpResponseInfo.fields["_host"].toString())
@@ -336,4 +338,65 @@ class CaptureOkHttpEventListenerFactoryTest {
         assertThat(httpResponseInfo.fields["_error_type"].toString()).isEqualTo(err::javaClass.get().simpleName)
         assertThat(httpResponseInfo.fields["_error_message"].toString()).isEqualTo(errorMessage)
     }
+
+    @Test
+    fun testExtraHeadersSendCustomSpans() {
+        // ARRANGE
+        val headerFields = mapOf(
+            "x-capture-span-key" to "gql",
+            "x-capture-span-gql-name" to "mySpanName",
+            "x-capture-span-gql-field-operation-name" to "myOperationName",
+            "x-capture-span-gql-field-operation-id" to "myOperationId",
+            "x-capture-span-gql-field-operation-type" to "query",
+        )
+        val expectedSpanName = "_mySpanName"
+        val expectedFields = mapOf(
+            "_operation_name" to "myOperationName",
+            "_operation_id" to "myOperationId",
+            "_operation_type" to "query",
+        )
+
+        val request = Request.Builder()
+            .url(endpoint)
+            .post("test".toRequestBody())
+            .headers(headerFields.toHeaders())
+            .build()
+
+        val response = Response.Builder()
+            .request(request)
+            .protocol(Protocol.HTTP_2)
+            .code(200)
+            .message("message")
+            .header("response_header", "response_header_value")
+            .build()
+
+        val call: Call = mock()
+        whenever(call.request()).thenReturn(request)
+
+        // ACT
+        val factory = CaptureOkHttpEventListenerFactory(null, logger, clock)
+        val listener = factory.create(call)
+
+        listener.callStart(call)
+
+        listener.responseHeadersEnd(call, response)
+        listener.responseBodyEnd(call, 234)
+
+        listener.callEnd(call)
+
+        // ASSERT
+        val httpRequestInfoCapture = argumentCaptor<HttpRequestInfo>()
+        verify(logger).log(httpRequestInfoCapture.capture())
+        val httpResponseInfoCapture = argumentCaptor<HttpResponseInfo>()
+        verify(logger).log(httpResponseInfoCapture.capture())
+
+        val httpRequestInfo = httpRequestInfoCapture.firstValue
+        val httpResponseInfo = httpResponseInfoCapture.firstValue
+
+        assertThat(httpRequestInfo.fields["_span_name"].toString()).isEqualTo(expectedSpanName)
+        // validate all the extra headers are present as properly formatted fields
+        assertThat(httpRequestInfo.fields.mapValues { it.value.toString() }.entries.containsAll(expectedFields.entries)).isTrue()
+        // validate all request fields are present in response
+        assertThat(httpResponseInfo.fields.mapValues { it.value.toString() }.entries.containsAll(expectedFields.entries)).isTrue()
+    }
 }

platform/jvm/capture/src/test/kotlin/io/bitdrift/capture/CaptureOkHttpEventListenerFactoryTest.kt

@@ -27,6 +27,7 @@ import androidx.compose.ui.platform.ViewCompositionStrategy
 import androidx.fragment.app.Fragment
 import androidx.navigation.fragment.findNavController
 import com.apollographql.apollo3.ApolloClient
+import com.apollographql.apollo3.network.okHttpClient
 import com.example.rocketreserver.LaunchListQuery
 import com.github.michaelbull.result.onFailure
 import com.github.michaelbull.result.onSuccess
@@ -36,7 +37,7 @@ import io.bitdrift.capture.Capture.Logger
 import io.bitdrift.capture.CaptureJniLibrary
 import io.bitdrift.capture.LogLevel
 import io.bitdrift.capture.LoggerImpl
-import io.bitdrift.capture.apollo3.CaptureApollo3Interceptor
+import io.bitdrift.capture.apollo3.CaptureApolloInterceptor
 import io.bitdrift.capture.network.okhttp.CaptureOkHttpEventListenerFactory
 import io.bitdrift.gradletestapp.databinding.FragmentFirstBinding
 import kotlinx.coroutines.MainScope
@@ -141,20 +142,14 @@ class FirstFragment : Fragment() {
             AppExitReason.entries
         )
 
-        okHttpClient = provideOkHttpClient()
-        apolloClient = provideApolloClient()
-    }
-
-    private fun provideOkHttpClient(): OkHttpClient {
-        return OkHttpClient.Builder()
+        okHttpClient = OkHttpClient.Builder()
             .eventListenerFactory(CaptureOkHttpEventListenerFactory())
             .build()
-    }
 
-    private fun provideApolloClient(): ApolloClient {
-        return ApolloClient.Builder()
+        apolloClient = ApolloClient.Builder()
             .serverUrl("https://apollo-fullstack-tutorial.herokuapp.com/graphql")
-            .addInterceptor(CaptureApollo3Interceptor())
+            .okHttpClient(okHttpClient)
+            .addInterceptor(CaptureApolloInterceptor())
             .build()
     }
 
@@ -223,8 +218,12 @@ class FirstFragment : Fragment() {
 
     private fun performGraphQlRequest(view: View) {
         MainScope().launch {
-            val response = apolloClient.query(LaunchListQuery()).execute()
-            Logger.logDebug(mapOf("response_data" to response.data.toString())) { "GraphQL response data received" }
+            try {
+                val response = apolloClient.query(LaunchListQuery()).execute()
+                Logger.logDebug(mapOf("response_data" to response.data.toString())) { "GraphQL response data received" }
+            } catch (e: Exception) {
+                Timber.e(e, "GraphQL request failed")
+            }
         }
 
     }