diff --git a/.changeset/tracing-custom-spans.md b/.changeset/tracing-custom-spans.md new file mode 100644 index 000000000..b930ea808 --- /dev/null +++ b/.changeset/tracing-custom-spans.md @@ -0,0 +1,11 @@ +--- +"workers-rs": minor +--- + +Add `worker::observability` — bindings for Cloudflare Workers [custom spans](https://developers.cloudflare.com/changelog/post/2026-06-16-custom-spans/) (`cloudflare:workers` `enterSpan`). + +- `enter_span(name, |span| ...)` and `enter_span_async(name, |span| async { ... })` open custom trace spans that nest under the automatic platform spans in the Workers Observability waterfall. +- `Span::set_attribute` / `Span::is_traced` attach metadata and check sampling. +- `with_active_span` exposes the innermost open span so a `tracing_subscriber::Layer` can forward `tracing` events/fields onto it. + +The new `custom-spans` example shows a ready-made `WorkersLayer` doing exactly that. Addresses #899. diff --git a/Cargo.lock b/Cargo.lock index cb8b17987..4d2f10fdc 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -489,6 +489,16 @@ dependencies = [ "windows-sys 0.61.2", ] +[[package]] +name = "console_error_panic_hook" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a06aeb73f470f66dcdbf7223caeebb85984942f22f1adb2a088cf9668146bbbc" +dependencies = [ + "cfg-if", + "wasm-bindgen", +] + [[package]] name = "const-oid" version = "0.10.2" @@ -669,6 +679,16 @@ dependencies = [ "worker", ] +[[package]] +name = "custom-spans" +version = "0.1.0" +dependencies = [ + "console_error_panic_hook", + "tracing", + "tracing-subscriber", + "worker", +] + [[package]] name = "data-encoding" version = "2.11.0" diff --git a/examples/custom-spans/Cargo.toml b/examples/custom-spans/Cargo.toml new file mode 100644 index 000000000..e921dd71b --- /dev/null +++ b/examples/custom-spans/Cargo.toml @@ -0,0 +1,17 @@ +[package] +name = "custom-spans" +version = "0.1.0" +edition = "2021" + +[package.metadata.release] +release = false + +[lib] +crate-type = ["cdylib"] + +[dependencies] +# Binding comes from `worker`; the WorkersLayer (src/layer.rs) needs tracing-subscriber. +worker.workspace = true +tracing = "0.1" +tracing-subscriber = { version = "0.3", default-features = false, features = ["registry", "std"] } +console_error_panic_hook = "0.1" diff --git a/examples/custom-spans/README.md b/examples/custom-spans/README.md new file mode 100644 index 000000000..5120976d8 --- /dev/null +++ b/examples/custom-spans/README.md @@ -0,0 +1,25 @@ +# custom-spans + +Custom trace spans for Workers Observability, in Rust — using +[`worker::observability`](../../worker/src/observability.rs). + +It demonstrates: + +- `enter_span_async("handle_request", |span| async move { … })` — an async + root span around the request handler. +- `enter_span("load_rows", |span| …)` — a nested sync span that auto-parents + under the root via the JS async context. +- `span.set_attribute(...)` and `span.is_traced()`. +- `WorkersLayer` (the `tracing` feature) forwarding ordinary `tracing::info!` + events onto the active platform span as attributes. + +Custom spans are recorded only when tracing is enabled in your Worker's +observability config — see `wrangler.toml` (`[observability.traces]`). + +```sh +npx wrangler deploy +``` + +Then open the Worker's **Observability → Traces** view and trigger a request; +`handle_request` and its nested `load_rows` span appear in the waterfall next to +the automatic `fetch` span. diff --git a/examples/custom-spans/package.json b/examples/custom-spans/package.json new file mode 100644 index 000000000..dfae78872 --- /dev/null +++ b/examples/custom-spans/package.json @@ -0,0 +1,12 @@ +{ + "name": "custom-spans", + "version": "0.0.0", + "private": true, + "scripts": { + "deploy": "cargo install worker-build ; wrangler deploy", + "dev": "cargo install worker-build ; wrangler dev --local" + }, + "devDependencies": { + "wrangler": "^4" + } +} diff --git a/examples/custom-spans/src/layer.rs b/examples/custom-spans/src/layer.rs new file mode 100644 index 000000000..1a913bfd5 --- /dev/null +++ b/examples/custom-spans/src/layer.rs @@ -0,0 +1,97 @@ +//! `WorkersLayer` — a `tracing_subscriber::Layer` that forwards `tracing` +//! events and span fields onto the active Workers platform span. +//! +//! ## Why it's shaped this way +//! +//! `tracing` models a span lifetime as two separate operations — `on_enter` +//! and a later `on_exit`, driven by a guard's `Drop`. The platform models it +//! as one **callback-scoped** operation (`enterSpan(name, cb)`); there is no +//! imperative start/end. A `Layer` therefore can't bridge an arbitrary +//! `tracing::span!` to a platform span: at `on_enter` it would have to call +//! `enterSpan` and not return from its callback until the separate `on_exit`, +//! which a single-threaded Worker can't suspend and resume. Durations have to +//! come from the platform anyway, since guest timer resolution is clamped. +//! +//! So the work splits: span **structure + timing** come from wrapping work in +//! [`worker::observability::enter_span`] / `enter_span_async` (closure-scoped, +//! so they map onto `enterSpan` and nest via the JS async context); **events + +//! fields** are forwarded by this layer onto the active span via +//! [`worker::observability::with_active_span`]. +//! +//! This lives in the example rather than the `worker` crate so `worker` stays +//! free of a `tracing-subscriber` dependency. Copy it into your project, or +//! lift it into `worker` behind a feature if your project wants it there. + +use tracing::field::{Field, Visit}; +use tracing::span::{Attributes, Id, Record}; +use tracing::{Event, Subscriber}; +use tracing_subscriber::layer::Context; +use tracing_subscriber::registry::LookupSpan; +use tracing_subscriber::Layer; +use worker::observability::{with_active_span, Span}; + +/// Forwards `tracing` events and span fields onto the active platform span as +/// attributes. Install it on a `tracing_subscriber` registry and establish +/// platform spans with `worker::observability::enter_span[_async]`. +#[derive(Debug, Default, Clone, Copy)] +pub struct WorkersLayer; + +impl Layer for WorkersLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, +{ + fn on_new_span(&self, attrs: &Attributes<'_>, _id: &Id, _ctx: Context<'_, S>) { + let prefix = attrs.metadata().name(); + with_active_span(|span| attrs.record(&mut AttrVisitor { span, prefix })); + } + + fn on_record(&self, id: &Id, values: &Record<'_>, ctx: Context<'_, S>) { + let prefix = ctx.span(id).map(|s| s.name()).unwrap_or("span"); + with_active_span(|span| values.record(&mut AttrVisitor { span, prefix })); + } + + fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) { + let prefix = event.metadata().level().as_str(); + with_active_span(|span| event.record(&mut AttrVisitor { span, prefix })); + } +} + +/// Writes each visited `tracing` field as a typed `setAttribute` on the +/// platform span, under the key `"."`. +struct AttrVisitor<'a> { + span: &'a Span, + prefix: &'a str, +} + +impl AttrVisitor<'_> { + fn key(&self, field: &Field) -> String { + format!("{}.{}", self.prefix, field.name()) + } +} + +impl Visit for AttrVisitor<'_> { + fn record_bool(&mut self, field: &Field, value: bool) { + self.span.set_attribute(&self.key(field), value); + } + + fn record_i64(&mut self, field: &Field, value: i64) { + self.span.set_attribute(&self.key(field), value); + } + + fn record_u64(&mut self, field: &Field, value: u64) { + self.span.set_attribute(&self.key(field), value); + } + + fn record_f64(&mut self, field: &Field, value: f64) { + self.span.set_attribute(&self.key(field), value); + } + + fn record_str(&mut self, field: &Field, value: &str) { + self.span.set_attribute(&self.key(field), value); + } + + fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) { + self.span + .set_attribute(&self.key(field), format!("{value:?}").as_str()); + } +} diff --git a/examples/custom-spans/src/lib.rs b/examples/custom-spans/src/lib.rs new file mode 100644 index 000000000..dacf0f656 --- /dev/null +++ b/examples/custom-spans/src/lib.rs @@ -0,0 +1,51 @@ +//! Custom trace spans for Workers Observability, in Rust. +//! +//! Wraps the request in an async platform span, nests a sync span under it, +//! and lets the `WorkersLayer` forward `tracing` events onto the active span. +//! Deploy with `observability.traces` enabled (see `wrangler.toml`) and the +//! spans appear in the trace waterfall alongside the automatic `fetch` span. + +mod layer; + +use layer::WorkersLayer; +use tracing::info; +use tracing_subscriber::prelude::*; +use worker::observability::{enter_span, enter_span_async}; +use worker::{event, Context, Env, Request, Response, Result}; + +#[event(start)] +fn start() { + console_error_panic_hook::set_once(); + // `try_init` so a hot-reloaded isolate doesn't panic on a second install. + let _ = tracing_subscriber::registry().with(WorkersLayer).try_init(); +} + +#[event(fetch)] +async fn fetch(req: Request, _env: Env, _ctx: Context) -> Result { + let path = req.path(); + + enter_span_async("handle_request", move |span| async move { + span.set_attribute("http.path", path.as_str()); + span.set_attribute("sampled", span.is_traced()); + + // A plain `tracing` event — the layer forwards `user_id` as an + // attribute on `handle_request`. No platform-specific code here. + info!(user_id = 42, "request received"); + + // A nested sync span; auto-parents under `handle_request`. + let rows = enter_span("load_rows", |child| { + let rows = expensive_query(); + child.set_attribute("db.rows", rows); + rows + }); + + info!(rows, "query complete"); + Response::ok(format!("loaded {rows} rows for {path}")) + }) + .await +} + +/// Stand-in for real work — a Worker would hit D1 / KV / a binding here. +fn expensive_query() -> u32 { + 1234 +} diff --git a/examples/custom-spans/wrangler.toml b/examples/custom-spans/wrangler.toml new file mode 100644 index 000000000..78fcd6ded --- /dev/null +++ b/examples/custom-spans/wrangler.toml @@ -0,0 +1,14 @@ +name = "custom-spans" +main = "build/worker/shim.mjs" +compatibility_date = "2026-06-16" + +[build] +command = "cargo install \"worker-build@^0.8\" && worker-build --release" + +# Custom spans are only recorded when tracing is enabled in observability. +[observability] +enabled = true + +[observability.traces] +enabled = true +head_sampling_rate = 1 diff --git a/worker/src/bindings/mod.rs b/worker/src/bindings/mod.rs index aa5f45d47..9411253d2 100644 --- a/worker/src/bindings/mod.rs +++ b/worker/src/bindings/mod.rs @@ -1 +1,2 @@ pub mod email; +pub mod tracing; diff --git a/worker/src/bindings/tracing.rs b/worker/src/bindings/tracing.rs new file mode 100644 index 000000000..8a6f4b80e --- /dev/null +++ b/worker/src/bindings/tracing.rs @@ -0,0 +1,71 @@ +//! Raw `wasm-bindgen` import of the `cloudflare:workers` `tracing` API. +//! +//! Hand-written (not `ts-gen`-generated) because the safe wrapper in +//! [`crate::tracing`] needs a couple of shapes `ts-gen` doesn't express well — +//! the two `enterSpan` callback forms (sync vs. promise-returning) and the +//! `setAttribute` value overloads. +//! +//! Platform surface (`@cloudflare/workers-types`): +//! +//! ```ts +//! interface Tracing { +//! enterSpan( +//! name: string, +//! callback: (span: Span, ...args: A) => T, +//! ...args: A +//! ): T; +//! } +//! declare abstract class Span { +//! get isTraced(): boolean; +//! setAttribute(key: string, value?: boolean | number | string): void; +//! } +//! ``` + +use js_sys::Promise; +use wasm_bindgen::closure::ScopedClosure; +use wasm_bindgen::prelude::*; + +#[wasm_bindgen(module = "cloudflare:workers")] +extern "C" { + /// The `tracing` namespace object exported by `cloudflare:workers`. + /// Thread-local because a Worker isolate is single-threaded and the + /// binding is not `Sync`. + #[wasm_bindgen(thread_local_v2, js_name = tracing)] + pub(crate) static TRACING: Tracing; + + #[wasm_bindgen(js_name = Tracing)] + pub(crate) type Tracing; + + /// `enterSpan` with a synchronous callback: the span closes when the + /// callback returns. + #[wasm_bindgen(method, js_name = enterSpan)] + pub(crate) fn enter_span_sync(this: &Tracing, name: &str, cb: &ScopedClosure); + + /// `enterSpan` with an async callback: the callback returns a `Promise` + /// and workerd keeps the span open until it settles. `enterSpan` returns + /// that same promise. + #[wasm_bindgen(method, js_name = enterSpan)] + pub(crate) fn enter_span_async( + this: &Tracing, + name: &str, + cb: &Closure Promise>, + ) -> Promise; + + /// A live span handle. Refcounted JS object — cloning is cheap and a clone + /// stays valid while the span is open. + #[wasm_bindgen(js_name = Span)] + #[derive(Debug, Clone)] + pub(crate) type Span; + + // `setAttribute(key, value)` is `boolean | number | string` in JS; bind one + // overload per kind so the safe wrapper stays typed. + #[wasm_bindgen(method, js_name = setAttribute)] + pub(crate) fn set_attribute_bool(this: &Span, key: &str, value: bool); + #[wasm_bindgen(method, js_name = setAttribute)] + pub(crate) fn set_attribute_num(this: &Span, key: &str, value: f64); + #[wasm_bindgen(method, js_name = setAttribute)] + pub(crate) fn set_attribute_str(this: &Span, key: &str, value: &str); + + #[wasm_bindgen(method, getter, js_name = isTraced)] + pub(crate) fn is_traced(this: &Span) -> bool; +} diff --git a/worker/src/lib.rs b/worker/src/lib.rs index 604cf0c09..f48323b44 100644 --- a/worker/src/lib.rs +++ b/worker/src/lib.rs @@ -241,6 +241,7 @@ mod headers; mod http; mod hyperdrive; pub mod kv; +pub mod observability; #[cfg(feature = "queue")] mod queue; mod r2; diff --git a/worker/src/observability.rs b/worker/src/observability.rs new file mode 100644 index 000000000..241f5c210 --- /dev/null +++ b/worker/src/observability.rs @@ -0,0 +1,200 @@ +//! Custom trace spans for Workers Observability. +//! +//! Wraps the `cloudflare:workers` [custom-span API][api]: [`enter_span`] (sync) +//! and [`enter_span_async`] (for `async` handlers) open a span that appears in +//! the trace waterfall alongside the automatic `fetch` / KV / D1 spans, with +//! correct parent-child nesting. Attach metadata with [`Span::set_attribute`]. +//! +//! ```ignore +//! use worker::observability::{enter_span, enter_span_async}; +//! +//! # async fn handler() { +//! enter_span_async("handle_request", |span| async move { +//! span.set_attribute("http.path", "/items"); +//! enter_span("load_rows", |child| { +//! child.set_attribute("db.rows", 42); +//! }); +//! }) +//! .await; +//! # } +//! ``` +//! +//! Spans are **callback-scoped**: a span opens when `enter_span` is called and +//! closes when the callback returns (sync) or its future resolves (async). +//! There is no imperative start/end — the platform measures duration itself, +//! which is why durations are accurate even though guest timer resolution is +//! clamped. +//! +//! ## Bridging the `tracing` crate +//! +//! [`with_active_span`] exposes the innermost open span so a +//! `tracing_subscriber::Layer` can forward `tracing` events/fields onto it as +//! attributes. A ready-made layer isn't included here to keep this crate free +//! of a `tracing-subscriber` dependency — see the `custom-spans` example for a +//! `WorkersLayer` you can copy. +//! +//! [api]: https://developers.cloudflare.com/changelog/post/2026-06-16-custom-spans/ + +use std::cell::RefCell; +use std::future::Future; + +use wasm_bindgen::closure::ScopedClosure; +use wasm_bindgen::prelude::*; +use wasm_bindgen_futures::{future_to_promise, JsFuture}; + +use crate::bindings::tracing as raw; + +/// A handle to an open span. Cheap to clone (a refcounted JS object). Valid +/// only while the span that produced it is open, which by construction is the +/// body of the [`enter_span`] / [`enter_span_async`] call that yielded it. +#[derive(Debug, Clone)] +pub struct Span(raw::Span); + +impl Span { + /// Attach an attribute. Accepts any [`AttributeValue`] (`bool`, integer, + /// float, or string). + pub fn set_attribute(&self, key: &str, value: impl AttributeValue) { + value.set_on(self, key); + } + + /// Whether this request is being sampled. Use it to skip building + /// expensive attributes when the span won't be recorded. + pub fn is_traced(&self) -> bool { + self.0.is_traced() + } +} + +mod sealed { + pub trait Sealed {} +} + +/// A value that can be attached to a [`Span`] — the JS `boolean | number | +/// string` union. Integers are widened to `f64` (JS `number`); values past +/// 2^53 lose precision. Sealed: implemented for the primitive types only. +pub trait AttributeValue: sealed::Sealed { + #[doc(hidden)] + fn set_on(self, span: &Span, key: &str); +} + +impl sealed::Sealed for bool {} +impl AttributeValue for bool { + fn set_on(self, span: &Span, key: &str) { + span.0.set_attribute_bool(key, self); + } +} + +impl sealed::Sealed for &str {} +impl AttributeValue for &str { + fn set_on(self, span: &Span, key: &str) { + span.0.set_attribute_str(key, self); + } +} + +macro_rules! attribute_value_num { + ($($t:ty),*) => {$( + impl sealed::Sealed for $t {} + impl AttributeValue for $t { + fn set_on(self, span: &Span, key: &str) { + span.0.set_attribute_num(key, self as f64); + } + } + )*}; +} +attribute_value_num!(i8, i16, i32, i64, isize, u8, u16, u32, u64, usize, f32, f64); + +thread_local! { + /// Stack of currently-open platform spans, innermost last. Pushed by + /// `enter_span` / `enter_span_async` for the duration of their body so a + /// `tracing` layer (see [`with_active_span`]) can target the active span. A + /// thread-local rather than the `tracing` registry because a JS [`Span`] is + /// `!Send` and registry extensions must be `Send + Sync`. + static ACTIVE: RefCell> = const { RefCell::new(Vec::new()) }; +} + +fn push_active(span: &Span) { + ACTIVE.with_borrow_mut(|s| s.push(span.clone())); +} + +fn pop_active() { + ACTIVE.with_borrow_mut(|s| { + s.pop(); + }); +} + +/// Run `f` with the innermost open span, if any; returns `None` when no span is +/// open. The hook a `tracing_subscriber::Layer` uses to forward events onto the +/// active platform span (see the `custom-spans` example). `f` must not re-enter +/// this function — a borrow is held for its duration. +pub fn with_active_span(f: impl FnOnce(&Span) -> R) -> Option { + ACTIVE.with_borrow(|stack| stack.last().map(f)) +} + +/// Open a synchronous custom span named `name`, run `f` inside it, and close +/// it when `f` returns. Nests under any span already open on the JS async +/// context — including an enclosing [`enter_span`] — so the platform tree +/// mirrors the call tree. +pub fn enter_span(name: &str, f: impl FnOnce(&Span) -> T) -> T { + let mut f = Some(f); + let mut out: Option = None; + + // `enterSpan` invokes this exactly once, synchronously, before returning, + // so the callback may borrow non-`'static` state. `borrow_mut` encodes + // that the JS function must not outlive this stack frame. + let mut cb = |span: raw::Span| { + let span = Span(span); + push_active(&span); + let f = f.take().expect("enterSpan invoked its callback twice"); + out = Some(f(&span)); + pop_active(); + }; + + { + let scoped = ScopedClosure::borrow_mut(&mut cb); + raw::TRACING.with(|t| t.enter_span_sync(name, &scoped)); + } + + out.expect("enterSpan must invoke its callback synchronously") +} + +/// Open an asynchronous custom span named `name`, drive `f`'s future inside it, +/// and close it when the future resolves. This is the form `async` request +/// handlers need. +/// +/// Unlike [`enter_span`], the callback returns a `Promise` that outlives the +/// `enterSpan` call (workerd awaits it), so `f` and its future must be +/// `'static`. +pub async fn enter_span_async(name: &str, f: F) -> T +where + F: FnOnce(Span) -> Fut + 'static, + Fut: Future + 'static, + T: 'static, +{ + let result: std::rc::Rc>> = std::rc::Rc::new(RefCell::new(None)); + let sink = result.clone(); + + let mut f = Some(f); + let cb = Closure::wrap(Box::new(move |span: raw::Span| -> js_sys::Promise { + let span = Span(span); + let f = f.take().expect("enterSpan invoked its callback twice"); + let fut = f(span.clone()); + let sink = sink.clone(); + future_to_promise(async move { + push_active(&span); + let value = fut.await; + pop_active(); + *sink.borrow_mut() = Some(value); + Ok(JsValue::UNDEFINED) + }) + }) as Box js_sys::Promise>); + + let promise = raw::TRACING.with(|t| t.enter_span_async(name, &cb)); + // Keep `cb` alive until the span's promise settles, then drop it. + let _ = JsFuture::from(promise).await; + drop(cb); + + std::rc::Rc::try_unwrap(result) + .ok() + .expect("span future outlived its handle") + .into_inner() + .expect("enterSpan async callback must resolve the result") +}