Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
751 changes: 751 additions & 0 deletions docs/execplans/11-1-2-structured-logging-and-tracing-spans.md

Large diffs are not rendered by default.

6 changes: 3 additions & 3 deletions docs/roadmap.md
Original file line number Diff line number Diff line change
Expand Up @@ -493,9 +493,9 @@ document so larger deployments can adopt the library confidently.
- [x] 11.1.1. Add middleware hooks for outgoing requests and incoming frames so
metrics, retries, and authentication tokens can be injected symmetrically
with server middleware.
- [ ] 11.1.2. Provide structured logging and tracing spans around connect,
send, receive, and stream lifecycle events, plus configuration for
per-command timing.
- [x] 11.1.2. Provide structured logging and tracing spans around connect,
send, receive, call, stream, and close lifecycle events, plus configuration
for per-command timing.

### 11.2. Connection pooling and concurrency

Expand Down
40 changes: 40 additions & 0 deletions docs/users-guide.md
Original file line number Diff line number Diff line change
Expand Up @@ -1140,6 +1140,7 @@ as `TCP_NODELAY` or buffer size adjustments.
| Error hook | `on_error(...)` | Disabled | Transport and decode failures must be routed to observability. |
| Before-send hook | `before_send(...)` | Disabled | Inspect or mutate serialized bytes before every outgoing frame. |
| After-receive hook | `after_receive(...)` | Disabled | Inspect or mutate raw bytes after every incoming frame is read. |
| Tracing config | `tracing_config(TracingConfig)` | INFO connect/close, DEBUG data ops, timing off | Customize tracing span levels and per-command timing. |

```rust
use std::{net::SocketAddr, time::Duration};
Expand Down Expand Up @@ -1423,6 +1424,45 @@ println!("sent {} frames", outcome.frames_sent());
`frames_sent()`. The error hook is invoked on all failure paths, consistent
with other client send methods.[^53]

### Client tracing

The client emits `tracing` spans around every operation. Span levels and
per-command timing are configurable via `TracingConfig`, which is passed to the
builder with `tracing_config()`. When no `tracing` subscriber is installed, all
instrumentation is zero-cost.

Default span levels: `INFO` for lifecycle operations (`connect`, `close`) and
`DEBUG` for data operations (`send`, `receive`, `call`, `call_streaming`).
Per-command timing is disabled by default.

```rust
use std::net::SocketAddr;

use tracing::Level;
use wireframe::client::{TracingConfig, WireframeClient};

let addr: SocketAddr = "127.0.0.1:7878".parse().expect("valid socket address");

// Enable timing for connect and call, set all spans to TRACE level.
let config = TracingConfig::default()
.with_all_levels(Level::TRACE)
.with_connect_timing(true)
.with_call_timing(true);

