remove redundant span attributes and improve log output format (#4075)

## Description
#4052 aligned our spans
closer to SRA but the output format resulted in `rpc.service` and
`rpc.method` on both the new generated operation span and the internal
orchestrator `invoke` span. This resulted in pretty long and clutter log
output. This PR cleans up the log output a bit to have only the top
level operation span include these attributes. This also fixes a subtle
bug where presigned requests wouldn't contain the same top level
operation span instrumentation because presigned requests make use of
`<Operation>::orchestrate_with_stop_point` and not
`<Operation>::orchestrate`. For IMDS and other "manually constructed"
operations, I've moved the `invoke` span instrumentation into
`Operation::invoke` to ensure we still capture that information in the
logs for those use cases.

Example output format:
```
2025-03-28T14:44:02.471068Z DEBUG S3.ListBuckets{rpc.service="S3" rpc.method="ListBuckets" sdk_invocation_id=4073472 rpc.system="aws-api"}:try_op: aws_smithy_runtime::cli
ent::orchestrator: beginning attempt #1
```

## Checklist
<!--- If a checkbox below is not applicable, then please DELETE it
rather than leaving it unchecked -->
- [x] For changes to the smithy-rs codegen or runtime crates, I have
created a changelog entry Markdown file in the `.changelog` directory,
specifying "client," "server," or both in the `applies_to` key.

----

_By submitting this pull request, I confirm that you can use, modify,
copy, and redistribute this contribution, under the terms of your
choice._

Author: aajtodd

.changelog/1743173123.md

@@ -0,0 +1,11 @@
+---
+applies_to:
+- client
+authors:
+- aajtodd
+references: []
+breaking: false
+new_feature: false
+bug_fix: false
+---
+remove redundant span attributes and improve log output format

aws/rust-runtime/Cargo.lock

@@ -62,23 +62,20 @@ async fn all_expected_operation_spans_emitted_with_correct_nesting() {
     let _guard = tracing::subscriber::set_default(subscriber);
 
     const OPERATION_NAME: &str = "S3.GetObject";
-    const INVOKE: &str = "invoke";
     const TRY_OP: &str = "try_op";
     const TRY_ATTEMPT: &str = "try_attempt";
 
     let apply_configuration = assertion_registry
         .build()
         .with_name("apply_configuration")
         .with_parent_name(OPERATION_NAME)
-        .with_parent_name(INVOKE)
         .was_closed_exactly(1)
         .finalize();
 
     let serialization = assertion_registry
         .build()
         .with_name("serialization")
         .with_parent_name(OPERATION_NAME)
-        .with_parent_name(INVOKE)
         .with_parent_name(TRY_OP)
         .was_closed_exactly(1)
         .finalize();
@@ -87,7 +84,6 @@ async fn all_expected_operation_spans_emitted_with_correct_nesting() {
         .build()
         .with_name("orchestrate_endpoint")
         .with_parent_name(OPERATION_NAME)
-        .with_parent_name(INVOKE)
         .with_parent_name(TRY_OP)
         .with_parent_name(TRY_ATTEMPT)
         .was_closed_exactly(1)
@@ -97,7 +93,6 @@ async fn all_expected_operation_spans_emitted_with_correct_nesting() {
         .build()
         .with_name("lazy_load_identity")
         .with_parent_name(OPERATION_NAME)
-        .with_parent_name(INVOKE)
         .with_parent_name(TRY_OP)
         .with_parent_name(TRY_ATTEMPT)
         .was_closed_exactly(1)
@@ -107,7 +102,6 @@ async fn all_expected_operation_spans_emitted_with_correct_nesting() {
         .build()
         .with_name("deserialize_streaming")
         .with_parent_name(OPERATION_NAME)
-        .with_parent_name(INVOKE)
         .with_parent_name(TRY_OP)
         .with_parent_name(TRY_ATTEMPT)
         .was_closed_exactly(1)
@@ -117,7 +111,6 @@ async fn all_expected_operation_spans_emitted_with_correct_nesting() {
         .build()
         .with_name("deserialization")
         .with_parent_name(OPERATION_NAME)
-        .with_parent_name(INVOKE)
         .with_parent_name(TRY_OP)
         .with_parent_name(TRY_ATTEMPT)
         .was_closed_exactly(1)
@@ -128,7 +121,6 @@ async fn all_expected_operation_spans_emitted_with_correct_nesting() {
         .with_name(TRY_ATTEMPT)
         .with_span_field("attempt")
         .with_parent_name(OPERATION_NAME)
-        .with_parent_name(INVOKE)
         .with_parent_name(TRY_OP)
         .was_closed_exactly(1)
         .finalize();
@@ -137,7 +129,6 @@ async fn all_expected_operation_spans_emitted_with_correct_nesting() {
         .build()
         .with_name("finally_attempt")
         .with_parent_name(OPERATION_NAME)
-        .with_parent_name(INVOKE)
         .with_parent_name(TRY_OP)
         .was_closed_exactly(1)
         .finalize();
@@ -146,22 +137,13 @@ async fn all_expected_operation_spans_emitted_with_correct_nesting() {
         .build()
         .with_name(TRY_OP)
         .with_parent_name(OPERATION_NAME)
-        .with_parent_name(INVOKE)
         .was_closed_exactly(1)
         .finalize();
 
     let finally_op = assertion_registry
         .build()
         .with_name("finally_op")
         .with_parent_name(OPERATION_NAME)
-        .with_parent_name(INVOKE)
-        .was_closed_exactly(1)
-        .finalize();
-
-    let invoke = assertion_registry
-        .build()
-        .with_name(INVOKE)
-        .with_parent_name(OPERATION_NAME)
         .was_closed_exactly(1)
         .finalize();
 
@@ -184,7 +166,6 @@ async fn all_expected_operation_spans_emitted_with_correct_nesting() {
     finally_attempt.assert();
     try_op.assert();
     finally_op.assert();
-    invoke.assert();
     operation.assert();
 }
 

aws/sdk/integration-tests/telemetry/tests/spans.rs

@@ -138,17 +138,7 @@ open class OperationGenerator(
                             err.downcast::<#{OperationError}>().expect("correct error type")
                         })
                     };
-                    use #{Tracing}::Instrument;
                     let context = Self::orchestrate_with_stop_point(runtime_plugins, input, #{StopPoint}::None)
-                        // Create a parent span for the entire operation. Includes a random, internal-only,
-                        // seven-digit ID for the operation orchestration so that it can be correlated in the logs.
-                        .instrument(#{Tracing}::debug_span!(
-                                "$serviceName.$operationName",
-                                "rpc.service" = ${serviceName.dq()},
-                                "rpc.method" = ${operationName.dq()},
-                                "sdk_invocation_id" = #{FastRand}::u32(1_000_000..10_000_000),
-                                #{AdditionalSpanFields}
-                            ))
                         .await
                         .map_err(map_err)?;
                     let output = context.finalize().map_err(map_err)?;
@@ -161,13 +151,24 @@ open class OperationGenerator(
                     stop_point: #{StopPoint},
                 ) -> #{Result}<#{InterceptorContext}, #{SdkError}<#{Error}, #{HttpResponse}>> {
                     let input = #{Input}::erase(input);
+                    use #{Tracing}::Instrument;
                     #{invoke_with_stop_point}(
                         ${serviceName.dq()},
                         ${operationName.dq()},
                         input,
                         runtime_plugins,
                         stop_point
-                    ).await
+                    )
+                    // Create a parent span for the entire operation. Includes a random, internal-only,
+                    // seven-digit ID for the operation orchestration so that it can be correlated in the logs.
+                    .instrument(#{Tracing}::debug_span!(
+                            "$serviceName.$operationName",
+                            "rpc.service" = ${serviceName.dq()},
+                            "rpc.method" = ${operationName.dq()},
+                            "sdk_invocation_id" = #{FastRand}::u32(1_000_000..10_000_000),
+                            #{AdditionalSpanFields}
+                        ))
+                    .await
                 }
 
                 pub(crate) fn operation_runtime_plugins(

codegen-client/src/main/kotlin/software/amazon/smithy/rust/codegen/client/smithy/generators/OperationGenerator.kt

@@ -1,6 +1,6 @@
 [package]
 name = "aws-smithy-runtime"
-version = "1.8.1"
+version = "1.8.2"
 authors = ["AWS Rust SDK Team <aws-sdk-rust@amazon.com>", "Zelda Hessler <zhessler@amazon.com>"]
 description = "The new smithy runtime crate"
 edition = "2021"

rust-runtime/Cargo.lock

@@ -133,8 +133,11 @@ pub enum StopPoint {
 ///
 /// See the docs on [`invoke`] for more details.
 pub async fn invoke_with_stop_point(
-    service_name: &str,
-    operation_name: &str,
+    // NOTE: service_name and operation_name were at one point used for instrumentation that is now
+    // handled as part of codegen. Manually constructed operations (e.g. via Operation::builder())
+    // are handled as part of Operation::invoke
+    _service_name: &str,
+    _operation_name: &str,
     input: Input,
     runtime_plugins: &RuntimePlugins,
     stop_point: StopPoint,
@@ -168,11 +171,6 @@ pub async fn invoke_with_stop_point(
         .maybe_timeout(operation_timeout_config)
         .await
     }
-    .instrument(debug_span!(
-        "invoke",
-        "rpc.service" = service_name,
-        "rpc.method" = operation_name
-    ))
     .await
 }
 

rust-runtime/aws-smithy-runtime/Cargo.toml

@@ -43,6 +43,7 @@ use aws_smithy_types::timeout::TimeoutConfig;
 use std::borrow::Cow;
 use std::fmt;
 use std::marker::PhantomData;
+use tracing::{debug_span, Instrument};
 
 struct FnSerializer<F, I> {
     f: F,
@@ -150,6 +151,11 @@ where
             input,
             &self.runtime_plugins,
         )
+        .instrument(debug_span!(
+            "invoke",
+            "rpc.service" = &self.service_name.as_ref(),
+            "rpc.method" = &self.operation_name.as_ref()
+        ))
         .await
         .map_err(|err| err.map_service_error(|e| e.downcast().expect("correct type")))?;