cove_runtime/trace.rs
1//! Runtime observability.
2//!
3//! ADR 0001 asks the runtime to trace host calls, capability use, and task
4//! lifecycle "without language-specific application hooks" — a program does
5//! not opt in to being traced, and it cannot opt out of being traceable. This
6//! module defines the event shape and where events go; [`crate::host`] and
7//! (in a later pass) the interpreter are the only places that produce them.
8//!
9//! A trace is also the input to `cove replay`, which reproduces a run's Host
10//! API interactions without calling a host. That is why [`TraceEvent::HostCall`]
11//! carries the call's arguments and its result and not only its shape: a
12//! trace that says a call happened is enough to inspect a run, and not enough
13//! to reproduce one.
14//!
15//! # JSON schema
16//!
17//! [`JsonlSink`] writes one JSON object per line, and every `Duration` field
18//! is rendered as an integer count of nanoseconds under a key ending in
19//! `_ns`. The first line is a header declaring [`TRACE_FORMAT_VERSION`], so a
20//! reader that does not know the version can reject the trace rather than
21//! misread it. These keys are a stable, documented interface — a trace format
22//! that changes silently breaks whatever reads it:
23//!
24//! ```text
25//! {"event":"trace_header","version":<u32>,"backend":"ast"|"vm","values":"full"|"redacted","entry":<string>,"args":[<string>...]}
26//! {"event":"task_spawned","id":<u64>,"parent":<u64|null>,"scope":<string>}
27//! {"event":"task_completed","id":<u64>,"cpu_ns":<u64>}
28//! {"event":"task_cancelled","id":<u64>}
29//! {"event":"host_call","task":<u64>,"module":<string>,"op":<string>,"capability":<string>,"wait_ns":<u64>,"granted":<bool>,"args":[<value>...],"outcome":<outcome>|null}
30//! {"event":"entry_enter","module":<string>,"function":<string>}
31//! {"event":"entry_exit","module":<string>,"function":<string>,"cpu_ns":<u64>,"wait_ns":<u64>}
32//! {"event":"heap_collected","task":<u64>,"allocated":<u64>,"freed":<u64>,"live_objects":<u64>,"live_bytes":<u64>,"pause_ns":<u64>}
33//! {"event":"heap_summary","collections":<u64>,"object_count":<u64>|null,"allocated_bytes":<u64>|null,"live_bytes":<u64>|null,"peak_bytes":<u64>|null,"pause_ns":<u64>|null,"allocated_words":<u64>|null,"capacity_words":<u64>|null,"live_words":<u64>|null}
34//! {"event":"run_ended","outcome":<outcome-name>,"message":<string>|null}
35//! ```
36//!
37//! A `task` is the id of the task that did the thing, and the entry's own id
38//! is [`crate::runtime::ENTRY_TASK`]: the entry is not a spawned task, so it
39//! takes the one id the run never hands out. An `<outcome-name>` is one of
40//! the names [`RunOutcome::as_str`] writes.
41//!
42//! An `<outcome>` is `null` for a call that never reached the host, and
43//! otherwise one of:
44//!
45//! ```text
46//! {"kind":"value","value":<value>}
47//! {"kind":"error","message":<string>}
48//! {"kind":"not_recordable"}
49//! ```
50//!
51//! A `<value>` is a tagged encoding of one [`Value`], covering the shapes
52//! that cross the Host API boundary:
53//!
54//! ```text
55//! {"type":"unit"}
56//! {"type":"bool","value":<bool>}
57//! {"type":"int","value":<i64>}
58//! {"type":"float","value":<number>}
59//! {"type":"duration","ns":<i64>}
60//! {"type":"string","value":<string>}
61//! {"type":"array","items":[<value>...]}
62//! {"type":"enum","name":<string>,"case":<string>,"payload":[<value>...]}
63//! {"type":"struct","name":<string>,"fields":[{"name":<string>,"value":<value>}...]}
64//! {"type":"resource","name":<string>,"id":<i64>}
65//! {"type":"redacted","of":<string>}
66//! {"type":"opaque","of":<string>,"shown":<string>}
67//! ```
68//!
69//! `redacted` is what [`ValueCapture::Redacted`] writes in place of every
70//! recorded value; `opaque` is what a value the encoding cannot represent —
71//! a vector, a closure, a task handle — leaves behind. Both are readable and
72//! neither can be replayed, which is exactly the distinction `cove replay`
73//! reports.
74//!
75//! # What an event may carry
76//!
77//! An event is produced by whichever task made the call and written by the
78//! one sink the run shares, so every event crosses a thread boundary. What
79//! may cross one is what the Language Card's task-safety rule allows, which
80//! `cove_runtime::task::Transfer` both decides and carries — so that is the
81//! form a [`RecordedValue`] keeps a value in. A value that may not cross
82//! keeps instead what a trace could have said about it anyway: what it was
83//! and what it printed as, which is the `opaque` the format already writes
84//! for a vector. The two features agree by construction: a value a task
85//! could not have carried is a value a replay could not have reproduced.
86
87use std::io::Write;
88use std::sync::Mutex;
89use std::time::Duration;
90
91use crate::task::Transfer;
92use crate::value::{Repr, Value};
93use crate::wallclock::Instant;
94
95/// The version of the JSONL trace format this build writes, and the only one
96/// it reads.
97///
98/// Version 2 gave every `host_call` the id of the task that made it, gave
99/// every run a terminal `run_ended` event, and settled `heap_collected`'s
100/// `task` on the same convention the other two use, so the entry is task
101/// [`crate::runtime::ENTRY_TASK`] rather than a null. A version 1 trace can
102/// answer none of the three questions this build's reader now asks of one, and
103/// a reader that met a `run_ended` it had never heard of would report a broken
104/// line rather than an old file — so the version says what changed and a
105/// version 1 trace is refused for its version.
106///
107/// Version 3 added [`TraceHeader::backend`], so a file says which of the two
108/// backends wrote it and `cove replay` reads that rather than guessing it.
109/// ADR 0026 is the decision. A version 2 trace is refused for its version,
110/// exactly as a version 1 one is: this reader has always read one version,
111/// and a version 2 file is precisely a file that cannot answer the question a
112/// version 3 replay asks first.
113///
114/// Version 4 reshaped `heap_summary`. It had six fields and all six described
115/// a heap that is a set of objects, because the only machine that wrote one
116/// had such a heap. The linear-memory backend's heap is a run of words, and
117/// [issue #240](https://github.com/myuon/cove/issues/240) decided not to make
118/// the event choose: *"Do not force `heap_summary` to choose between objects
119/// and words. They answer different questions."* So the event now carries
120/// both families, every figure is `null` from a machine that does not count
121/// it, and no reader is handed a zero that reads as a measurement. A version
122/// 3 trace is refused for its version like the two before it.
123pub const TRACE_FORMAT_VERSION: u32 = 4;
124
125/// The version of the `cove-runtime` crate a program ran against —
126/// `CARGO_PKG_VERSION` at build time, and nothing more than that.
127///
128/// This is not [`TRACE_FORMAT_VERSION`]: that one versions the shape of the
129/// JSONL a trace is written as, and moves only when an event's fields do,
130/// which is rarely. This one moves with every release of the crate, whether
131/// or not a single trace field changed, because what it answers is "which
132/// build of the runtime ran this" rather than "can this reader parse what was
133/// written".
134///
135/// [Issue #248](https://github.com/myuon/cove/issues/248) is why this exists:
136/// an embedding that records enough to replay a run needs a
137/// `cove_runtime_version` among what it records, and before this there was
138/// nothing reachable from the embedding API to put there — only
139/// `TRACE_FORMAT_VERSION`, which answers a different question, and the
140/// interface hash `cove-cli` computes for its own package format, which is
141/// `pub(crate)` and hashes declared signatures rather than a build. A version
142/// genuinely is the runtime's own to answer, and re-exporting the one Cargo
143/// already stamps on every build costs nothing.
144///
145/// A replay identity needs one more thing this crate can answer and this
146/// constant does not carry: which backend ran the program. Fuel is not
147/// portable between [`Vm`](crate::Vm) and the tree-walking interpreter, so a
148/// version without a backend does not pin down a run. [`RecordingBackend`]
149/// is that other half — already public, already spelled the way `--backend`
150/// accepts — and a replay identity built from the embedding API is this
151/// constant plus one of its variants, not a new string invented to match
152/// them. What this constant deliberately does not attempt is a hash of the
153/// program that ran: that identity is the *embedding's* source or bytecode,
154/// not the runtime's, and only the embedding knows which of those it shipped
155/// — folding it in here would answer a question that belongs one layer up.
156pub const RUNTIME_VERSION: &str = env!("CARGO_PKG_VERSION");
157
158/// Which backend produced a recording.
159///
160/// A trace is written by `cove run --trace`, by a built binary, and by a
161/// benchmark, and all of them run a program on one of the evaluators this
162/// toolchain has. The header names which, so that `cove replay` can run the
163/// recording on the backend that made it without inferring anything, and can
164/// say so when it was told to do otherwise. ADR 0026 is the decision and its
165/// reasoning.
166///
167/// A closed set rather than free text, spelled with the names `--backend`
168/// accepts, so a reader that meets an unknown name refuses the file rather
169/// than carrying a string it cannot act on.
170#[derive(Clone, Copy, Debug, PartialEq, Eq)]
171pub enum RecordingBackend {
172 /// The tree-walking interpreter, which ADR 0012 keeps as the oracle.
173 Ast,
174 /// The linear-memory backend of ADR 0034, which is what runs a program.
175 ///
176 /// Between ADR 0034's cutover and the rename that followed it, this
177 /// backend was spelled `lvm` here, and a trace recorded in that window
178 /// says so. Such a file is not read: [`RecordingBackend::parse`] refuses
179 /// `lvm` the way it refuses any other name, and `cove replay` reports it
180 /// as a header it cannot read. That is the trade issue #240 took
181 /// deliberately when it chose to delete the predecessor first and rename
182 /// second — the window is measured in commits, the format version had
183 /// already moved to 4 in the same cutover, and a trace is a recording of
184 /// a run that can be taken again. Nothing was built to accept the old
185 /// spelling: an alias would make a name that is scheduled to mean
186 /// nothing readable forever.
187 Vm,
188}
189
190impl RecordingBackend {
191 /// The name this backend is written under in a trace header, which is
192 /// also the name `--backend` accepts for it.
193 pub fn as_str(self) -> &'static str {
194 match self {
195 RecordingBackend::Ast => "ast",
196 RecordingBackend::Vm => "vm",
197 }
198 }
199
200 /// Parses the name [`RecordingBackend::as_str`] produces.
201 pub fn parse(text: &str) -> Option<RecordingBackend> {
202 match text {
203 "ast" => Some(RecordingBackend::Ast),
204 "vm" => Some(RecordingBackend::Vm),
205 _ => None,
206 }
207 }
208}
209
210impl std::fmt::Display for RecordingBackend {
211 fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
212 f.write_str(self.as_str())
213 }
214}
215
216/// How much of a host call's arguments and results a trace records.
217///
218/// A trace is a file a human may read and may share, and `env.get`,
219/// `files.read`, and `documents.read` all answer with whatever the host holds
220/// — which may be a secret. [`ValueCapture::Full`] is the default because a
221/// trace that does not carry values cannot be replayed, and replay is the
222/// reason the values are recorded at all; [`ValueCapture::Redacted`] is the
223/// form to share, and it is honest about what it dropped rather than
224/// pretending the call never happened.
225#[derive(Clone, Copy, Debug, PartialEq, Eq)]
226pub enum ValueCapture {
227 /// Record every argument and result in full.
228 Full,
229 /// Record each value's type and nothing else.
230 Redacted,
231}
232
233impl ValueCapture {
234 /// The name this mode is written under in a trace header, and the name
235 /// `cove run --trace-values` accepts.
236 pub fn as_str(self) -> &'static str {
237 match self {
238 ValueCapture::Full => "full",
239 ValueCapture::Redacted => "redacted",
240 }
241 }
242
243 /// Parses the name [`ValueCapture::as_str`] produces.
244 pub fn parse(text: &str) -> Option<ValueCapture> {
245 match text {
246 "full" => Some(ValueCapture::Full),
247 "redacted" => Some(ValueCapture::Redacted),
248 _ => None,
249 }
250 }
251}
252
253/// What a trace declares about itself before its first event.
254///
255/// The entry and its arguments are here because a replay needs them and no
256/// event carries them: `cove replay` starts the same entry with the same
257/// arguments, and refuses a trace recorded from a different one. The backend
258/// is here for the same reason read one step further: a replay wants to be
259/// the run it replays, and which evaluator ran is part of what that run was.
260#[derive(Clone, Debug)]
261pub struct TraceHeader {
262 /// Which backend ran the program this trace recorded.
263 pub backend: RecordingBackend,
264 /// How much of each host call's values the trace carries.
265 pub values: ValueCapture,
266 /// The qualified entry function the run started, such as
267 /// `restricted.main`.
268 pub entry: String,
269 /// The process arguments the entry was given.
270 pub args: Vec<String>,
271}
272
273/// One value as a trace records it.
274///
275/// A trace event crosses from the task that produced it to the sink that
276/// writes it, so the values it carries are exactly the values that may cross
277/// a task boundary: a [`Transfer`], which is what the task-safety rule
278/// produces. Everything else is kept as the `opaque` marker the format
279/// already writes for it.
280#[derive(Clone, Debug)]
281pub enum RecordedValue {
282 /// A value the trace carries whole.
283 Carried(Transfer),
284 /// A value no task boundary may carry — a vector, a task, a task scope —
285 /// kept as the type it had and the text it printed as.
286 Opaque {
287 /// The type name, which is also all a redacted trace records.
288 of: String,
289 /// What the value printed as.
290 shown: String,
291 },
292}
293
294impl RecordedValue {
295 /// Records `value`: whole when it may cross a boundary, and as what it
296 /// was when it may not.
297 pub fn of(value: &Value) -> RecordedValue {
298 match Transfer::of(value) {
299 Ok(transfer) => RecordedValue::Carried(transfer),
300 Err(_) => RecordedValue::Opaque {
301 of: value.type_name(),
302 shown: value.to_string(),
303 },
304 }
305 }
306}
307
308/// What a host call produced, when the trace records it.
309#[derive(Clone, Debug)]
310pub enum HostOutcome {
311 /// The host answered with a value. A Cove `Err(...)` is a value like any
312 /// other and arrives here, not in [`HostOutcome::Error`].
313 Value(RecordedValue),
314 /// The host refused the call with a runtime error, which is not an
315 /// ordinary Cove failure.
316 Error(String),
317 /// The operation's schema declares it not recordable, so the call
318 /// dispatched but its result was deliberately not written down.
319 ///
320 /// `process.exit` is the shipped example: handing its result back on a
321 /// replay would keep running a program that had ended.
322 NotRecordable,
323}
324
325/// How a run ended.
326///
327/// Every run reaches exactly one of these, and [`TraceEvent::RunEnded`]
328/// records which. The names [`RunOutcome::as_str`] writes are a compatibility
329/// surface like the rest of the format: a reader groups runs by them.
330///
331/// The first two are the program answering. Cove's entry returns
332/// `Result<Unit, Error>`, so a returned `Err` is a program saying what it was
333/// written to say and not a failure of the run — which is why it is kept
334/// apart from every other way a run can end. The rest are failures, and they
335/// divide the way [`crate::error::RuntimeError`]'s own documentation divides
336/// them: a broken invariant, the Host API boundary refusing, or a limit the
337/// host imposed. The limits are [`crate::budget::Stopped`] one for one, so a
338/// trace names the control that stopped the run rather than reporting six
339/// stops as one.
340#[derive(Clone, Copy, Debug, PartialEq, Eq)]
341pub enum RunOutcome {
342 /// The entry returned a value that is not an `Err`.
343 Success,
344 /// The entry returned `Err(...)`: expected failure, expressed in the
345 /// language rather than by stopping the run.
346 Error,
347 /// Cove execution broke an invariant — a failed assertion, a division by
348 /// zero, an overflow, a violated task-safety rule.
349 ///
350 /// This is also where a host that failed on its own terms arrives, and
351 /// the two are not currently told apart: an error raised inside a host
352 /// and an error raised by a Cove callback the host was running come back
353 /// out of the same call, and nothing at the boundary can say which was
354 /// which.
355 Invariant,
356 /// The Host API boundary refused: a capability the run was not granted,
357 /// an operation that does not exist, or an argument or a result the
358 /// operation's own schema does not admit.
359 HostBoundary,
360 /// The fuel budget was exhausted.
361 Fuel,
362 /// The wall-clock deadline was exceeded.
363 Deadline,
364 /// The run was cancelled from outside.
365 Cancelled,
366 /// The call-depth limit was exceeded.
367 CallDepth,
368 /// The host-call limit was exceeded.
369 HostCalls,
370 /// A `spawn` would have passed the concurrency limit.
371 Concurrency,
372 /// A debugger halted the run.
373 ///
374 /// Its own outcome for the reason every other stop mode has one: a
375 /// reader deciding what to do about a stopped run wants to know which
376 /// control stopped it, and a run somebody was stepping through is not a
377 /// run that broke an invariant or ran out of anything.
378 Debugger,
379}
380
381impl RunOutcome {
382 /// The name this outcome is written under in a trace.
383 pub fn as_str(self) -> &'static str {
384 match self {
385 RunOutcome::Success => "success",
386 RunOutcome::Error => "error",
387 RunOutcome::Invariant => "invariant",
388 RunOutcome::HostBoundary => "host_boundary",
389 RunOutcome::Fuel => "fuel",
390 RunOutcome::Deadline => "deadline",
391 RunOutcome::Cancelled => "cancelled",
392 RunOutcome::CallDepth => "call_depth",
393 RunOutcome::HostCalls => "host_calls",
394 RunOutcome::Concurrency => "concurrency",
395 RunOutcome::Debugger => "debugger",
396 }
397 }
398
399 /// Parses the name [`RunOutcome::as_str`] produces.
400 pub fn parse(text: &str) -> Option<RunOutcome> {
401 [
402 RunOutcome::Success,
403 RunOutcome::Error,
404 RunOutcome::Invariant,
405 RunOutcome::HostBoundary,
406 RunOutcome::Fuel,
407 RunOutcome::Deadline,
408 RunOutcome::Cancelled,
409 RunOutcome::CallDepth,
410 RunOutcome::HostCalls,
411 RunOutcome::Concurrency,
412 RunOutcome::Debugger,
413 ]
414 .into_iter()
415 .find(|outcome| outcome.as_str() == text)
416 }
417
418 /// Whether this outcome is one a program chose rather than one the
419 /// runtime imposed.
420 ///
421 /// The distinction the trace makes with it is what a redacted trace
422 /// carries: the message of a run the program ended is a value the program
423 /// built, which may hold anything the run read, while the message of a
424 /// run the runtime stopped is the runtime's own sentence about its own
425 /// limit.
426 pub fn is_the_program_s_own(self) -> bool {
427 matches!(self, RunOutcome::Success | RunOutcome::Error)
428 }
429}
430
431/// One recorded runtime event.
432#[derive(Clone, Debug)]
433pub enum TraceEvent {
434 /// A task was created in `scope`, as a child of `parent` (or none, for a
435 /// root task).
436 TaskSpawned {
437 id: u64,
438 parent: Option<u64>,
439 scope: String,
440 },
441 /// A task ran to completion, having spent `cpu` executing (not waiting
442 /// on a host call).
443 TaskCompleted { id: u64, cpu: Duration },
444 /// A task was cancelled before it completed.
445 TaskCancelled { id: u64 },
446 /// A Host API call was dispatched (`granted: true`) or rejected
447 /// (`granted: false`), after waiting `wait` for the host to respond. For
448 /// a rejected call, `wait` is the time spent deciding to reject it, which
449 /// is ordinarily negligible.
450 ///
451 /// `args` are the arguments the program passed, and `outcome` is what the
452 /// host answered — `None` for a call that never reached a host, so there
453 /// was nothing to answer. Together they are what makes the call
454 /// reproducible.
455 ///
456 /// `task` is the task that made the call, which is what lets a trace of a
457 /// run with concurrent tasks be grouped by whose I/O each call was. The
458 /// entry made its own calls under [`crate::runtime::ENTRY_TASK`].
459 HostCall {
460 task: u64,
461 module: String,
462 op: String,
463 capability: String,
464 wait: Duration,
465 granted: bool,
466 args: Vec<RecordedValue>,
467 outcome: Option<HostOutcome>,
468 },
469 /// One task's heap was collected.
470 ///
471 /// ADR 0001 asks a trace to make allocation and memory pressure visible,
472 /// and ADR 0011 makes this the event that does it. Allocation is reported
473 /// as the count since the previous collection rather than as one event per
474 /// object: an event per allocation would be most of the trace, and would
475 /// tell a reader less about pressure than the pair of numbers that bracket
476 /// it — what was allocated, and what survived.
477 ///
478 /// A heap belongs to one task, so this event says whose it was, and two
479 /// tasks collecting at the same time produce two independent events.
480 HeapCollected {
481 /// The task whose heap this was, or [`crate::runtime::ENTRY_TASK`]
482 /// for the entry's own.
483 task: u64,
484 /// Objects allocated since the previous collection.
485 allocated: u64,
486 /// Objects this collection reclaimed.
487 freed: u64,
488 /// Objects live after it.
489 live_objects: u64,
490 /// Bytes live after it.
491 live_bytes: u64,
492 /// How long the task was stopped.
493 pause: Duration,
494 },
495 /// What every heap in the run did, recorded once as the run ends.
496 ///
497 /// Every figure but `collections` is optional, and that is
498 /// [issue #240](https://github.com/myuon/cove/issues/240)'s decision
499 /// rather than laxity. The two evaluators do not have the same kind of
500 /// heap: the interpreter's is a set of `Rc`-ed objects and it counts
501 /// objects and the bytes they asked for, while the linear-memory
502 /// backend's is a run of eight-byte words and it counts words. Neither
503 /// figure can be derived from the other — an inline struct is words in
504 /// one and no object at all in the other — so the event carries both
505 /// families and a machine leaves `None` in the ones it does not count.
506 /// A zero there would read as a measurement of nothing rather than as the
507 /// absence of a measurement, which is the same distinction `cove run
508 /// --stats` draws.
509 HeapSummary {
510 /// How many collections ran, over every heap of the run.
511 ///
512 /// The one figure both machines count, and the one that is not
513 /// optional: a collection is a collection whatever the heap holds.
514 collections: u64,
515 /// Collectable objects allocated over the whole run, by every task.
516 object_count: Option<u64>,
517 /// Bytes those allocations asked for.
518 allocated_bytes: Option<u64>,
519 /// Bytes live when the run ended. Every heap is swept once more as it
520 /// is retired, so this is what the entry was still holding after its
521 /// own last sweep — usually nothing.
522 live_bytes: Option<u64>,
523 /// The largest live set any one collection measured.
524 peak_bytes: Option<u64>,
525 /// Total time tasks were stopped for collection, summed over threads,
526 /// so a run with four tasks collecting at once can report more pause
527 /// than it took wall-clock time.
528 pause: Option<Duration>,
529 /// Words handed out over the whole run, reuse counted each time.
530 ///
531 /// Cumulative rather than present: it is what the run asked the
532 /// allocator for, so a loop that allocates and drops shows the work
533 /// it did rather than the nothing it kept.
534 allocated_words: Option<u64>,
535 /// Words the heap region occupies, free blocks included.
536 capacity_words: Option<u64>,
537 /// Words held by objects that survived the run's last collection, and
538 /// `None` when no collection ran, because there is then nothing that
539 /// measured it.
540 live_words: Option<u64>,
541 },
542 /// A host-selected entry function began running.
543 EntryEnter { module: String, function: String },
544 /// A host-selected entry function finished, having spent `cpu` executing
545 /// and `wait` waiting on host calls.
546 EntryExit {
547 module: String,
548 function: String,
549 cpu: Duration,
550 wait: Duration,
551 },
552 /// The run ended, and this is how. The last event of every trace.
553 ///
554 /// [`TraceEvent::EntryExit`] says what an entry that got as far as
555 /// running spent; this says how the whole run came out, including for a
556 /// run that never reached its entry at all. There is one per run because
557 /// there is one entry per run: a task that ends is already three events
558 /// of its own, and a task's failure does not decide the run's — it
559 /// reaches whoever joined it, and either stops the run, which this event
560 /// then reports with that task's own message, or is handled, in which
561 /// case no terminal classification would have been true of it.
562 RunEnded {
563 outcome: RunOutcome,
564 /// Why, for an outcome that has a why: the `Error` the entry
565 /// returned, or the message of the error that stopped the run.
566 /// `None` for a run that succeeded.
567 message: Option<String>,
568 },
569}
570
571/// Where trace events go.
572///
573/// A sink records through a shared reference and is `Send + Sync` because
574/// every task thread traces into the same one: ADR 0008 runs each spawned
575/// task on its own thread, and a trace that each thread wrote to separately
576/// would not be one trace. A sink that needs mutable state of its own
577/// synchronizes it, which is also what keeps two threads from interleaving
578/// halves of a line.
579///
580/// # Two installation points, not one
581///
582/// One `Arc<dyn TraceSink>` does not see every event: a run has two of them.
583/// [`HostRegistry::set_trace`](crate::HostRegistry::set_trace) is where
584/// [`TraceEvent::HostCall`] alone goes. Every other event —
585/// [`TraceEvent::TaskSpawned`], [`TraceEvent::TaskCompleted`],
586/// [`TraceEvent::TaskCancelled`], [`TraceEvent::HeapCollected`],
587/// [`TraceEvent::HeapSummary`], [`TraceEvent::EntryEnter`],
588/// [`TraceEvent::EntryExit`] and [`TraceEvent::RunEnded`] — goes through
589/// [`Runtime::with_trace`](crate::Runtime::with_trace). Each defaults to its
590/// own [`NullSink`], independently, so installing one says nothing about
591/// whether the other was, and an embedding that installs only one gets a
592/// trace that is silently missing the other's events rather than an error.
593///
594/// # Correlating an event to something of the host's own
595///
596/// [`TraceEvent`]'s task-lifecycle and per-call variants carry a bare task
597/// id — [`crate::runtime::ENTRY_TASK`] for the entry, and whatever
598/// [`Runtime::next_task_id`](crate::Runtime::next_task_id) handed out for a
599/// spawned one — and nothing else. That is deliberate rather than an
600/// omission: the id a host wants to hang an event on (a creature, a request,
601/// a session) belongs to the host, not to the runtime, and a sink is exactly
602/// the place a host bridges the two. A sink built per invocation, closing
603/// over the host's own identifier, is how that bridge is made; the runtime
604/// does not carry the identifier itself because it has no way to know what
605/// shape it should be.
606pub trait TraceSink: Send + Sync {
607 /// Records one event. Must not panic: a broken trace sink should degrade
608 /// the trace, not the program being traced.
609 fn record(&self, event: TraceEvent);
610
611 /// Whether anything will read what is recorded.
612 ///
613 /// Describing a host call's values costs a copy of each of them, and a
614 /// value no boundary may carry costs printing it. A run that is not being
615 /// traced should not pay for a trace nobody keeps, so a sink that
616 /// discards everything says so and [`crate::host::HostRegistry::call`]
617 /// skips the description. The default is `true`: a sink that does
618 /// something with an event needs the event to be complete.
619 fn is_recording(&self) -> bool {
620 true
621 }
622}
623
624/// Creates the file a trace is written to, readable only by its owner where
625/// the platform can say so.
626///
627/// A full-capture trace holds whatever the host answered with, so it is not a
628/// file to leave world-readable by default. The mode applies to a file this
629/// call creates; one that already exists keeps the permissions it has.
630pub fn create_trace_file(path: &std::path::Path) -> std::io::Result<std::fs::File> {
631 let mut options = std::fs::OpenOptions::new();
632 options.write(true).create(true).truncate(true);
633 #[cfg(unix)]
634 {
635 use std::os::unix::fs::OpenOptionsExt;
636 options.mode(0o600);
637 }
638 options.open(path)
639}
640
641/// Discards every event. The default when a run is not being traced.
642pub struct NullSink;
643
644impl TraceSink for NullSink {
645 fn record(&self, _event: TraceEvent) {}
646
647 fn is_recording(&self) -> bool {
648 false
649 }
650}
651
652/// Writes one JSON object per line to `W`, flushing after every event so a
653/// trace is visible as it happens rather than only at exit.
654///
655/// The writer is behind a lock so that a line written from a task thread is
656/// written whole: concurrent tasks produce events at the same time, and half
657/// a JSON object is not a trace line.
658pub struct JsonlSink<W: Write + Send> {
659 writer: Mutex<W>,
660 values: ValueCapture,
661}
662
663impl<W: Write + Send> JsonlSink<W> {
664 /// Writes trace lines to `writer`, starting with the header line that
665 /// declares the format version, the backend that is about to run, the
666 /// value capture mode, and the entry the run started.
667 pub fn new(mut writer: W, header: TraceHeader) -> Self {
668 let args = header
669 .args
670 .iter()
671 .map(|arg| json_string(arg))
672 .collect::<Vec<_>>()
673 .join(",");
674 // A trace sink degrades silently: losing a trace line must never
675 // fail the run it is observing.
676 let _ = writeln!(
677 writer,
678 "{{\"event\":\"trace_header\",\"version\":{TRACE_FORMAT_VERSION},\"backend\":{},\"values\":{},\"entry\":{},\"args\":[{args}]}}",
679 json_string(header.backend.as_str()),
680 json_string(header.values.as_str()),
681 json_string(&header.entry),
682 );
683 let _ = writer.flush();
684 JsonlSink {
685 writer: Mutex::new(writer),
686 values: header.values,
687 }
688 }
689}
690
691impl<W: Write + Send> TraceSink for JsonlSink<W> {
692 fn record(&self, event: TraceEvent) {
693 let line = to_json_line(&event, self.values);
694 // A trace sink degrades silently: losing a trace line must never fail
695 // the run it is observing, and that includes a lock another thread
696 // poisoned by panicking.
697 let Ok(mut writer) = self.writer.lock() else {
698 return;
699 };
700 let _ = writeln!(writer, "{line}");
701 let _ = writer.flush();
702 }
703}
704
705/// Escapes `s` as a JSON string literal, including the surrounding quotes.
706fn json_string(s: &str) -> String {
707 let mut out = String::with_capacity(s.len() + 2);
708 out.push('"');
709 for c in s.chars() {
710 match c {
711 '"' => out.push_str("\\\""),
712 '\\' => out.push_str("\\\\"),
713 '\n' => out.push_str("\\n"),
714 '\r' => out.push_str("\\r"),
715 '\t' => out.push_str("\\t"),
716 c if (c as u32) < 0x20 => out.push_str(&format!("\\u{:04x}", c as u32)),
717 c => out.push(c),
718 }
719 }
720 out.push('"');
721 out
722}
723
724/// Renders a `Duration` as the integer nanosecond count a `_ns`-suffixed key
725/// expects.
726fn json_ns(d: Duration) -> u128 {
727 d.as_nanos()
728}
729
730/// A figure a machine may not have counted, as JSON.
731///
732/// `null` rather than `0`, for the reason [`TraceEvent::HeapSummary`] gives:
733/// a zero is a measurement and the absence of one is not.
734fn json_measure(measured: Option<impl std::fmt::Display>) -> String {
735 match measured {
736 Some(value) => value.to_string(),
737 None => "null".to_string(),
738 }
739}
740
741/// Renders one [`Value`] in the trace's value encoding, honouring `capture`.
742///
743/// [`ValueCapture::Redacted`] replaces the whole value, not only its leaves:
744/// a redaction that kept the shape of a struct would still describe the
745/// secret it was hiding.
746pub fn value_to_json(value: &Value, capture: ValueCapture) -> String {
747 match capture {
748 ValueCapture::Full => encode_value(value),
749 ValueCapture::Redacted => format!(
750 "{{\"type\":\"redacted\",\"of\":{}}}",
751 json_string(&value.type_name())
752 ),
753 }
754}
755
756/// Renders one [`Value`] in full.
757fn encode_value(value: &Value) -> String {
758 let opaque = |value: &Value| {
759 format!(
760 "{{\"type\":\"opaque\",\"of\":{},\"shown\":{}}}",
761 json_string(&value.type_name()),
762 json_string(&value.to_string())
763 )
764 };
765 match value {
766 Value(Repr::Unit) => "{\"type\":\"unit\"}".to_string(),
767 Value(Repr::Bool(b)) => format!("{{\"type\":\"bool\",\"value\":{b}}}"),
768 Value(Repr::Int(i)) => format!("{{\"type\":\"int\",\"value\":{i}}}"),
769 // JSON has no way to write an infinity or a NaN, so a float that is
770 // not finite is recorded as what it printed rather than as a number
771 // no reader could parse back.
772 Value(Repr::Float(x)) if x.is_finite() => format!("{{\"type\":\"float\",\"value\":{x:?}}}"),
773 Value(Repr::Duration(ns)) => format!("{{\"type\":\"duration\",\"ns\":{ns}}}"),
774 Value(Repr::Str(s)) => format!("{{\"type\":\"string\",\"value\":{}}}", json_string(s)),
775 // A handle is a name, so recording it whole is recording the name:
776 // that is exactly what a replay needs in order to hand the same
777 // resource back and match the calls later made on it.
778 Value(Repr::Resource(handle)) => format!(
779 "{{\"type\":\"resource\",\"name\":{},\"id\":{}}}",
780 json_string(&handle.qualified_type()),
781 handle.id
782 ),
783 Value(Repr::Array(items)) => {
784 let items = items.iter().map(encode_value).collect::<Vec<_>>().join(",");
785 format!("{{\"type\":\"array\",\"items\":[{items}]}}")
786 }
787 Value(Repr::Enum(value)) => {
788 let payload = value
789 .payload
790 .iter()
791 .map(encode_value)
792 .collect::<Vec<_>>()
793 .join(",");
794 format!(
795 "{{\"type\":\"enum\",\"name\":{},\"case\":{},\"payload\":[{payload}]}}",
796 json_string(&value.type_name),
797 json_string(&value.case)
798 )
799 }
800 Value(Repr::Struct(value)) => {
801 let fields = value
802 .fields
803 .iter()
804 .map(|(name, field)| {
805 format!(
806 "{{\"name\":{},\"value\":{}}}",
807 json_string(name),
808 encode_value(field)
809 )
810 })
811 .collect::<Vec<_>>()
812 .join(",");
813 format!(
814 "{{\"type\":\"struct\",\"name\":{},\"fields\":[{fields}]}}",
815 json_string(&value.type_name)
816 )
817 }
818 other => opaque(other),
819 }
820}
821
822/// Renders one [`RecordedValue`], honouring `capture`.
823///
824/// A carried value is rebuilt before it is written: that is the far side of
825/// the boundary the event crossed, and rebuilding it is the same copy the
826/// rule already demands. What it produces is one [`Value`] again, so the
827/// encoding below is the one encoding, whichever side of a boundary a value
828/// reached it from.
829fn recorded_to_json(recorded: &RecordedValue, capture: ValueCapture) -> String {
830 match recorded {
831 RecordedValue::Carried(transfer) => value_to_json(&transfer.clone().into_value(), capture),
832 RecordedValue::Opaque { of, shown } => match capture {
833 ValueCapture::Full => format!(
834 "{{\"type\":\"opaque\",\"of\":{},\"shown\":{}}}",
835 json_string(of),
836 json_string(shown)
837 ),
838 ValueCapture::Redacted => {
839 format!("{{\"type\":\"redacted\",\"of\":{}}}", json_string(of))
840 }
841 },
842 }
843}
844
845/// Renders one [`HostOutcome`], or `null` when a call never reached a host.
846fn encode_outcome(outcome: Option<&HostOutcome>, capture: ValueCapture) -> String {
847 match outcome {
848 None => "null".to_string(),
849 Some(HostOutcome::Value(value)) => format!(
850 "{{\"kind\":\"value\",\"value\":{}}}",
851 recorded_to_json(value, capture)
852 ),
853 // A runtime error is the host refusing, not data the host holds, so
854 // it stays readable even in a redacted trace.
855 Some(HostOutcome::Error(message)) => format!(
856 "{{\"kind\":\"error\",\"message\":{}}}",
857 json_string(message)
858 ),
859 Some(HostOutcome::NotRecordable) => "{\"kind\":\"not_recordable\"}".to_string(),
860 }
861}
862
863/// Renders one [`TraceEvent`] as the single JSON line documented on this
864/// module.
865fn to_json_line(event: &TraceEvent, capture: ValueCapture) -> String {
866 match event {
867 TraceEvent::TaskSpawned { id, parent, scope } => {
868 let parent = match parent {
869 Some(id) => id.to_string(),
870 None => "null".to_string(),
871 };
872 format!(
873 "{{\"event\":\"task_spawned\",\"id\":{id},\"parent\":{parent},\"scope\":{}}}",
874 json_string(scope)
875 )
876 }
877 TraceEvent::TaskCompleted { id, cpu } => format!(
878 "{{\"event\":\"task_completed\",\"id\":{id},\"cpu_ns\":{}}}",
879 json_ns(*cpu)
880 ),
881 TraceEvent::TaskCancelled { id } => {
882 format!("{{\"event\":\"task_cancelled\",\"id\":{id}}}")
883 }
884 TraceEvent::HostCall {
885 task,
886 module,
887 op,
888 capability,
889 wait,
890 granted,
891 args,
892 outcome,
893 } => {
894 let args = args
895 .iter()
896 .map(|arg| recorded_to_json(arg, capture))
897 .collect::<Vec<_>>()
898 .join(",");
899 format!(
900 "{{\"event\":\"host_call\",\"task\":{task},\"module\":{},\"op\":{},\"capability\":{},\"wait_ns\":{},\"granted\":{granted},\"args\":[{args}],\"outcome\":{}}}",
901 json_string(module),
902 json_string(op),
903 json_string(capability),
904 json_ns(*wait),
905 encode_outcome(outcome.as_ref(), capture),
906 )
907 }
908 TraceEvent::HeapCollected {
909 task,
910 allocated,
911 freed,
912 live_objects,
913 live_bytes,
914 pause,
915 } => {
916 format!(
917 "{{\"event\":\"heap_collected\",\"task\":{task},\"allocated\":{allocated},\"freed\":{freed},\"live_objects\":{live_objects},\"live_bytes\":{live_bytes},\"pause_ns\":{}}}",
918 json_ns(*pause)
919 )
920 }
921 TraceEvent::HeapSummary {
922 collections,
923 object_count,
924 allocated_bytes,
925 live_bytes,
926 peak_bytes,
927 pause,
928 allocated_words,
929 capacity_words,
930 live_words,
931 } => format!(
932 "{{\"event\":\"heap_summary\",\"collections\":{collections},\"object_count\":{},\"allocated_bytes\":{},\"live_bytes\":{},\"peak_bytes\":{},\"pause_ns\":{},\"allocated_words\":{},\"capacity_words\":{},\"live_words\":{}}}",
933 json_measure(*object_count),
934 json_measure(*allocated_bytes),
935 json_measure(*live_bytes),
936 json_measure(*peak_bytes),
937 json_measure(pause.map(json_ns)),
938 json_measure(*allocated_words),
939 json_measure(*capacity_words),
940 json_measure(*live_words),
941 ),
942 TraceEvent::EntryEnter { module, function } => format!(
943 "{{\"event\":\"entry_enter\",\"module\":{},\"function\":{}}}",
944 json_string(module),
945 json_string(function)
946 ),
947 TraceEvent::EntryExit {
948 module,
949 function,
950 cpu,
951 wait,
952 } => format!(
953 "{{\"event\":\"entry_exit\",\"module\":{},\"function\":{},\"cpu_ns\":{},\"wait_ns\":{}}}",
954 json_string(module),
955 json_string(function),
956 json_ns(*cpu),
957 json_ns(*wait),
958 ),
959 TraceEvent::RunEnded { outcome, message } => format!(
960 "{{\"event\":\"run_ended\",\"outcome\":{},\"message\":{}}}",
961 json_string(outcome.as_str()),
962 encode_run_message(*outcome, message.as_deref(), capture),
963 ),
964 }
965}
966
967/// Renders the message a run ended with, honouring `capture`.
968///
969/// The runtime's own sentence about its own limit is kept in both modes, for
970/// the same reason a host's refusal is: it is why the run stopped, not data
971/// the run read. The `Error` a program *returned* is a value the program
972/// built, and a redacted trace carries no values it built — so it is dropped
973/// rather than shown, which leaves the classification, which is the part a
974/// reader groups by.
975fn encode_run_message(outcome: RunOutcome, message: Option<&str>, capture: ValueCapture) -> String {
976 match message {
977 Some(_) if capture == ValueCapture::Redacted && outcome.is_the_program_s_own() => {
978 "null".to_string()
979 }
980 Some(message) => json_string(message),
981 None => "null".to_string(),
982 }
983}
984
985/// Accumulates wait time separately from total elapsed time, so a caller can
986/// report CPU as `elapsed - wait`.
987///
988/// "CPU" here means "not waiting": neither on a host call nor for a task to
989/// finish. Each task thread keeps its own timing, so with ADR 0008's thread
990/// per task the separation is a concurrency measurement — one task's CPU work
991/// and another's wait are recorded against different contexts and can overlap
992/// in wall-clock time, which is what ADR 0001 asks a trace to make
993/// attributable. It is also why the two no longer sum to the run's elapsed
994/// time: several tasks can be waiting at once.
995pub struct Timing {
996 started_at: Instant,
997 wait: Duration,
998}
999
1000impl Timing {
1001 /// Starts timing now.
1002 pub fn start() -> Self {
1003 Timing {
1004 started_at: Instant::now(),
1005 wait: Duration::ZERO,
1006 }
1007 }
1008
1009 /// Records `wait` as time spent waiting on a host call.
1010 pub fn add_wait(&mut self, wait: Duration) {
1011 self.wait += wait;
1012 }
1013
1014 /// Total wait time recorded so far.
1015 pub fn wait(&self) -> Duration {
1016 self.wait
1017 }
1018
1019 /// Total time elapsed since [`Timing::start`].
1020 pub fn elapsed(&self) -> Duration {
1021 self.started_at.elapsed()
1022 }
1023
1024 /// `elapsed() - wait()`: time spent doing anything other than waiting on
1025 /// a host call.
1026 pub fn cpu(&self) -> Duration {
1027 self.elapsed().saturating_sub(self.wait)
1028 }
1029}
1030
1031#[cfg(test)]
1032mod tests {
1033 use super::*;
1034 use std::rc::Rc;
1035
1036 struct Buffer(Vec<u8>);
1037
1038 impl Write for Buffer {
1039 fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
1040 self.0.write(buf)
1041 }
1042 fn flush(&mut self) -> std::io::Result<()> {
1043 Ok(())
1044 }
1045 }
1046
1047 fn header(values: ValueCapture) -> TraceHeader {
1048 TraceHeader {
1049 backend: RecordingBackend::Vm,
1050 values,
1051 entry: "hello.main".to_string(),
1052 args: Vec::new(),
1053 }
1054 }
1055
1056 /// Records `event` and returns the lines after the header.
1057 fn record_with(values: ValueCapture, event: TraceEvent) -> String {
1058 let sink = JsonlSink::new(Buffer(Vec::new()), header(values));
1059 sink.record(event);
1060 let text = String::from_utf8(sink.writer.into_inner().unwrap().0).unwrap();
1061 assert!(text.ends_with('\n'), "line should end with a newline");
1062 let mut lines = text.trim_end_matches('\n').split('\n');
1063 lines.next().expect("the header line");
1064 lines.collect::<Vec<_>>().join("\n")
1065 }
1066
1067 fn record_one(event: TraceEvent) -> String {
1068 record_with(ValueCapture::Full, event)
1069 }
1070
1071 /// A recorded value, written the way a host call's argument arrives:
1072 /// as the value itself.
1073 fn recorded(value: Value) -> RecordedValue {
1074 RecordedValue::of(&value)
1075 }
1076
1077 /// The recorded form of a host's answer.
1078 fn answered(value: Value) -> Option<HostOutcome> {
1079 Some(HostOutcome::Value(recorded(value)))
1080 }
1081
1082 fn host_call(args: Vec<Value>, outcome: Option<HostOutcome>) -> TraceEvent {
1083 TraceEvent::HostCall {
1084 task: crate::runtime::ENTRY_TASK,
1085 module: "documents".to_string(),
1086 op: "read".to_string(),
1087 capability: "documents".to_string(),
1088 wait: Duration::from_nanos(900),
1089 granted: true,
1090 args: args.into_iter().map(recorded).collect(),
1091 outcome,
1092 }
1093 }
1094
1095 #[test]
1096 fn the_first_line_declares_the_version_the_backend_the_mode_the_entry_and_the_arguments() {
1097 let sink = JsonlSink::new(
1098 Buffer(Vec::new()),
1099 TraceHeader {
1100 backend: RecordingBackend::Vm,
1101 values: ValueCapture::Full,
1102 entry: "restricted.main".to_string(),
1103 args: vec!["one".to_string(), "two".to_string()],
1104 },
1105 );
1106 assert_eq!(
1107 String::from_utf8(sink.writer.into_inner().unwrap().0).unwrap(),
1108 "{\"event\":\"trace_header\",\"version\":4,\"backend\":\"vm\",\"values\":\"full\",\"entry\":\"restricted.main\",\"args\":[\"one\",\"two\"]}\n"
1109 );
1110 }
1111
1112 /// The other backend, written the same way.
1113 ///
1114 /// ADR 0026's point is that the field distinguishes two recordings, so a
1115 /// test that only ever saw one of the two names would not be testing the
1116 /// distinction. The oracle is the half that has to be asked for on the
1117 /// command line, and it is the half worth pinning here.
1118 #[test]
1119 fn a_recording_made_on_the_oracle_says_so_in_its_header() {
1120 let sink = JsonlSink::new(
1121 Buffer(Vec::new()),
1122 TraceHeader {
1123 backend: RecordingBackend::Ast,
1124 values: ValueCapture::Full,
1125 entry: "restricted.main".to_string(),
1126 args: Vec::new(),
1127 },
1128 );
1129 assert_eq!(
1130 String::from_utf8(sink.writer.into_inner().unwrap().0).unwrap(),
1131 "{\"event\":\"trace_header\",\"version\":4,\"backend\":\"ast\",\"values\":\"full\",\"entry\":\"restricted.main\",\"args\":[]}\n"
1132 );
1133 }
1134
1135 /// Every spelling a header writes is one `--backend` accepts, and each
1136 /// parses back to what wrote it.
1137 #[test]
1138 fn a_recording_backend_round_trips_through_its_name() {
1139 for backend in [RecordingBackend::Ast, RecordingBackend::Vm] {
1140 assert_eq!(RecordingBackend::parse(backend.as_str()), Some(backend));
1141 }
1142 assert_eq!(RecordingBackend::parse("jit"), None);
1143 }
1144
1145 #[test]
1146 fn the_header_names_the_redacted_mode_when_that_is_what_was_asked_for() {
1147 let sink = JsonlSink::new(Buffer(Vec::new()), header(ValueCapture::Redacted));
1148 let text = String::from_utf8(sink.writer.into_inner().unwrap().0).unwrap();
1149 assert!(text.contains("\"values\":\"redacted\""), "{text}");
1150 }
1151
1152 #[test]
1153 fn task_spawned_with_a_parent() {
1154 assert_eq!(
1155 record_one(TraceEvent::TaskSpawned {
1156 id: 2,
1157 parent: Some(1),
1158 scope: "worker".to_string(),
1159 }),
1160 r#"{"event":"task_spawned","id":2,"parent":1,"scope":"worker"}"#
1161 );
1162 }
1163
1164 #[test]
1165 fn task_spawned_without_a_parent() {
1166 assert_eq!(
1167 record_one(TraceEvent::TaskSpawned {
1168 id: 1,
1169 parent: None,
1170 scope: "main".to_string(),
1171 }),
1172 r#"{"event":"task_spawned","id":1,"parent":null,"scope":"main"}"#
1173 );
1174 }
1175
1176 #[test]
1177 fn task_completed() {
1178 assert_eq!(
1179 record_one(TraceEvent::TaskCompleted {
1180 id: 1,
1181 cpu: Duration::from_micros(2),
1182 }),
1183 r#"{"event":"task_completed","id":1,"cpu_ns":2000}"#
1184 );
1185 }
1186
1187 #[test]
1188 fn task_cancelled() {
1189 assert_eq!(
1190 record_one(TraceEvent::TaskCancelled { id: 3 }),
1191 r#"{"event":"task_cancelled","id":3}"#
1192 );
1193 }
1194
1195 #[test]
1196 fn a_granted_call_records_its_arguments_and_its_result() {
1197 assert_eq!(
1198 record_one(host_call(
1199 vec![Value(Repr::Str("input".into()))],
1200 answered(Value::ok(Value(Repr::Str("text".into())))),
1201 )),
1202 r#"{"event":"host_call","task":0,"module":"documents","op":"read","capability":"documents","wait_ns":900,"granted":true,"args":[{"type":"string","value":"input"}],"outcome":{"kind":"value","value":{"type":"enum","name":"Result","case":"Ok","payload":[{"type":"string","value":"text"}]}}}"#
1203 );
1204 }
1205
1206 #[test]
1207 fn a_call_that_never_reached_a_host_records_no_outcome() {
1208 assert_eq!(
1209 record_one(TraceEvent::HostCall {
1210 task: 3,
1211 module: "network".to_string(),
1212 op: "fetch".to_string(),
1213 capability: "network".to_string(),
1214 wait: Duration::ZERO,
1215 granted: false,
1216 args: vec![recorded(Value(Repr::Str("https://example.test".into())))],
1217 outcome: None,
1218 }),
1219 r#"{"event":"host_call","task":3,"module":"network","op":"fetch","capability":"network","wait_ns":0,"granted":false,"args":[{"type":"string","value":"https://example.test"}],"outcome":null}"#
1220 );
1221 }
1222
1223 /// The `recordable` flag decides, and `process.exit` is the operation it
1224 /// decides against: a replay that handed its result back would keep
1225 /// running a program that had ended.
1226 #[test]
1227 fn an_operation_that_is_not_recordable_records_that_instead_of_a_result() {
1228 assert_eq!(
1229 record_one(host_call(Vec::new(), Some(HostOutcome::NotRecordable))),
1230 r#"{"event":"host_call","task":0,"module":"documents","op":"read","capability":"documents","wait_ns":900,"granted":true,"args":[],"outcome":{"kind":"not_recordable"}}"#
1231 );
1232 }
1233
1234 #[test]
1235 fn a_host_that_refused_records_the_runtime_error_it_refused_with() {
1236 assert_eq!(
1237 record_one(host_call(
1238 Vec::new(),
1239 Some(HostOutcome::Error("no such host".to_string())),
1240 )),
1241 r#"{"event":"host_call","task":0,"module":"documents","op":"read","capability":"documents","wait_ns":900,"granted":true,"args":[],"outcome":{"kind":"error","message":"no such host"}}"#
1242 );
1243 }
1244
1245 /// A redacted trace is the one to share: it says a call happened, with
1246 /// what kinds of values, and nothing about their contents.
1247 #[test]
1248 fn redacted_capture_replaces_every_argument_and_result_with_its_type() {
1249 assert_eq!(
1250 record_with(
1251 ValueCapture::Redacted,
1252 host_call(
1253 vec![Value(Repr::Str("PASSWORD".into()))],
1254 answered(Value::some(Value(Repr::Str("hunter2".into())))),
1255 )
1256 ),
1257 r#"{"event":"host_call","task":0,"module":"documents","op":"read","capability":"documents","wait_ns":900,"granted":true,"args":[{"type":"redacted","of":"String"}],"outcome":{"kind":"value","value":{"type":"redacted","of":"Option"}}}"#
1258 );
1259 }
1260
1261 /// Redaction replaces the whole value rather than its leaves: a redacted
1262 /// struct that kept its shape would still describe the secret.
1263 #[test]
1264 fn redaction_does_not_leave_the_shape_of_what_it_hid() {
1265 let text = record_with(
1266 ValueCapture::Redacted,
1267 host_call(
1268 vec![Value(Repr::Struct(Rc::new(crate::value::StructValue {
1269 type_name: "Credentials".into(),
1270 fields: vec![("token".into(), Value(Repr::Str("hunter2".into())))],
1271 opaque: false,
1272 })))],
1273 None,
1274 ),
1275 );
1276 assert!(
1277 text.contains(r#""args":[{"type":"redacted","of":"Credentials"}]"#),
1278 "{text}"
1279 );
1280 assert!(!text.contains("token"), "{text}");
1281 assert!(!text.contains("hunter2"), "{text}");
1282 }
1283
1284 #[test]
1285 fn every_value_shape_that_crosses_the_boundary_has_an_encoding() {
1286 let encoded = |value: Value| encode_value(&value);
1287 assert_eq!(encoded(Value(Repr::Unit)), r#"{"type":"unit"}"#);
1288 assert_eq!(
1289 encoded(Value(Repr::Bool(true))),
1290 r#"{"type":"bool","value":true}"#
1291 );
1292 assert_eq!(
1293 encoded(Value(Repr::Int(-7))),
1294 r#"{"type":"int","value":-7}"#
1295 );
1296 assert_eq!(
1297 encoded(Value(Repr::Float(1.5))),
1298 r#"{"type":"float","value":1.5}"#
1299 );
1300 assert_eq!(
1301 encoded(Value(Repr::Duration(1_000))),
1302 r#"{"type":"duration","ns":1000}"#
1303 );
1304 assert_eq!(
1305 encoded(Value(Repr::Str("hi".into()))),
1306 r#"{"type":"string","value":"hi"}"#
1307 );
1308 assert_eq!(
1309 encoded(Value(Repr::Array(
1310 vec![Value(Repr::Int(1)), Value(Repr::Int(2))].into()
1311 ))),
1312 r#"{"type":"array","items":[{"type":"int","value":1},{"type":"int","value":2}]}"#
1313 );
1314 assert_eq!(
1315 encoded(Value::none()),
1316 r#"{"type":"enum","name":"Option","case":"None","payload":[]}"#
1317 );
1318 assert_eq!(
1319 encoded(Value::error("broken")),
1320 r#"{"type":"struct","name":"Error","fields":[{"name":"message","value":{"type":"string","value":"broken"}}]}"#
1321 );
1322 }
1323
1324 /// A value that may not cross a task boundary is recorded as what it was
1325 /// and what it printed as, which is the same `opaque` the encoding
1326 /// already writes for it — so a trace says the same thing whether the
1327 /// call was made by the entry or by a task.
1328 #[test]
1329 fn a_value_that_may_not_cross_a_boundary_is_recorded_as_opaque() {
1330 let vector = Value(Repr::Vector(crate::value::VectorStorage::new(vec![Value(
1331 Repr::Int(1),
1332 )])));
1333 let recorded = RecordedValue::of(&vector);
1334 assert!(
1335 matches!(&recorded, RecordedValue::Opaque { of, shown } if of == "Vector" && shown == "[1]")
1336 );
1337 assert_eq!(
1338 recorded_to_json(&recorded, ValueCapture::Full),
1339 r#"{"type":"opaque","of":"Vector","shown":"[1]"}"#
1340 );
1341 assert_eq!(
1342 recorded_to_json(&recorded, ValueCapture::Redacted),
1343 r#"{"type":"redacted","of":"Vector"}"#
1344 );
1345 }
1346
1347 /// A value that may cross is carried whole, and rebuilding it on the
1348 /// writing side produces the encoding it would have had all along.
1349 #[test]
1350 fn a_value_that_may_cross_a_boundary_is_carried_whole() {
1351 let recorded = RecordedValue::of(&Value::ok(Value(Repr::Str("text".into()))));
1352 assert!(matches!(recorded, RecordedValue::Carried(_)));
1353 assert_eq!(
1354 recorded_to_json(&recorded, ValueCapture::Full),
1355 r#"{"type":"enum","name":"Result","case":"Ok","payload":[{"type":"string","value":"text"}]}"#
1356 );
1357 }
1358
1359 /// A value the encoding cannot represent leaves a readable marker behind
1360 /// rather than a number no reader could parse or a silently dropped
1361 /// argument.
1362 #[test]
1363 fn a_value_the_encoding_cannot_represent_is_recorded_as_opaque() {
1364 assert_eq!(
1365 encode_value(&Value(Repr::Vector(crate::value::VectorStorage::new(
1366 vec![Value(Repr::Int(1))]
1367 )))),
1368 r#"{"type":"opaque","of":"Vector","shown":"[1]"}"#
1369 );
1370 assert_eq!(
1371 encode_value(&Value(Repr::Float(f64::INFINITY))),
1372 r#"{"type":"opaque","of":"Float","shown":"inf"}"#
1373 );
1374 }
1375
1376 #[test]
1377 fn entry_enter() {
1378 assert_eq!(
1379 record_one(TraceEvent::EntryEnter {
1380 module: "hello".to_string(),
1381 function: "main".to_string(),
1382 }),
1383 r#"{"event":"entry_enter","module":"hello","function":"main"}"#
1384 );
1385 }
1386
1387 #[test]
1388 fn heap_collected() {
1389 assert_eq!(
1390 record_one(TraceEvent::HeapCollected {
1391 task: 2,
1392 allocated: 64,
1393 freed: 60,
1394 live_objects: 4,
1395 live_bytes: 512,
1396 pause: Duration::from_micros(9),
1397 }),
1398 r#"{"event":"heap_collected","task":2,"allocated":64,"freed":60,"live_objects":4,"live_bytes":512,"pause_ns":9000}"#
1399 );
1400 }
1401
1402 /// A call the entry made and a call a task made are told apart by the one
1403 /// field that says so, which is what makes a concurrent trace groupable.
1404 #[test]
1405 fn a_host_call_names_the_task_that_made_it() {
1406 let entry = record_one(host_call(Vec::new(), None));
1407 assert!(entry.contains(r#""event":"host_call","task":0"#), "{entry}");
1408 let spawned = record_one(TraceEvent::HostCall {
1409 task: 7,
1410 module: "console".to_string(),
1411 op: "println".to_string(),
1412 capability: "console".to_string(),
1413 wait: Duration::ZERO,
1414 granted: true,
1415 args: Vec::new(),
1416 outcome: None,
1417 });
1418 assert!(
1419 spawned.contains(r#""event":"host_call","task":7"#),
1420 "{spawned}"
1421 );
1422 }
1423
1424 #[test]
1425 fn heap_collected_for_the_entry_names_the_entry_s_task() {
1426 assert_eq!(
1427 record_one(TraceEvent::HeapCollected {
1428 task: crate::runtime::ENTRY_TASK,
1429 allocated: 1,
1430 freed: 0,
1431 live_objects: 1,
1432 live_bytes: 8,
1433 pause: Duration::ZERO,
1434 }),
1435 r#"{"event":"heap_collected","task":0,"allocated":1,"freed":0,"live_objects":1,"live_bytes":8,"pause_ns":0}"#
1436 );
1437 }
1438
1439 /// The object half of the event, from a machine that counts objects.
1440 #[test]
1441 fn heap_summary_of_a_heap_of_objects() {
1442 assert_eq!(
1443 record_one(TraceEvent::HeapSummary {
1444 collections: 2,
1445 object_count: Some(128),
1446 allocated_bytes: Some(4096),
1447 live_bytes: Some(96),
1448 peak_bytes: Some(1024),
1449 pause: Some(Duration::from_micros(31)),
1450 allocated_words: None,
1451 capacity_words: None,
1452 live_words: None,
1453 }),
1454 r#"{"event":"heap_summary","collections":2,"object_count":128,"allocated_bytes":4096,"live_bytes":96,"peak_bytes":1024,"pause_ns":31000,"allocated_words":null,"capacity_words":null,"live_words":null}"#
1455 );
1456 }
1457
1458 /// The word half, from a machine that counts words — and the shape issue
1459 /// #240 asked for, which is that neither half is forced into the other's
1460 /// units and an uncounted figure is `null` rather than nought.
1461 #[test]
1462 fn heap_summary_of_a_heap_of_words() {
1463 assert_eq!(
1464 record_one(TraceEvent::HeapSummary {
1465 collections: 1,
1466 object_count: None,
1467 allocated_bytes: None,
1468 live_bytes: None,
1469 peak_bytes: None,
1470 pause: None,
1471 allocated_words: Some(512),
1472 capacity_words: Some(4096),
1473 live_words: Some(96),
1474 }),
1475 r#"{"event":"heap_summary","collections":1,"object_count":null,"allocated_bytes":null,"live_bytes":null,"peak_bytes":null,"pause_ns":null,"allocated_words":512,"capacity_words":4096,"live_words":96}"#
1476 );
1477 }
1478
1479 #[test]
1480 fn entry_exit() {
1481 assert_eq!(
1482 record_one(TraceEvent::EntryExit {
1483 module: "hello".to_string(),
1484 function: "main".to_string(),
1485 cpu: Duration::from_nanos(1200),
1486 wait: Duration::from_nanos(300),
1487 }),
1488 r#"{"event":"entry_exit","module":"hello","function":"main","cpu_ns":1200,"wait_ns":300}"#
1489 );
1490 }
1491
1492 #[test]
1493 fn a_run_that_succeeded_ends_with_that_and_no_message() {
1494 assert_eq!(
1495 record_one(TraceEvent::RunEnded {
1496 outcome: RunOutcome::Success,
1497 message: None,
1498 }),
1499 r#"{"event":"run_ended","outcome":"success","message":null}"#
1500 );
1501 }
1502
1503 #[test]
1504 fn a_run_whose_entry_returned_an_error_ends_with_that_error() {
1505 assert_eq!(
1506 record_one(TraceEvent::RunEnded {
1507 outcome: RunOutcome::Error,
1508 message: Some("no such document".to_string()),
1509 }),
1510 r#"{"event":"run_ended","outcome":"error","message":"no such document"}"#
1511 );
1512 }
1513
1514 #[test]
1515 fn a_run_a_limit_stopped_ends_naming_the_limit_and_what_it_said() {
1516 assert_eq!(
1517 record_one(TraceEvent::RunEnded {
1518 outcome: RunOutcome::Deadline,
1519 message: Some("execution stopped: wall-clock deadline of 1ms exceeded".to_string()),
1520 }),
1521 r#"{"event":"run_ended","outcome":"deadline","message":"execution stopped: wall-clock deadline of 1ms exceeded"}"#
1522 );
1523 }
1524
1525 /// Every classification has a name, and every name reads back as the
1526 /// classification it was written for: a trace consumer groups runs by
1527 /// these strings, so they are as much of the format as the keys are.
1528 #[test]
1529 fn every_run_outcome_has_a_name_that_round_trips() {
1530 let all = [
1531 (RunOutcome::Success, "success"),
1532 (RunOutcome::Error, "error"),
1533 (RunOutcome::Invariant, "invariant"),
1534 (RunOutcome::HostBoundary, "host_boundary"),
1535 (RunOutcome::Fuel, "fuel"),
1536 (RunOutcome::Deadline, "deadline"),
1537 (RunOutcome::Cancelled, "cancelled"),
1538 (RunOutcome::CallDepth, "call_depth"),
1539 (RunOutcome::HostCalls, "host_calls"),
1540 (RunOutcome::Concurrency, "concurrency"),
1541 (RunOutcome::Debugger, "debugger"),
1542 ];
1543 for (outcome, name) in all {
1544 assert_eq!(outcome.as_str(), name);
1545 assert_eq!(RunOutcome::parse(name), Some(outcome));
1546 }
1547 assert_eq!(RunOutcome::parse("stopped"), None);
1548 }
1549
1550 /// A redacted trace carries no value the program built, and the `Error` a
1551 /// program returned is one — while the runtime's own sentence about its
1552 /// own limit is not, so that one stays.
1553 #[test]
1554 fn a_redacted_trace_drops_a_returned_error_and_keeps_a_limit_s_own_words() {
1555 assert_eq!(
1556 record_with(
1557 ValueCapture::Redacted,
1558 TraceEvent::RunEnded {
1559 outcome: RunOutcome::Error,
1560 message: Some("the token was hunter2".to_string()),
1561 }
1562 ),
1563 r#"{"event":"run_ended","outcome":"error","message":null}"#
1564 );
1565 assert_eq!(
1566 record_with(
1567 ValueCapture::Redacted,
1568 TraceEvent::RunEnded {
1569 outcome: RunOutcome::Fuel,
1570 message: Some("execution stopped: fuel budget of 10 exhausted".to_string()),
1571 }
1572 ),
1573 r#"{"event":"run_ended","outcome":"fuel","message":"execution stopped: fuel budget of 10 exhausted"}"#
1574 );
1575 }
1576
1577 #[test]
1578 fn strings_needing_escaping_are_escaped() {
1579 assert_eq!(
1580 record_one(TraceEvent::EntryEnter {
1581 module: "weird\"name\\with\nnewline\tand\rcontrol".to_string(),
1582 function: "f".to_string(),
1583 }),
1584 r#"{"event":"entry_enter","module":"weird\"name\\with\nnewline\tand\rcontrol","function":"f"}"#
1585 );
1586 }
1587
1588 #[test]
1589 fn control_character_outside_the_named_escapes_uses_a_unicode_escape() {
1590 assert_eq!(
1591 record_one(TraceEvent::EntryEnter {
1592 module: "bell\u{7}".to_string(),
1593 function: "f".to_string(),
1594 }),
1595 "{\"event\":\"entry_enter\",\"module\":\"bell\\u0007\",\"function\":\"f\"}"
1596 );
1597 }
1598
1599 #[test]
1600 fn value_capture_names_round_trip() {
1601 for mode in [ValueCapture::Full, ValueCapture::Redacted] {
1602 assert_eq!(ValueCapture::parse(mode.as_str()), Some(mode));
1603 }
1604 assert_eq!(ValueCapture::parse("some"), None);
1605 }
1606
1607 #[test]
1608 fn null_sink_records_nothing_observable() {
1609 let sink = NullSink;
1610 sink.record(TraceEvent::TaskCancelled { id: 1 });
1611 // No assertion beyond "does not panic": NullSink has no observable
1612 // state.
1613 }
1614
1615 #[test]
1616 fn timing_reports_cpu_as_elapsed_minus_wait() {
1617 let mut timing = Timing::start();
1618 std::thread::sleep(Duration::from_millis(5));
1619 timing.add_wait(Duration::from_millis(2));
1620 assert_eq!(timing.wait(), Duration::from_millis(2));
1621 assert!(timing.elapsed() >= Duration::from_millis(5));
1622 // `elapsed()` (and so `cpu()`) advances every time it is called, so
1623 // assert the relationship each captures rather than comparing two
1624 // separate calls for equality.
1625 assert!(timing.cpu() >= Duration::from_millis(3));
1626 assert!(timing.cpu() <= timing.elapsed());
1627 }
1628}