let mut client = WireframeClient::builder()
.tracing_config(config)
.connect(addr)
.await?;
```

When timing is enabled for an operation, a `DEBUG`-level event recording
`elapsed_us` is emitted when the operation completes (on both success and error
paths). Streaming responses emit per-frame `DEBUG` events with
`stream.frames_received` and a termination event with `stream.frames_total`.

Clients configured without `tracing_config()` use the default configuration and
behave identically to the pre-tracing API.

### Client message API with correlation identifiers

The client provides envelope-aware messaging APIs that work with the `Packet`
Expand Down
58 changes: 58 additions & 0 deletions docs/wireframe-client-design.md
Original file line number Diff line number Diff line change
Expand Up @@ -67,6 +67,7 @@ length‑delimited codec.
| Setup hook | `on_connection_setup(...)` | Disabled | Store per-connection state for metrics, auth context, or counters. |
| Teardown hook | `on_connection_teardown(...)` | Disabled | Flush metrics and release per-connection resources on `close()`. |
| Error hook | `on_error(...)` | Disabled | Centralize client transport/decode/correlation error reporting. |
| Tracing config | `tracing_config(TracingConfig)` | INFO connect/close, DEBUG data ops, timing off | Customize tracing span levels and per-command timing. |

### Request/response helpers

Expand Down Expand Up @@ -241,6 +242,63 @@ can universally inspect or modify the serialized payload.
`after_receive` is wired into `receive_internal()` (messaging.rs) and
`ResponseStream::poll_next()` (response_stream.rs).

### Tracing instrumentation

Every client operation is wrapped in a `tracing` span with structured fields.
Span levels are configurable per-operation via `TracingConfig`, with sensible
defaults: `INFO` for lifecycle operations (connect, close) and `DEBUG` for
high-frequency data operations (send, receive, call, streaming). When no
`tracing` subscriber is installed, all instrumentation is zero-cost.

**Span hierarchy and field conventions:**

| Operation | Span name | Structured fields |
| ------------------- | ------------------------ | ------------------------------------------ |
| `connect()` | `client.connect` | `peer.addr` |
| `send()` | `client.send` | `frame.bytes` |
| `receive()` | `client.receive` | `frame.bytes` (deferred), `result` |
| `send_envelope()` | `client.send_envelope` | `correlation_id`, `frame.bytes` |
| `call()` | `client.call` | `result` (deferred) |
| `call_correlated()` | `client.call_correlated` | `correlation_id` (deferred), `result` |
| `call_streaming()` | `client.call_streaming` | `correlation_id`, `frame.bytes` (deferred) |
| `close()` | `client.close` | (none) |

**Per-frame streaming events**: `ResponseStream` emits `tracing::debug!` events
(not spans) on each received data frame and on stream termination:

- `stream frame received` with `frame.bytes`, `stream.frames_received`, and
`correlation_id`.
- `stream terminated` with `stream.frames_total` and `correlation_id`.

**Per-command timing**: When enabled via `TracingConfig::with_*_timing(true)`,
an additional `tracing::debug!` event recording `elapsed_us` is emitted when
the operation completes. Timing events fire on both success and error paths.
Timing is disabled by default for all operations.

**Design rationale — async-safe span instrumentation**: `Span::enter()` guards
must not be held across `.await` points because a multi-threaded runtime may
poll the future on a different thread, causing the span to be "entered" on the
wrong thread. Client methods use `tracing::Instrument::instrument(span)` to
wrap async futures so the span is entered only while the future is polled and
exited between polls. For purely synchronous sections,
`Span::in_scope(|| { ... })` is the correct pattern. See the
[`tracing::Instrument`][instrument-docs] trait and the
[`#[tracing::instrument]`][attr-docs] attribute for further guidance.

[instrument-docs]: https://docs.rs/tracing/latest/tracing/trait.Instrument.html
[attr-docs]: https://docs.rs/tracing/latest/tracing/attr.instrument.html

**Design rationale — `dynamic_span!` macro**: The `tracing` crate requires
compile-time level constants in `span!` macros. To support user-configurable
levels per operation, a `macro_rules!` macro in `tracing_helpers.rs` matches on
the five `Level` variants, delegating to the corresponding
`tracing::<level>_span!` macro per branch. Each branch has static metadata
while branch selection is dynamic.

**Design rationale — `ResponseStream` events, not spans**: Creating spans
inside `poll_next` is problematic because it is synchronous and called many
times. Events are lightweight and appropriate for per-frame diagnostics.

### Preamble support

The client builder now supports an optional preamble exchange. Use
Expand Down
28 changes: 26 additions & 2 deletions src/client/builder/connect.rs
Original file line number Diff line number Diff line change
@@ -1,14 +1,20 @@
//! Connection establishment for `WireframeClientBuilder`.

use std::{net::SocketAddr, sync::atomic::AtomicU64};
use std::{net::SocketAddr, sync::atomic::AtomicU64, time::Instant};

use bincode::Encode;
use tokio::net::TcpSocket;
use tokio_util::codec::Framed;
use tracing::Instrument;

use super::WireframeClientBuilder;
use crate::{
client::{ClientError, WireframeClient, preamble_exchange::perform_preamble_exchange},
client::{
ClientError,
WireframeClient,
preamble_exchange::perform_preamble_exchange,
tracing_helpers::{connect_span, emit_timing_event},
},
rewind_stream::RewindStream,
serializer::Serializer,
};
Expand Down Expand Up @@ -51,6 +57,23 @@ where
pub async fn connect(
self,
addr: SocketAddr,
) -> Result<WireframeClient<S, RewindStream<tokio::net::TcpStream>, C>, ClientError> {
let span = connect_span(&self.tracing_config, &addr.to_string());
let timing_start = self.tracing_config.connect_timing.then(Instant::now);

Comment thread
coderabbitai[bot] marked this conversation as resolved.
async {
let result = self.connect_inner(addr).await;
emit_timing_event(timing_start);
result
}
.instrument(span)
.await
}

