refactor(libsy): adopt #[tracing::instrument] for method spans

Signed-off-by: Eric Liu <zengyuanl@nvidia.com>

Author: eric-liu-nvidia

Cargo.lock

@@ -22,7 +22,7 @@ rand = "0.8"
 switchyard-protocol = { path = "../protocol" }
 tokio = { version = "1", features = ["full"] }
 tokio-stream = "0.1"
-tracing = { version = "0.1", default-features = false, features = ["std"] }
+tracing = { version = "0.1", default-features = false, features = ["std", "attributes"] }
 
 [dev-dependencies]
 # SDK + in-memory exporter to assert what the observability layer records.

crates/libsy/Cargo.toml

@@ -5,7 +5,7 @@
 //! routing/optimization algorithm implements, and the offload channel it makes model
 //! calls and publishes [`Decision`]s over. See the crate root for the narrative model.
 
-use std::{error::Error, pin::Pin, sync::Arc};
+use std::{error::Error, pin::Pin, sync::Arc, time::Instant};
 
 use async_trait::async_trait;
 use futures::{Stream, StreamExt};
@@ -133,16 +133,37 @@ impl Driver {
     /// response resolves when its stream handle arrives); latency, outcome, and
     /// token usage are recorded when it resolves. The provider call itself gets a
     /// `libsy.client_call` span when [`Algorithm::run`] serves it.
+    #[tracing::instrument(
+        target = "libsy",
+        name = "libsy.llm_call",
+        skip_all,
+        fields(
+            algorithm = observability::algorithm_label(&routed.ctx),
+            selected_model = routed.decision.selected_model(),
+            outcome = tracing::field::Empty,
+            error = tracing::field::Empty,
+            input_tokens = tracing::field::Empty,
+            output_tokens = tracing::field::Empty,
+            total_tokens = tracing::field::Empty,
+            reasoning_tokens = tracing::field::Empty,
+        )
+    )]
     pub async fn call_llm(&self, routed: RoutedRequest) -> Result<Response, BoxErr> {
-        let ctx = routed.ctx.clone();
+        let algorithm = observability::algorithm_label(&routed.ctx).to_string();
         let selected_model = routed.decision.selected_model().to_string();
-        observability::observe_llm_call(
-            &ctx,
+        let started = Instant::now();
+        let result = self
+            .driver
+            .fulfill_request::<RoutedRequest, Response>(routed.ctx.clone(), routed)
+            .await;
+        observability::record_llm_call(
+            &algorithm,
             &selected_model,
-            self.driver
-                .fulfill_request::<RoutedRequest, Response>(routed.ctx.clone(), routed),
-        )
-        .await
+            started.elapsed(),
+            &result,
+            &tracing::Span::current(),
+        );
+        result
     }
 
     /// Offload a call to `target`: pair `request` with `decision` and the target's
@@ -393,6 +414,19 @@ where
         // Serve one offloaded call with its target's default client. A failed *model*
         // call is forwarded to the algorithm via `respond`; this errors only on an
         // infrastructure failure (no default client, or the promise was dropped).
