recon_sim/
narrate.rs

1//! Rendering a run to a `tracing` subscriber as it happens.
2//!
3//! The trace is the record; this is a view of it. Both come from one producer in one order, so
4//! there is no second account of the run to disagree with the first — which is the whole reason
5//! narration goes into the trace rather than straight to a subscriber.
6//!
7//! # Why the driver renders, and not the protocol
8//!
9//! `tracing`'s dispatcher is thread-local. A protocol calling `tracing::info!` would be reaching
10//! for something ambient, which constraint 2 exists to forbid, and it would get both of the facts a
11//! reader needs first wrong: five simulated processes share one thread, so nothing would say *which*
12//! process spoke, and a subscriber timestamps with the wall clock, which measures how long the
13//! simulation took rather than anything about the run being reproduced.
14//!
15//! So protocols call `Cx::note`, the simulator records it, and only the simulator — a driver, which
16//! is allowed to — touches a dispatcher.
17//!
18//! # As it is recorded, not at the end
19//!
20//! A run that fails to terminate is one of the things worth reading, and a renderer that walked a
21//! finished trace would have nothing to show for it.
22
23use crate::trace::{ProtoTraceEvent, TraceEvent};
24use core::fmt::Debug;
25use recon_core::Protocol;
26
27/// Renders one recorded event. A function pointer rather than a closure so that the simulator can
28/// hold it without acquiring `Debug` bounds it does not otherwise need — the same shape as the
29/// codec check.
30pub(crate) type Render<P> = fn(&ProtoTraceEvent<P>);
31
32/// Emit one recorded event to whatever subscriber is installed.
33///
34/// `at` is the run's virtual time on every event, and `node` names the process wherever the event
35/// has one. Everything the simulator does to a run is `DEBUG`; what a protocol *says* is `INFO`,
36/// because that is the half a reader is usually after and the half that is rare.
37pub(crate) fn render<P>(event: &ProtoTraceEvent<P>)
38where
39    P: Protocol,
40    P::Msg: Debug,
41    P::Ind: Debug,
42    P::Note: Debug,
43    P::Cmd: Debug,
44{
45    let at = event.at().as_offset();
46    match event {
47        TraceEvent::Said { node, note, .. } => {
48            tracing::info!(target: "recon_sim", ?at, node = %node, ?note, "said");
49        }
50        TraceEvent::Invoked { node, op, cmd, .. } => {
51            tracing::info!(target: "recon_sim", ?at, node = %node, %op, ?cmd, "invoked");
52        }
53        TraceEvent::NotInvoked { node, op, cmd, why, .. } => {
54            tracing::info!(target: "recon_sim", ?at, node = %node, %op, ?cmd, ?why, "not invoked");
55        }
56        TraceEvent::Sent { from, to, msg, .. } => {
57            tracing::debug!(target: "recon_sim", ?at, node = %from, %to, ?msg, "sent");
58        }
59        TraceEvent::HandedToSelf { node, msg, .. } => {
60            tracing::debug!(target: "recon_sim", ?at, node = %node, ?msg, "handed to self");
61        }
62        TraceEvent::Delivered { from, to, msg, .. } => {
63            tracing::debug!(target: "recon_sim", ?at, node = %to, %from, ?msg, "delivered");
64        }
65        TraceEvent::Dropped { from, to, msg, reason, .. } => {
66            tracing::debug!(target: "recon_sim", ?at, node = %from, %to, ?msg, ?reason, "dropped");
67        }
68        TraceEvent::Duplicated { from, to, msg, .. } => {
69            tracing::debug!(target: "recon_sim", ?at, node = %from, %to, ?msg, "duplicated");
70        }
71        TraceEvent::Reordered { from, to, msg, .. } => {
72            tracing::debug!(target: "recon_sim", ?at, node = %from, %to, ?msg, "reordered");
73        }
74        TraceEvent::TimerFired { node, id, .. } => {
75            tracing::debug!(target: "recon_sim", ?at, node = %node, ?id, "timer fired");
76        }
77        TraceEvent::Indicated { node, ind, .. } => {
78            tracing::debug!(target: "recon_sim", ?at, node = %node, ?ind, "indicated");
79        }
80        TraceEvent::SessionOpened { a, b, epoch, .. } => {
81            tracing::debug!(target: "recon_sim", ?at, %a, %b, epoch, "session opened");
82        }
83        TraceEvent::SessionEnded { a, b, epoch, reason, .. } => {
84            tracing::debug!(target: "recon_sim", ?at, %a, %b, epoch, ?reason, "session ended");
85        }
86        TraceEvent::SuffixLost { from, to, msg, .. } => {
87            tracing::debug!(target: "recon_sim", ?at, node = %from, %to, ?msg, "suffix lost");
88        }
89        TraceEvent::Crashed { node, .. } => {
90            tracing::debug!(target: "recon_sim", ?at, node = %node, "crashed");
91        }
92        TraceEvent::Suspended { node, .. } => {
93            tracing::debug!(target: "recon_sim", ?at, node = %node, "suspended");
94        }
95        TraceEvent::Resumed { node, .. } => {
96            tracing::debug!(target: "recon_sim", ?at, node = %node, "resumed");
97        }
98        TraceEvent::Restarted { node, .. } => {
99            tracing::debug!(target: "recon_sim", ?at, node = %node, "restarted");
100        }
101        TraceEvent::Wrote { node, kind, .. } => {
102            tracing::debug!(target: "recon_sim", ?at, node = %node, ?kind, "wrote");
103        }
104        TraceEvent::DiedWriting { node, .. } => {
105            tracing::debug!(target: "recon_sim", ?at, node = %node, "died writing");
106        }
107        TraceEvent::Recovered { node, had_state, .. } => {
108            tracing::debug!(target: "recon_sim", ?at, node = %node, had_state, "recovered");
109        }
110    }
111}
recon_sim/narrate.rs

recon_sim/
narrate.rs