/// Perform socket creation, connection, preamble exchange, and codec setup.
async fn connect_inner(
self,
addr: SocketAddr,
) -> Result<WireframeClient<S, RewindStream<tokio::net::TcpStream>, C>, ClientError> {
let socket = if addr.is_ipv4() {
TcpSocket::new_v4()?
Expand Down Expand Up @@ -95,6 +118,7 @@ where
on_disconnect: self.lifecycle_hooks.on_disconnect,
on_error: self.lifecycle_hooks.on_error,
request_hooks: self.request_hooks,
tracing_config: self.tracing_config,
correlation_counter: AtomicU64::new(1),
})
}
Expand Down
3 changes: 3 additions & 0 deletions src/client/builder/core.rs
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@ use crate::{
SocketOptions,
hooks::{LifecycleHooks, RequestHooks},
preamble_exchange::PreambleConfig,
tracing_config::TracingConfig,
},
serializer::BincodeSerializer,
};
Expand All @@ -32,6 +33,7 @@ pub struct WireframeClientBuilder<S = BincodeSerializer, P = (), C = ()> {
pub(crate) preamble_config: Option<PreambleConfig<P>>,
pub(crate) lifecycle_hooks: LifecycleHooks<C>,
pub(crate) request_hooks: RequestHooks,
pub(crate) tracing_config: TracingConfig,
}

impl WireframeClientBuilder<BincodeSerializer, (), ()> {
Expand All @@ -54,6 +56,7 @@ impl WireframeClientBuilder<BincodeSerializer, (), ()> {
preamble_config: None,
lifecycle_hooks: LifecycleHooks::default(),
request_hooks: RequestHooks::default(),
tracing_config: TracingConfig::default(),
}
}
}
Expand Down
4 changes: 4 additions & 0 deletions src/client/builder/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -28,6 +28,7 @@ macro_rules! builder_field_update {
preamble_config: $self.preamble_config,
lifecycle_hooks: $self.lifecycle_hooks,
request_hooks: $self.request_hooks,
tracing_config: $self.tracing_config,
}
};
// Preamble change: preserves S and C, moves lifecycle_hooks unchanged
Expand All @@ -39,6 +40,7 @@ macro_rules! builder_field_update {
preamble_config: $value,
lifecycle_hooks: $self.lifecycle_hooks,
request_hooks: $self.request_hooks,
tracing_config: $self.tracing_config,
}
};
// Lifecycle hooks change: preserves S and P, changes C
Expand All @@ -50,6 +52,7 @@ macro_rules! builder_field_update {
preamble_config: $self.preamble_config,
lifecycle_hooks: $value,
request_hooks: $self.request_hooks,
tracing_config: $self.tracing_config,
}
};
}
Expand All @@ -61,5 +64,6 @@ mod lifecycle;
mod preamble;
mod request_hooks;
mod serializer;
mod tracing;

pub use core::WireframeClientBuilder;
35 changes: 35 additions & 0 deletions src/client/builder/tracing.rs
Original file line number Diff line number Diff line change
@@ -0,0 +1,35 @@
//! Tracing configuration builder method for [`WireframeClientBuilder`].

use super::WireframeClientBuilder;
use crate::{client::tracing_config::TracingConfig, serializer::Serializer};

impl<S, P, C> WireframeClientBuilder<S, P, C>
where
S: Serializer + Send + Sync,
{
/// Configure tracing instrumentation for the client.
///
/// The [`TracingConfig`] controls which operations emit tracing spans,
/// at what level, and whether per-command elapsed-time events are
/// recorded.
///
/// When not called, the client uses [`TracingConfig::default()`], which
/// emits `INFO` spans for lifecycle operations (`connect`, `close`) and
/// `DEBUG` spans for data operations (`send`, `receive`, `call`,
/// `call_streaming`). Timing is disabled by default.
///
/// # Examples
///
/// ```
/// use wireframe::client::{TracingConfig, WireframeClientBuilder};
///
/// let config = TracingConfig::default().with_all_timing(true);
/// let builder = WireframeClientBuilder::new().tracing_config(config);
/// let _ = builder;
/// ```
#[must_use]
pub fn tracing_config(mut self, config: TracingConfig) -> Self {
self.tracing_config = config;
self
}
}
Loading
Loading