+        // `serve` makes the one API call libsy itself performs, so it gets its
+        // own `libsy.client_call` span.
+        #[tracing::instrument(
+            target = "libsy",
+            name = "libsy.client_call",
+            skip_all,
+            fields(
+                algorithm = observability::algorithm_label(&call.get_routed().ctx),
+                selected_model = call.get_decision().selected_model(),
+                outcome = tracing::field::Empty,
+                error = tracing::field::Empty,
+            )
+        )]
         async fn serve(call: CallLlmRequest) -> Result<(), Box<dyn Error + Send + Sync>> {
             let routed = call.get_routed().clone();
             let client = routed.default_client.clone().ok_or_else(|| {
@@ -425,15 +459,7 @@ where
                     match step {
                         None => stream_open = false,
                         Some(item) => match item? {
-                            Step::CallLlm(call) => {
-                                // `serve` makes the one API call libsy itself
-                                // performs; give it its own client-call span.
-                                let span = observability::client_call_span(
-                                    &call.get_routed().ctx,
-                                    call.get_decision().selected_model(),
-                                );
-                                in_flight.push(serve(*call).instrument(span));
-                            }
+                            Step::CallLlm(call) => in_flight.push(serve(*call)),
                             Step::Decision(decision) => trace.push(decision),
                             Step::ReturnToAgent(response) => {
                                 final_response = Some(*response);

crates/libsy/src/core/algorithm.rs

@@ -12,8 +12,9 @@
 //! no-op. Spans and logs use the `tracing` facade (the async-native surface the
 //! OpenTelemetry ecosystem bridges with `tracing-opentelemetry` /
 //! `opentelemetry-appender-tracing`), so the host's subscriber decides where
-//! they go. Spans are attached to futures with [`Instrument`], never a
-//! [`Span::enter`] guard held across an `.await`: a suspended task would leave
+//! they go. Method spans use `#[tracing::instrument]`; the `libsy.run` span is
+//! attached to the spawned run task with [`tracing::Instrument`]. Neither holds
+//! a [`Span::enter`] guard across an `.await` — a suspended task would leave
 //! the span entered on its executor thread, mis-parenting every span other
 //! tasks create there (see the `tracing` docs on spans in asynchronous code).
 //!
@@ -34,7 +35,7 @@ use std::time::{Duration, Instant};
 
 use opentelemetry::metrics::Meter;
 use opentelemetry::{global, KeyValue};
-use tracing::{Instrument, Span};
+use tracing::Span;
 
 use crate::{Context, Decision, Metadata, Response};
 
@@ -49,7 +50,7 @@ const SCOPE: &str = "libsy";
 pub(crate) const ALGORITHM_KEY: &str = "algorithm";
 
 /// The algorithm label carried by a request context; empty until stamped.
-fn algorithm_label<S>(ctx: &Context<S>) -> &str {
+pub(crate) fn algorithm_label<S>(ctx: &Context<S>) -> &str {
     ctx.values
         .get(ALGORITHM_KEY)
         .map(String::as_str)
@@ -126,48 +127,6 @@ pub(crate) async fn observe_run<S>(
     result
 }
 
-/// Drives one offloaded model call inside its own `libsy.llm_call` span,
-/// recording the call counter, latency histogram, token usage, span fields,
-/// and failure log when the call resolves.
-pub(crate) async fn observe_llm_call(
-    ctx: &Context,
-    selected_model: &str,
-    call: impl Future<Output = Result<Response, BoxErr>>,
-) -> Result<Response, BoxErr> {
-    let algorithm = algorithm_label(ctx);
-    let span = llm_call_span(algorithm, selected_model);
-    async {
-        let started = Instant::now();
-        let result = call.await;
-        record_llm_call(
-            algorithm,
-            selected_model,
-            started.elapsed(),
-            &result,
-            &Span::current(),
-        );
-        result
-    }
-    .instrument(span)
-    .await
-}
-
-/// Span covering one *actual* provider API call the crate itself performs —
-/// the default-client serve path inside [`Algorithm::run`](crate::Algorithm::run).
-/// `libsy.llm_call` measures fulfillment as the algorithm observes it; this
-/// span isolates the client call that fulfills it. A host serving calls over
-/// its own transport should emit an equivalent span in its `LlmClient`.
-pub(crate) fn client_call_span(ctx: &Context, selected_model: &str) -> Span {
-    tracing::info_span!(
-        target: SCOPE,
-        "libsy.client_call",
-        algorithm = algorithm_label(ctx),
-        selected_model,
-        outcome = tracing::field::Empty,
-        error = tracing::field::Empty,
-    )
-}
-
 /// Records the outcome fields on the enclosing `libsy.client_call` span. The
 /// failure itself is not logged here — it propagates to the algorithm, where
 /// the `libsy.llm_call` recording logs it once.
@@ -179,26 +138,6 @@ pub(crate) fn record_client_call(result: &Result<Response, BoxErr>) {
     }
 }
 
-/// Span covering one offloaded model call, a child of the surrounding
-/// `libsy.run` span. It measures *fulfillment* as the algorithm observes it —
-/// host queueing and serving included, not just the provider call. `outcome`,
-/// `error`, and the token-count fields are filled in by [`record_llm_call`]
-/// when the call resolves.
-fn llm_call_span(algorithm: &str, selected_model: &str) -> Span {
-    tracing::info_span!(
-        target: SCOPE,
-        "libsy.llm_call",
-        algorithm,
-        selected_model,
-        outcome = tracing::field::Empty,
-        error = tracing::field::Empty,
-        input_tokens = tracing::field::Empty,
-        output_tokens = tracing::field::Empty,
-        total_tokens = tracing::field::Empty,
-        reasoning_tokens = tracing::field::Empty,
-    )
-}
-
 /// Records the end of one algorithm run: the run counter and duration
 /// histogram, the `outcome`/`error` fields on `span`, and a warn log when the
 /// run failed.
@@ -226,7 +165,7 @@ fn record_run(algorithm: &str, duration: Duration, result: &Result<Response, Box
 /// latency histogram, token counters from the response usage (absent fields are
 /// skipped, not recorded as zero), the `outcome`/`error`/token fields on
 /// `span`, and a warn log when the call failed.
-fn record_llm_call(
+pub(crate) fn record_llm_call(
     algorithm: &str,
     selected_model: &str,
     duration: Duration,

crates/libsy/src/observability.rs

@@ -453,9 +453,10 @@ async fn successful_run_records_metrics_spans_and_decision_log() -> Result<(), B
     // The default-client serve inside `run` gets its own client-call span.
     let client_span = find_span(&spans, "libsy.client_call", "selected_model", MODEL);
     // Host-side span: `run`'s serve loop creates it outside the algorithm's
-    // spans, so it has no libsy parent. This pins the `Future::instrument`
-    // idiom — an `Entered` guard held across the offload `.await` would leave
-    // `libsy.llm_call` entered on the thread and leak it in as the parent.
+    // spans, so it has no libsy parent. This pins the instrument idiom
+    // (`#[tracing::instrument]` / `Future::instrument`) — an `Entered` guard
+    // held across the offload `.await` would leave `libsy.llm_call` entered
+    // on the thread and leak it in as the parent.
     assert_eq!(client_span.parent.as_deref(), None);
     assert_eq!(
         client_span.fields.get("algorithm").map(String::as_str),