refactor!: rename metrics and remove redundant metrics (#973)

.changes/b31b8667-e931-49cf-8897-4e2ded2b7f14.json

@@ -0,0 +1,5 @@
+{
+    "id": "b31b8667-e931-49cf-8897-4e2ded2b7f14",
+    "type": "misc",
+    "description": "Expose immutable `SpanContext` on `TraceSpan`"
+}

.changes/c063605b-4702-4d8a-a841-2e0b7aa78e78.json

@@ -0,0 +1,5 @@
+{
+    "id": "c063605b-4702-4d8a-a841-2e0b7aa78e78",
+    "type": "misc",
+    "description": "**BREAKING**: Remove `smithy.client.request.size`, `smithy.client.response.size`, `smithy.client.retries` metrics. Rename all `smithy.client.*` metrics to `smithy.client.call.*`."
+}

runtime/observability/logging-slf4j2/jvm/src/aws/smithy/kotlin/runtime/telemetry/logging/slf4j/Slf4j1xLoggerAdapter.kt

@@ -4,7 +4,6 @@
  */
 package aws.smithy.kotlin.runtime.telemetry.logging.slf4j
 
-import aws.smithy.kotlin.runtime.telemetry.context.Context
 import aws.smithy.kotlin.runtime.telemetry.logging.LogLevel
 import aws.smithy.kotlin.runtime.telemetry.logging.LogRecordBuilder
 import aws.smithy.kotlin.runtime.telemetry.logging.LoggerProvider
@@ -47,10 +46,6 @@ private class Slf4j1xLogRecordBuilderAdapter(
         kvp[key] = value
     }
 
-    override fun setContext(context: Context) {
-        // TODO - add a way to get the current trace context and set the key/value pair on it?
-    }
-
     override fun emit() {
         val message = requireNotNull(msg) { "no message provided to LogRecordBuilder" }
         val logMethod = when (level) {

runtime/observability/logging-slf4j2/jvm/src/aws/smithy/kotlin/runtime/telemetry/logging/slf4j/Slf4j2xLoggerAdapter.kt

@@ -4,7 +4,6 @@
  */
 package aws.smithy.kotlin.runtime.telemetry.logging.slf4j
 
-import aws.smithy.kotlin.runtime.telemetry.context.Context
 import aws.smithy.kotlin.runtime.telemetry.logging.LogLevel
 import aws.smithy.kotlin.runtime.telemetry.logging.LogRecordBuilder
 import org.slf4j.event.Level
@@ -37,10 +36,6 @@ private class Slf4j2xLogRecordBuilderAdapter(
         delegate.addKeyValue(key, value)
     }
 
-    override fun setContext(context: Context) {
-        // TODO - add a way to get the current trace context and set the key/value pair on it?
-    }
-
     override fun emit() = delegate.log()
 }
 

runtime/observability/telemetry-api/api/telemetry-api.api

@@ -68,7 +68,6 @@ public final class aws/smithy/kotlin/runtime/telemetry/logging/LogLevel : java/l
 public abstract interface class aws/smithy/kotlin/runtime/telemetry/logging/LogRecordBuilder {
 	public abstract fun emit ()V
 	public abstract fun setCause (Ljava/lang/Throwable;)V
-	public abstract fun setContext (Laws/smithy/kotlin/runtime/telemetry/context/Context;)V
 	public abstract fun setKeyValuePair (Ljava/lang/String;Ljava/lang/Object;)V
 	public abstract fun setMessage (Ljava/lang/String;)V
 	public abstract fun setMessage (Lkotlin/jvm/functions/Function0;)V
@@ -190,6 +189,18 @@ public final class aws/smithy/kotlin/runtime/telemetry/metrics/UpDownCounter$Def
 public final class aws/smithy/kotlin/runtime/telemetry/trace/CoroutineContextTraceExtKt {
 }
 
+public abstract interface class aws/smithy/kotlin/runtime/telemetry/trace/SpanContext {
+	public static final field Companion Laws/smithy/kotlin/runtime/telemetry/trace/SpanContext$Companion;
+	public abstract fun getSpanId ()Ljava/lang/String;
+	public abstract fun getTraceId ()Ljava/lang/String;
+	public abstract fun isRemote ()Z
+	public abstract fun isValid ()Z
+}
+
+public final class aws/smithy/kotlin/runtime/telemetry/trace/SpanContext$Companion {
+	public final fun getInvalid ()Laws/smithy/kotlin/runtime/telemetry/trace/SpanContext;
+}
+
 public final class aws/smithy/kotlin/runtime/telemetry/trace/SpanKind : java/lang/Enum {
 	public static final field CLIENT Laws/smithy/kotlin/runtime/telemetry/trace/SpanKind;
 	public static final field INTERNAL Laws/smithy/kotlin/runtime/telemetry/trace/SpanKind;
@@ -209,7 +220,7 @@ public final class aws/smithy/kotlin/runtime/telemetry/trace/SpanStatus : java/l
 public abstract interface class aws/smithy/kotlin/runtime/telemetry/trace/TraceSpan : aws/smithy/kotlin/runtime/telemetry/context/Scope {
 	public abstract fun close ()V
 	public abstract fun emitEvent (Ljava/lang/String;Laws/smithy/kotlin/runtime/util/Attributes;)V
-	public abstract fun getName ()Ljava/lang/String;
+	public abstract fun getSpanContext ()Laws/smithy/kotlin/runtime/telemetry/trace/SpanContext;
 	public abstract fun mergeAttributes (Laws/smithy/kotlin/runtime/util/Attributes;)V
 	public abstract fun set (Laws/smithy/kotlin/runtime/util/AttributeKey;Ljava/lang/Object;)V
 	public abstract fun setStatus (Laws/smithy/kotlin/runtime/telemetry/trace/SpanStatus;)V

runtime/observability/telemetry-api/common/src/aws/smithy/kotlin/runtime/telemetry/logging/CoroutineContextLogExt.kt

@@ -7,14 +7,21 @@ package aws.smithy.kotlin.runtime.telemetry.logging
 
 import aws.smithy.kotlin.runtime.ExperimentalApi
 import aws.smithy.kotlin.runtime.InternalApi
-import aws.smithy.kotlin.runtime.telemetry.context.Context
-import aws.smithy.kotlin.runtime.telemetry.context.telemetryContext
 import aws.smithy.kotlin.runtime.telemetry.telemetryProvider
+import aws.smithy.kotlin.runtime.telemetry.trace.SpanContext
+import aws.smithy.kotlin.runtime.telemetry.trace.traceSpan
 import kotlinx.coroutines.withContext
 import kotlin.coroutines.AbstractCoroutineContextElement
 import kotlin.coroutines.CoroutineContext
 import kotlin.coroutines.coroutineContext
 
+// NOTE: these keys are specifically chosen to match the ones used by OpenTelemetry
+// so that any of the javaagent/autoconfigure MDC instrumentation doesn't result in
+// multiple key/value pairs with the same information.
+// see: https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/v1.30.0/instrumentation-api-semconv/src/main/java/io/opentelemetry/instrumentation/api/log/LoggingContextConstants.java#L14
+private const val TRACE_ID_KEY = "trace_id"
+private const val SPAN_ID_KEY = "span_id"
+
 /**
  * Coroutine scoped telemetry context used for carrying telemetry provider configuration
  * @param kvPairs key/value pairs to add to output log statements
@@ -72,14 +79,17 @@ public fun CoroutineContext.log(
 ) {
     val logger = this.telemetryProvider.loggerProvider.getOrCreateLogger(sourceComponent)
     if (!logger.isEnabledFor(level)) return
-    val context = this.telemetryContext
     val loggingContext = this.loggingContext
+    val spanContext = this.traceSpan?.spanContext?.takeIf(SpanContext::isValid)
     logger.atLevel(level)
         .apply {
             ex?.let { setCause(it) }
             setMessage(content)
-            context?.let { setContext(it) }
             loggingContext.forEach { entry -> setKeyValuePair(entry.key, entry.value) }
+            if (spanContext != null) {
+                setKeyValuePair(TRACE_ID_KEY, spanContext.traceId)
+                setKeyValuePair(SPAN_ID_KEY, spanContext.spanId)
+            }
         }.emit()
 }
 
@@ -236,21 +246,7 @@ private class ContextAwareLogger(
     override fun warn(t: Throwable?, msg: () -> String) = context.warn(sourceComponent, t, msg)
     override fun error(t: Throwable?, msg: () -> String) = context.error(sourceComponent, t, msg)
     override fun isEnabledFor(level: LogLevel): Boolean = delegate.isEnabledFor(level)
-    override fun atLevel(level: LogLevel): LogRecordBuilder {
-        val builder = delegate.atLevel(level)
-        val telemetryContext = context.telemetryContext
-        return telemetryContext?.let { ContextAwareLogRecordBuilder(builder, it) } ?: builder
-    }
-}
-private class ContextAwareLogRecordBuilder(
-    private val delegate: LogRecordBuilder,
-    private var context: Context,
-) : LogRecordBuilder by delegate {
-    override fun setContext(context: Context) { this.context = context }
-    override fun emit() {
-        delegate.setContext(context)
-        delegate.emit()
-    }
+    override fun atLevel(level: LogLevel): LogRecordBuilder = delegate.atLevel(level)
 }
 
 /**

runtime/observability/telemetry-api/common/src/aws/smithy/kotlin/runtime/telemetry/logging/LogRecordBuilder.kt

@@ -5,8 +5,6 @@
 
 package aws.smithy.kotlin.runtime.telemetry.logging
 
-import aws.smithy.kotlin.runtime.telemetry.context.Context
-
 /**
  * Construct a logging record that can be emitted to an underlying logger.
  */
@@ -38,12 +36,6 @@ public interface LogRecordBuilder {
      */
     public fun setKeyValuePair(key: String, value: Any)
 
-    /**
-     * Set the telemetry context to associate with this log record
-     * @param context the context to associate
-     */
-    public fun setContext(context: Context)
-
     /**
      * Emit this event to the underlying logger
      */

runtime/observability/telemetry-api/common/src/aws/smithy/kotlin/runtime/telemetry/logging/NoOpLogger.kt

@@ -5,8 +5,6 @@
 
 package aws.smithy.kotlin.runtime.telemetry.logging
 
-import aws.smithy.kotlin.runtime.telemetry.context.Context
-
 internal object NoOpLoggerProvider : LoggerProvider {
     override fun getOrCreateLogger(name: String): Logger = NoOpLogger
 }
@@ -26,6 +24,5 @@ private object NoOpLogRecordBuilder : LogRecordBuilder {
     override fun setMessage(message: String) {}
     override fun setMessage(message: MessageSupplier) {}
     override fun setKeyValuePair(key: String, value: Any) {}
-    override fun setContext(context: Context) {}
     override fun emit() {}
 }

runtime/observability/telemetry-api/common/src/aws/smithy/kotlin/runtime/telemetry/trace/NoOpTracerProvider.kt

@@ -23,7 +23,7 @@ private object NoOpTracer : Tracer {
 }
 
 private object NoOpTraceSpan : TraceSpan {
-    override val name: String = "NoOpSpan"
+    override val spanContext: SpanContext = SpanContext.Invalid
     override fun emitEvent(name: String, attributes: Attributes) {}
     override fun setStatus(status: SpanStatus) {}
     override operator fun <T : Any> set(key: AttributeKey<T>, value: T) {}

runtime/observability/telemetry-api/common/src/aws/smithy/kotlin/runtime/telemetry/trace/SpanContext.kt

@@ -0,0 +1,41 @@
+/*
+ * Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved.
+ * SPDX-License-Identifier: Apache-2.0
+ */
+package aws.smithy.kotlin.runtime.telemetry.trace
+
+/**
+ * The immutable state that must be serialized and propagated as part of a distributed trace context.
+ */
+public interface SpanContext {
+    public companion object {
+        public val Invalid: SpanContext = InvalidSpanContext
+    }
+
+    /**
+     * The unique trace identifier this span belongs to
+     */
+    public val traceId: String
+
+    /**
+     * The unique span identifier
+     */
+    public val spanId: String
+
+    /**
+     * True if the [SpanContext] was propagated from a remote parent
+     */
+    public val isRemote: Boolean
+
+    /**
+     * True if the [SpanContext] has a non-zero [traceId] and [spanId]
+     */
+    public val isValid: Boolean
+}
+
+private object InvalidSpanContext : SpanContext {
+    override val traceId: String = "00000000000000000000000000000000"
+    override val spanId: String = "0000000000000000"
+    override val isRemote: Boolean = false
+    override val isValid: Boolean = false
+}

runtime/observability/telemetry-api/common/src/aws/smithy/kotlin/runtime/telemetry/trace/TraceSpan.kt

@@ -16,9 +16,9 @@ import aws.smithy.kotlin.runtime.util.emptyAttributes
  */
 public interface TraceSpan : Scope {
     /**
-     * The name of the span
+     * The immutable tracing context this span belongs to
      */
-    public val name: String
+    public val spanContext: SpanContext
 
     /**
      * Set an attribute on the span
@@ -34,7 +34,6 @@ public interface TraceSpan : Scope {
      */
     public fun mergeAttributes(attributes: Attributes)
 
-    // FIXME - when would we use OTeL trace events vs logs?
     /**
      * Add an event to this span
      * @param name the name of the event

runtime/observability/telemetry-provider-otel/jvm/src/aws/smithy/kotlin/runtime/telemetry/otel/OtelTracerProvider.kt

@@ -11,6 +11,7 @@ import aws.smithy.kotlin.runtime.util.AttributeKey
 import aws.smithy.kotlin.runtime.util.Attributes
 import io.opentelemetry.api.OpenTelemetry
 import io.opentelemetry.api.trace.Span as OtelSpan
+import io.opentelemetry.api.trace.SpanContext as OtelSpanContext
 import io.opentelemetry.api.trace.SpanKind as OtelSpanKind
 import io.opentelemetry.api.trace.StatusCode as OtelStatus
 import io.opentelemetry.api.trace.Tracer as OtelTracer
@@ -43,16 +44,29 @@ private class OtelTracerImpl(
             }
             .setSpanKind(spanKind.toOtelSpanKind())
 
-        return OtelTraceSpan(name, spanBuilder.startSpan())
+        return OtelTraceSpanImpl(spanBuilder.startSpan())
     }
 }
 
-private class OtelTraceSpan(
-    override val name: String,
+private class OtelSpanContextImpl(private val otelSpanContext: OtelSpanContext) : SpanContext {
+    override val traceId: String
+        get() = otelSpanContext.traceId
+    override val spanId: String
+        get() = otelSpanContext.spanId
+    override val isRemote: Boolean
+        get() = otelSpanContext.isRemote
+    override val isValid: Boolean
+        get() = otelSpanContext.isValid
+}
+
+internal class OtelTraceSpanImpl(
     private val otelSpan: OtelSpan,
 ) : TraceSpan {
 
     private val spanScope = otelSpan.makeCurrent()
+
+    override val spanContext: SpanContext
+        get() = OtelSpanContextImpl(otelSpan.spanContext)
     override fun <T : Any> set(key: AttributeKey<T>, value: T) {
         key.otelAttrKeyOrNull(value)?.let { otelKey ->
             otelSpan.setAttribute(otelKey, value)

runtime/protocol/http-client/common/src/aws/smithy/kotlin/runtime/http/interceptors/OperationTelemetryInterceptor.kt

@@ -57,14 +57,6 @@ internal class OperationTelemetryInterceptor(
             metrics.rpcCallDuration.recordSeconds(callDuration, perRpcAttributes, currentCtx)
         }
 
-        context.protocolRequest?.body?.contentLength?.let {
-            metrics.rpcRequestSize.record(it, perRpcAttributes, currentCtx)
-        }
-
-        context.protocolResponse?.body?.contentLength?.let {
-            metrics.rpcResponseSize.record(it, perRpcAttributes, currentCtx)
-        }
-
         context.response.exceptionOrNull()?.let { ex ->
             val exType = ex::class.simpleName
             val errorAttributes = if (exType != null) {
@@ -90,9 +82,6 @@ internal class OperationTelemetryInterceptor(
     override fun readAfterAttempt(context: ResponseInterceptorContext<Any, Any, HttpRequest, HttpResponse?>) {
         metrics.rpcAttempts.add(1L, perRpcAttributes, metrics.provider.contextManager.current())
         attempts++
-        if (attempts > 1) {
-            metrics.rpcRetryCount.add(1L, perRpcAttributes, metrics.provider.contextManager.current())
-        }
 
         val attemptDuration = attemptStart?.elapsedNow() ?: return
         metrics.rpcAttemptDuration.recordSeconds(attemptDuration, perRpcAttributes, metrics.provider.contextManager.current())

runtime/protocol/http-client/common/src/aws/smithy/kotlin/runtime/http/operation/OperationMetrics.kt

@@ -8,7 +8,6 @@ import aws.smithy.kotlin.runtime.ExperimentalApi
 import aws.smithy.kotlin.runtime.InternalApi
 import aws.smithy.kotlin.runtime.telemetry.TelemetryProvider
 import aws.smithy.kotlin.runtime.telemetry.metrics.DoubleHistogram
-import aws.smithy.kotlin.runtime.telemetry.metrics.LongHistogram
 import aws.smithy.kotlin.runtime.telemetry.metrics.MonotonicCounter
 
 /**
@@ -28,17 +27,14 @@ public class OperationMetrics(
         val None: OperationMetrics = OperationMetrics("NoOp", TelemetryProvider.None)
     }
 
-    public val rpcCallDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.duration", "s", "Overall call duration including retries")
-    public val rpcAttempts: MonotonicCounter = meter.createMonotonicCounter("smithy.client.attempts", "{attempt}", "The number of attempts for an operation")
-    public val rpcErrors: MonotonicCounter = meter.createMonotonicCounter("smithy.client.errors", "{error}", "The number of errors for an operation")
-    public val rpcRetryCount: MonotonicCounter = meter.createMonotonicCounter("smithy.client.retries", "{count}", "The number of retries for an operation")
-    public val rpcRequestSize: LongHistogram = meter.createLongHistogram("smithy.client.request.size", "By", "Size of the serialized request message")
-    public val rpcResponseSize: LongHistogram = meter.createLongHistogram("smithy.client.response.size", "By", "Size of the serialized response message")
-    public val rpcAttemptDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.attempt_duration", "s", "The time it takes to connect to complete an entire call attempt, including identity resolution, endpoint resolution, signing, sending the request, and receiving the HTTP status code and headers from the response for an operation")
-    public val rpcAttemptOverheadDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.attempt_overhead_duration", "s", "The time it takes to execute an attempt minus the time spent waiting for a response from the remote server")
-    public val serializationDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.serialization_duration", "s", "The time it takes to serialize a request message body")
-    public val deserializationDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.deserialization_duration", "s", "The time it takes to deserialize a response message body")
-    public val resolveEndpointDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.resolve_endpoint_duration", "s", "The time it takes to resolve an endpoint for a request")
-    public val resolveIdentityDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.auth.resolve_identity_duration", "s", "The time it takes to resolve an identity for signing a request")
-    public val signingDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.auth.signing_duration", "s", "The time it takes to sign a request")
+    public val rpcCallDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.call.duration", "s", "Overall call duration including retries")
+    public val rpcAttempts: MonotonicCounter = meter.createMonotonicCounter("smithy.client.call.attempts", "{attempt}", "The number of attempts for an operation")
+    public val rpcErrors: MonotonicCounter = meter.createMonotonicCounter("smithy.client.call.errors", "{error}", "The number of errors for an operation")
+    public val rpcAttemptDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.call.attempt_duration", "s", "The time it takes to connect to complete an entire call attempt, including identity resolution, endpoint resolution, signing, sending the request, and receiving the HTTP status code and headers from the response for an operation")
+    public val rpcAttemptOverheadDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.call.attempt_overhead_duration", "s", "The time it takes to execute an attempt minus the time spent waiting for a response from the remote server")
+    public val serializationDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.call.serialization_duration", "s", "The time it takes to serialize a request message body")
+    public val deserializationDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.call.deserialization_duration", "s", "The time it takes to deserialize a response message body")
+    public val resolveEndpointDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.call.resolve_endpoint_duration", "s", "The time it takes to resolve an endpoint for a request")
+    public val resolveIdentityDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.call.auth.resolve_identity_duration", "s", "The time it takes to resolve an identity for signing a request")
+    public val signingDuration: DoubleHistogram = meter.createDoubleHistogram("smithy.client.call.auth.signing_duration", "s", "The time it takes to sign a request")
 }