telltale_runtime/effects/middleware/
trace.rs

1// Tracing middleware for effect handlers
2//
3// Logs all choreographic operations with timing information for debugging and monitoring.
4
5use async_trait::async_trait;
6use serde::{de::DeserializeOwned, Serialize};
7use std::time::{Duration, Instant};
8use tracing::{debug, trace, warn};
9
10use crate::effects::contract::{DocumentedHandlerContract, HandlerContractProfile};
11use crate::effects::registry::{ExtensibleHandler, ExtensionRegistry};
12use crate::effects::{ChoreoHandler, ChoreoResult, RoleId};
13
14/// Tracing middleware that logs all choreographic operations
15#[derive(Clone)]
16pub struct Trace<H> {
17    inner: H,
18    prefix: String,
19}
20
21impl<H> Trace<H> {
22    pub fn new(inner: H) -> Self {
23        Self::with_prefix(inner, "choreo")
24    }
25
26    pub fn with_prefix(inner: H, prefix: impl Into<String>) -> Self {
27        Self {
28            inner,
29            prefix: prefix.into(),
30        }
31    }
32}
33
34impl<H> DocumentedHandlerContract for Trace<H>
35where
36    H: DocumentedHandlerContract,
37{
38    fn contract_profile() -> HandlerContractProfile {
39        let mut profile = H::contract_profile();
40        profile.handler_name = std::any::type_name::<Self>();
41        profile
42            .notes
43            .push("trace middleware may observe operations but must not change semantic outcomes");
44        profile
45    }
46}
47
48#[async_trait]
49impl<H: ChoreoHandler + Send> ChoreoHandler for Trace<H> {
50    type Role = H::Role;
51    type Endpoint = H::Endpoint;
52
53    async fn send<M: Serialize + Send + Sync>(
54        &mut self,
55        ep: &mut Self::Endpoint,
56        to: Self::Role,
57        msg: &M,
58    ) -> ChoreoResult<()> {
59        let start = Instant::now();
60        trace!(prefix = %self.prefix, ?to, "send: start");
61        let result = self.inner.send(ep, to, msg).await;
62        let duration = start.elapsed();
63        match &result {
64            Ok(()) => debug!(prefix = %self.prefix, ?to, ?duration, "send: success"),
65            Err(e) => warn!(prefix = %self.prefix, ?to, ?duration, error = %e, "send: failed"),
66        }
67        result
68    }
69
70    async fn recv<M: DeserializeOwned + Send>(
71        &mut self,
72        ep: &mut Self::Endpoint,
73        from: Self::Role,
74    ) -> ChoreoResult<M> {
75        let start = Instant::now();
76        trace!(prefix = %self.prefix, ?from, "recv: start");
77        let result = self.inner.recv(ep, from).await;
78        let duration = start.elapsed();
79        match &result {
80            Ok(_) => debug!(prefix = %self.prefix, ?from, ?duration, "recv: success"),
81            Err(e) => warn!(prefix = %self.prefix, ?from, ?duration, error = %e, "recv: failed"),
82        }
83        result
84    }
85
86    async fn choose(
87        &mut self,
88        ep: &mut Self::Endpoint,
89        who: Self::Role,
90        label: <Self::Role as RoleId>::Label,
91    ) -> ChoreoResult<()> {
92        debug!(prefix = %self.prefix, ?who, ?label, "choose");
93        self.inner.choose(ep, who, label).await
94    }
95
96    async fn offer(
97        &mut self,
98        ep: &mut Self::Endpoint,
99        from: Self::Role,
100    ) -> ChoreoResult<<Self::Role as RoleId>::Label> {
101        trace!(prefix = %self.prefix, ?from, "offer: waiting");
102        let label = self.inner.offer(ep, from).await?;
103        debug!(prefix = %self.prefix, ?from, ?label, "offer: received");
104        Ok(label)
105    }
106
107    async fn with_timeout<F, T>(
108        &mut self,
109        ep: &mut Self::Endpoint,
110        at: Self::Role,
111        dur: Duration,
112        body: F,
113    ) -> ChoreoResult<T>
114    where
115        F: std::future::Future<Output = ChoreoResult<T>> + Send,
116    {
117        debug!(prefix = %self.prefix, ?at, ?dur, "timeout: start");
118        let start = Instant::now();
119        let result = self.inner.with_timeout(ep, at, dur, body).await;
120        let elapsed = start.elapsed();
121        match &result {
122            Ok(_) => debug!(prefix = %self.prefix, ?at, ?elapsed, "timeout: completed"),
123            Err(e) => warn!(prefix = %self.prefix, ?at, ?elapsed, error = %e, "timeout: failed"),
124        }
125        result
126    }
127}
128
129impl<H> ExtensibleHandler for Trace<H>
130where
131    H: ExtensibleHandler + Send,
132{
133    fn extension_registry(&self) -> &ExtensionRegistry<Self::Endpoint, Self::Role> {
134        self.inner.extension_registry()
135    }
136}
telltale_runtime/effects/middleware/trace.rs

telltale_runtime/effects/middleware/
trace.rs
