detcore/
guest_log.rs

1/*
2 * Copyright (c) Meta Platforms, Inc. and affiliates.
3 * All rights reserved.
4 *
5 * This source code is licensed under the BSD-style license found in the
6 * LICENSE file in the root directory of this source tree.
7 */
8
9//! Detcore's warnings from inside the guest, printed by the coordinator.
10//!
11//! WHY THIS IS NEEDED. Where Detcore runs in the guest's own process (DBT,
12//! SaBRe, in-guest LiteInst and in-guest-trap), nothing printed its `tracing`
13//! events: a warning that ptrace and KVM print at the default level was lost.
14//!
15//! One mechanism serves every such runtime. The runtime installs [`subscriber`]
16//! with the one synchronous coordinator request it already has for Tool
17//! callbacks (the one shared open file control uses). The subscriber sends each
18//! WARN and ERROR event as one `GlobalRequest::GuestLog`, and the coordinator
19//! emits it again with the event's own level and target (`emit`). So the
20//! run's own filter decides, per target, exactly as it does for ptrace's
21//! events, and the line reads as ptrace's does, without span context.
22//!
23//! WHY ONLY WARN AND ERROR. Verification compares every INFO record, and a
24//! guest record printed when it arrives would land at a host-timed place
25//! among the run's ordered records. Warnings and errors are not compared, and
26//! they are what a default run prints. DETLOG records, which are INFO or
27//! DEBUG, keep their own ordered and counted channels ([`crate::detlog`](mod@crate::detlog), or
28//! the runtime's own, [`OwnChannel`]).
29//!
30//! A runtime with its own channel ([`OwnChannel`]) runs it at the run's own
31//! level, so it sends nothing: its channel already has every event the run
32//! prints.
33//!
34//! An event that cannot be sent (outside a Tool callback, while another
35//! request of the process is in flight, or from inside the send itself) is
36//! counted, per address space. The next request that gets through carries the
37//! count, which the coordinator prints as a warning; Detcore also sends any
38//! count still held when a thread exits, at `exit_group`, before an exec
39//! (`prepare_exec`, every exec path), before an injected `exit_group` and at
40//! an unrecoverable shutdown (`flush_unsent`), and last in each thread's exit
41//! hook, through the hook's own connection (`flush_unsent_through`). A
42//! process killed where its runtime runs no exit hook, or a warning after its
43//! last such point, leaves a count that cannot be reported. (DBT with no coordinator prints its warnings on its own
44//! diagnostic channel instead.) Nothing is written to
45//! the guest's own descriptors, and formatting uses only Rust's allocator (see
46//! `detcore/clippy.toml` for the C library calls that would use the guest's
47//! heap).
48
49use std::collections::BTreeMap;
50use std::fmt::Write as _;
51use std::io;
52use std::sync::Mutex;
53use std::sync::OnceLock;
54use std::sync::atomic::AtomicBool;
55use std::sync::atomic::AtomicU64;
56use std::sync::atomic::Ordering;
57
58use serde::Deserialize;
59use serde::Serialize;
60use tracing::Event;
61use tracing::Level;
62use tracing::Metadata;
63use tracing::Subscriber;
64use tracing::callsite::Callsite;
65use tracing::field::Field;
66use tracing::field::FieldSet;
67use tracing::field::Value;
68use tracing::field::Visit;
69use tracing::level_filters::LevelFilter;
70use tracing::metadata::Kind;
71use tracing::span;
72use tracing::subscriber::Interest;
73
74/// One Detcore event from inside the guest.
75#[derive(PartialEq, Eq, Debug, Clone, Serialize, Deserialize)]
76pub struct GuestLogRecord {
77    /// The event's level, as [`level_code`] numbers it.
78    pub level: u8,
79    /// The event's target: the emitting module's path, unless it named one.
80    pub target: String,
81    /// The event's fields as the coordinator's formatter prints them: the
82    /// message, then `name=value` for each other field.
83    pub message: String,
84}
85
86/// An in-guest runtime's one synchronous request to Detcore's global state from
87/// inside a Tool callback: it sends the request and waits for the answer, and
88/// refuses with an error where it cannot send. The runtime's shared open file
89/// transport sends through the same function.
90pub type CoordinatorCall = fn(
91    <crate::GlobalState as reverie::GlobalTool>::Request,
92) -> io::Result<<crate::GlobalState as reverie::GlobalTool>::Response>;
93
94/// A runtime's own channel for its events: DBT's, which carries its DETLOG
95/// records through `tracing` (where other runtimes use [`crate::detlog`](mod@crate::detlog)'s
96/// forwarder), to its protected verification evidence or to its diagnostic
97/// output, at the level the run asked for. It takes every event up to
98/// `max_level`, exactly as the runtime's own subscriber did. A subscriber with
99/// an own channel sends nothing to the coordinator: events above the run's
100/// level are not printed there either.
101#[derive(Clone, Copy)]
102pub struct OwnChannel {
103    /// The most verbose level the channel takes.
104    pub max_level: Level,
105    /// Writes one event to the channel.
106    pub write: fn(&Event<'_>),
107}
108
109/// The most verbose level sent to the coordinator.
110const SENT_LEVEL: Level = Level::WARN;
111
112/// Events of this address space that could not be sent since the last
113/// request that was. A forked child, whose copy of memory holds its parent's
114/// count, starts again at zero ([`starts_new_process`]).
115static UNSENT: AtomicU64 = AtomicU64::new(0);
116/// The address space [`UNSENT`] counts for, once a process's first thread has
117/// started in it; a copy of memory that names another address space is a
118/// forked child's.
119static UNSENT_OWNER: Mutex<Option<crate::types::MmId>> = Mutex::new(None);
120static NEXT_SPAN_ID: AtomicU64 = AtomicU64::new(1);
121
122/// Whether a send is under way in this process, so an event the send itself
123/// emits, or another thread's meanwhile, is counted instead of sent. (The
124/// in-guest coordinator connection takes one request at a time, so another
125/// thread's request would be refused as in flight anyway.) A process-wide flag,
126/// not a thread-local: Detcore's in-guest thread-local layout is pinned by
127/// LiteInst's allocator qualifier, and DynamoRIO's application threads cannot
128/// run thread-local destructors (see `detcore/clippy.toml`).
129static SENDING: AtomicBool = AtomicBool::new(false);
130
131/// The number this module gives `level`: 1 for ERROR up to 5 for TRACE.
132pub fn level_code(level: &Level) -> u8 {
133    match *level {
134        Level::ERROR => 1,
135        Level::WARN => 2,
136        Level::INFO => 3,
137        Level::DEBUG => 4,
138        Level::TRACE => 5,
139    }
140}
141
142fn level_from_code(code: u8) -> Option<Level> {
143    match code {
144        1 => Some(Level::ERROR),
145        2 => Some(Level::WARN),
146        3 => Some(Level::INFO),
147        4 => Some(Level::DEBUG),
148        5 => Some(Level::TRACE),
149        _ => None,
150    }
151}
152
153/// The subscriber an in-guest runtime installs as its global default: it sends
154/// WARN and ERROR events through `call`, and writes every event up to its
155/// level to `own`, when the runtime has one.
156pub fn subscriber(call: CoordinatorCall, own: Option<OwnChannel>) -> impl Subscriber {
157    GuestLogSubscriber { call, own }
158}
159
160/// Installs [`subscriber`] as this process's global default. Returns false,
161/// and changes nothing, when the process already has a global subscriber.
162pub fn install(call: CoordinatorCall, own: Option<OwnChannel>) -> bool {
163    tracing::subscriber::set_global_default(subscriber(call, own)).is_ok()
164}
165
166/// Notes that a process's first thread started in address space `mm`, its
167/// final one (after an exec's). When the count in memory belongs to another
168/// address space, this is a forked child holding its parent's count, which is
169/// not its own, and it starts at zero; the root process's own count stays.
170/// Detcore gives a vfork child its parent's MmId, so it keeps the count; the
171/// in-guest runtimes copy a vfork child's memory, so that child's report can
172/// repeat its parent's count (a duplicate, never a silent loss). An image an
173/// exec-private-init successor starts runs no thread start and keeps the
174/// count it inherited the same way. Detcore calls it when a process's first
175/// thread starts; it acts only under an in-guest runtime's subscriber.
176pub(crate) fn starts_new_process(mm: crate::types::MmId) {
177    // Only an in-guest runtime's process counts unsent warnings.
178    if !tracing::dispatcher::get_default(|dispatch| dispatch.is::<GuestLogSubscriber>()) {
179        return;
180    }
181    let mut owner = UNSENT_OWNER
182        .lock()
183        .unwrap_or_else(|poison| poison.into_inner());
184    if owner.is_some_and(|owner| owner != mm) {
185        UNSENT.store(0, Ordering::Release);
186        // A parent's send under way at the fork is not this child's.
187        SENDING.store(false, Ordering::Release);
188    }
189    *owner = Some(mm);
190}
191
192/// Sends this address space's unsent count, if any, through the installed
193/// subscriber. Detcore calls it where a process may end or replace its image:
194/// at a thread's exit, at `exit_group` and before `execve`. Without an in-guest
195/// subscriber, or with nothing held, it does nothing.
196pub(crate) fn flush_unsent() {
197    if UNSENT.load(Ordering::Acquire) == 0 {
198        return;
199    }
200    tracing::dispatcher::get_default(|dispatch| {
201        if let Some(subscriber) = dispatch.downcast_ref::<GuestLogSubscriber>() {
202            subscriber.send(None);
203        }
204    });
205}
206
207/// Sends this address space's unsent count, if any, through `rpc`: a Tool exit
208/// callback's own connection to the global state. It serves the callback where
209/// the warning path's call cannot (on LiteInst exit callbacks run outside the
210/// runtime's Tool-callback mark), so the hook's own warnings, and every earlier
211/// one still held, are reported. A count the coordinator does not take back is
212/// kept. Without an in-guest subscriber nothing is ever held, so it sends
213/// nothing.
214pub(crate) async fn flush_unsent_through<R>(rpc: &R)
215where
216    R: reverie::GlobalRPC<crate::GlobalState>,
217{
218    let unsent = UNSENT.swap(0, Ordering::AcqRel);
219    if unsent == 0 {
220        return;
221    }
222    let answer = rpc
223        .send_rpc(crate::tool_global::guest_log_request(None, unsent))
224        .await;
225    if crate::tool_global::guest_log_reply(answer).is_err() {
226        UNSENT.fetch_add(unsent, Ordering::AcqRel);
227    }
228}
229
230/// Clears [`SENDING`] when a send ends, unwinding included.
231struct Sending;
232
233impl Drop for Sending {
234    fn drop(&mut self) {
235        SENDING.store(false, Ordering::Release);
236    }
237}
238
239struct GuestLogSubscriber {
240    call: CoordinatorCall,
241    own: Option<OwnChannel>,
242}
243
244impl GuestLogSubscriber {
245    /// Sends one record, or only this process's unsent count, with that count,
246    /// unless a send is already under way. A record that is not sent is
247    /// counted.
248    fn send(&self, record: Option<GuestLogRecord>) {
249        let counts = u64::from(record.is_some());
250        if SENDING.swap(true, Ordering::AcqRel) {
251            UNSENT.fetch_add(counts, Ordering::AcqRel);
252            return;
253        }
254        let _sending = Sending;
255        let unsent = UNSENT.swap(0, Ordering::AcqRel);
256        let sent = (self.call)(crate::tool_global::guest_log_request(record, unsent))
257            .and_then(crate::tool_global::guest_log_reply);
258        if sent.is_err() {
259            UNSENT.fetch_add(unsent + counts, Ordering::AcqRel);
260        }
261    }
262
263    fn own_takes(&self, level: &Level) -> Option<OwnChannel> {
264        self.own.filter(|own| *level <= own.max_level)
265    }
266
267    /// Whether events of `level` are sent: WARN and ERROR, by a runtime with
268    /// no own channel.
269    fn sends(&self, level: &Level) -> bool {
270        self.own.is_none() && *level <= SENT_LEVEL
271    }
272}
273
274impl Subscriber for GuestLogSubscriber {
275    fn max_level_hint(&self) -> Option<LevelFilter> {
276        Some(match self.own {
277            Some(own) => own.max_level.into(),
278            None => SENT_LEVEL.into(),
279        })
280    }
281
282    fn enabled(&self, metadata: &Metadata<'_>) -> bool {
283        self.sends(metadata.level()) || self.own_takes(metadata.level()).is_some()
284    }
285
286    fn new_span(&self, _span: &span::Attributes<'_>) -> span::Id {
287        span::Id::from_u64(NEXT_SPAN_ID.fetch_add(1, Ordering::Relaxed))
288    }
289
290    fn record(&self, _span: &span::Id, _values: &span::Record<'_>) {}
291
292    fn record_follows_from(&self, _span: &span::Id, _follows: &span::Id) {}
293
294    fn event(&self, event: &Event<'_>) {
295        let metadata = event.metadata();
296        if let Some(own) = self.own_takes(metadata.level()) {
297            (own.write)(event);
298            return;
299        }
300        if !self.sends(metadata.level()) {
301            return;
302        }
303        let mut fields = Fields::default();
304        event.record(&mut fields);
305        self.send(Some(GuestLogRecord {
306            level: level_code(metadata.level()),
307            target: metadata.target().to_owned(),
308            message: fields.0,
309        }));
310    }
311
312    fn enter(&self, _span: &span::Id) {}
313
314    fn exit(&self, _span: &span::Id) {}
315}
316
317/// An event's fields as `tracing_subscriber`'s default formatter prints them:
318/// the message as written, every other field as `name=value` with the value's
319/// `Debug` form, separated by spaces.
320#[derive(Default)]
321struct Fields(String);
322
323impl Fields {
324    fn separate(&mut self) {
325        if !self.0.is_empty() {
326            self.0.push(' ');
327        }
328    }
329}
330
331impl Visit for Fields {
332    fn record_str(&mut self, field: &Field, value: &str) {
333        self.separate();
334        if field.name() == "message" {
335            self.0.push_str(value);
336        } else {
337            let _ = write!(self.0, "{}={value:?}", field.name());
338        }
339    }
340
341    fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
342        self.separate();
343        if field.name() == "message" {
344            let _ = write!(self.0, "{value:?}");
345        } else {
346            let _ = write!(self.0, "{}={value:?}", field.name());
347        }
348    }
349}
350
351/// A callsite the coordinator makes for one level and target of guest records,
352/// so its own subscriber filters and prints them as events of that target.
353struct GuestCallsite {
354    metadata: OnceLock<Metadata<'static>>,
355}
356
357impl Callsite for GuestCallsite {
358    fn set_interest(&self, _interest: Interest) {}
359
360    fn metadata(&self) -> &Metadata<'_> {
361        self.metadata
362            .get()
363            .expect("a guest callsite's metadata is set before it is registered")
364    }
365}
366
367/// The most distinct (level, target) callsites the coordinator makes; records
368/// beyond them are printed under this module's own target, naming theirs.
369const MAX_CALLSITES: usize = 1024;
370
371/// The callsite for guest records of `level` and `target`. Each is made once and
372/// lives for the run, as a callsite must.
373fn callsite(level: Level, target: &str) -> Option<&'static GuestCallsite> {
374    static CALLSITES: Mutex<BTreeMap<(u8, String), &'static GuestCallsite>> =
375        Mutex::new(BTreeMap::new());
376    let mut callsites = CALLSITES
377        .lock()
378        .unwrap_or_else(|poison| poison.into_inner());
379    let key = (level_code(&level), target.to_owned());
380    if let Some(callsite) = callsites.get(&key) {
381        return Some(callsite);
382    }
383    if callsites.len() >= MAX_CALLSITES {
384        return None;
385    }
386    let callsite: &'static GuestCallsite = Box::leak(Box::new(GuestCallsite {
387        metadata: OnceLock::new(),
388    }));
389    let target: &'static str = Box::leak(target.to_owned().into_boxed_str());
390    let _ = callsite.metadata.set(Metadata::new(
391        "guest event",
392        target,
393        level,
394        None,
395        None,
396        None,
397        FieldSet::new(&["message"], tracing::callsite::Identifier(callsite)),
398        Kind::EVENT,
399    ));
400    tracing::callsite::register(callsite);
401    callsites.insert(key, callsite);
402    Some(callsite)
403}
404
405/// Emits one guest record in the coordinator, at its own level and target, after
406/// a warning naming the records of the sender's process that were lost before
407/// it (`unsent_before`).
408pub(crate) fn emit(record: Option<&GuestLogRecord>, unsent_before: u64) {
409    if unsent_before > 0 {
410        tracing::warn!(
411            "{} Detcore warning(s) from inside the guest could not be sent to the coordinator and are missing",
412            unsent_before
413        );
414    }
415    let Some(record) = record else {
416        return;
417    };
418    let Some(level) = level_from_code(record.level) else {
419        return;
420    };
421    if level > LevelFilter::current() {
422        return;
423    }
424    let Some(callsite) = callsite(level, &record.target) else {
425        tracing::warn!(
426            "(guest record of {} {}, past the callsite limit) {}",
427            level,
428            record.target,
429            record.message
430        );
431        return;
432    };
433    let metadata = callsite.metadata();
434    tracing::dispatcher::get_default(|dispatch| {
435        if !dispatch.enabled(metadata) {
436            return;
437        }
438        let fields = metadata.fields();
439        let Some(message) = fields.field("message") else {
440            return;
441        };
442        let text = format_args!("{}", record.message);
443        let values = [(&message, Some(&text as &dyn Value))];
444        dispatch.event(&Event::new(metadata, &fields.value_set(&values)));
445    });
446}
447
448#[cfg(test)]
449mod tests {
450    use std::sync::Arc;
451
452    use super::*;
453    use crate::tool_global::GlobalRequest;
454    use crate::tool_global::GlobalResponse;
455
456    /// Each event a subscriber saw: its level, target and fields as
457    /// [`Fields`] reads them.
458    #[derive(Default)]
459    struct Capture(Mutex<Vec<(Level, String, String)>>);
460
461    impl Subscriber for Capture {
462        fn enabled(&self, _metadata: &Metadata<'_>) -> bool {
463            true
464        }
465        fn new_span(&self, _span: &span::Attributes<'_>) -> span::Id {
466            span::Id::from_u64(1)
467        }
468        fn record(&self, _span: &span::Id, _values: &span::Record<'_>) {}
469        fn record_follows_from(&self, _span: &span::Id, _follows: &span::Id) {}
470        fn event(&self, event: &Event<'_>) {
471            let mut fields = Fields::default();
472            event.record(&mut fields);
473            let metadata = event.metadata();
474            self.0.lock().unwrap().push((
475                *metadata.level(),
476                metadata.target().to_owned(),
477                fields.0,
478            ));
479        }
480        fn enter(&self, _span: &span::Id) {}
481        fn exit(&self, _span: &span::Id) {}
482    }
483
484    #[test]
485    fn level_codes_round_trip() {
486        for level in [
487            Level::ERROR,
488            Level::WARN,
489            Level::INFO,
490            Level::DEBUG,
491            Level::TRACE,
492        ] {
493            assert_eq!(level_from_code(level_code(&level)), Some(level));
494        }
495        assert_eq!(level_from_code(0), None);
496    }
497
498    /// The fields read as the default formatter prints them: the message as
499    /// written, then each other field as `name=value` in `Debug` form.
500    #[test]
501    fn fields_read_as_the_default_formatter_prints_them() {
502        let capture = Arc::new(Capture::default());
503        tracing::subscriber::with_default(capture.clone(), || {
504            tracing::warn!("cpuid leaf 0x{:x} not in the table", 0x4ffffff0);
505            tracing::warn!(fd = 3, path = "a b", "cannot restore");
506        });
507        let fields: Vec<_> = capture
508            .0
509            .lock()
510            .unwrap()
511            .iter()
512            .map(|event| event.2.clone())
513            .collect();
514        assert_eq!(
515            fields,
516            [
517                "cpuid leaf 0x4ffffff0 not in the table",
518                "cannot restore fd=3 path=\"a b\""
519            ]
520        );
521    }
522
523    /// The coordinator prints a guest record at its own level and target, so
524    /// its filter treats it as that module's event, after a warning that
525    /// counts the records of that process lost before it; a request with only
526    /// a count prints only that warning.
527    #[test]
528    fn the_coordinator_emits_a_record_at_its_level_and_target_after_its_losses() {
529        let capture = Arc::new(Capture::default());
530        tracing::subscriber::with_default(capture.clone(), || {
531            emit(
532                Some(&GuestLogRecord {
533                    level: 2,
534                    target: "detcore::syscalls::files".to_owned(),
535                    message: "cannot restore fd=3".to_owned(),
536                }),
537                2,
538            );
539            emit(None, 1);
540            emit(None, 0);
541        });
542        let events = capture.0.lock().unwrap();
543        assert_eq!(events.len(), 3, "{events:?}");
544        let ours = module_path!().trim_end_matches("::tests");
545        assert_eq!((events[0].0, events[0].1.as_str()), (Level::WARN, ours));
546        assert!(
547            events[0]
548                .2
549                .starts_with("2 Detcore warning(s) from inside the guest"),
550            "{events:?}"
551        );
552        assert_eq!(
553            events[1],
554            (
555                Level::WARN,
556                "detcore::syscalls::files".to_owned(),
557                "cannot restore fd=3".to_owned()
558            )
559        );
560        assert!(
561            events[2].2.starts_with("1 Detcore warning(s)"),
562            "{events:?}"
563        );
564    }
565
566    /// What the fake coordinator call received: each record and count, and
567    /// whether it refused. It refuses its first call.
568    static SENT: Mutex<Vec<(Option<GuestLogRecord>, u64, bool)>> = Mutex::new(Vec::new());
569
570    fn fake_call(
571        request: <crate::GlobalState as reverie::GlobalTool>::Request,
572    ) -> io::Result<<crate::GlobalState as reverie::GlobalTool>::Response> {
573        let GlobalRequest::GuestLog(record, unsent) = request.2 else {
574            panic!("the guest log sends only GuestLog requests: {request:?}");
575        };
576        let mut sent = SENT.lock().unwrap();
577        let refuse = sent.is_empty();
578        sent.push((record, unsent, refuse));
579        if refuse {
580            Err(io::Error::other("refused"))
581        } else {
582            Ok((None, GlobalResponse::GuestLog(())))
583        }
584    }
585
586    /// Held by each test that uses the process-wide count, so that tests run
587    /// as threads of one process cannot interleave on it.
588    static COUNT_TEST_LOCK: Mutex<()> = Mutex::new(());
589
590    /// In the guest, through the subscriber a runtime installs: a warning that
591    /// cannot be sent is counted and carried by the next request that gets
592    /// through; INFO, DEBUG and TRACE events are never sent; and the
593    /// exit_group flush sends a count still held.
594    #[test]
595    fn the_guest_sends_warnings_counts_what_it_could_not_send_and_flushes_at_exit() {
596        let _count = COUNT_TEST_LOCK
597            .lock()
598            .unwrap_or_else(|poison| poison.into_inner());
599        use crate::types::DetTid;
600        use crate::types::MmId;
601        let root = MmId::initial(DetTid::from_raw(3));
602        let child = MmId::initial(DetTid::from_raw(7));
603        // Outside an in-guest runtime's subscriber, a process start leaves the
604        // count alone.
605        UNSENT.store(5, Ordering::Release);
606        starts_new_process(root);
607        starts_new_process(child);
608        assert_eq!(UNSENT.load(Ordering::Acquire), 5);
609        let subscriber = subscriber(fake_call, None);
610        tracing::subscriber::with_default(subscriber, || {
611            // A count held before the root process's first thread starts is
612            // kept, as is one when another process's thread starts in the same
613            // memory (a vfork child); a forked child's copy starts at zero.
614            *UNSENT_OWNER.lock().unwrap() = None;
615            starts_new_process(root);
616            starts_new_process(root);
617            assert_eq!(UNSENT.load(Ordering::Acquire), 5);
618            starts_new_process(child);
619            assert_eq!(UNSENT.load(Ordering::Acquire), 0);
620            starts_new_process(root);
621            tracing::warn!("first");
622            tracing::error!(target: "detcore::fifo_peer", "second");
623            tracing::info!("not sent");
624            tracing::debug!("not sent");
625            tracing::trace!("not sent");
626            assert!(!tracing::enabled!(Level::INFO));
627            UNSENT.store(3, Ordering::Release);
628            flush_unsent();
629            flush_unsent();
630        });
631        let sent = SENT.lock().unwrap();
632        let summary: Vec<_> = sent
633            .iter()
634            .map(|(record, unsent, refused)| {
635                (
636                    record
637                        .as_ref()
638                        .map(|r| (r.level, r.target.clone(), r.message.clone())),
639                    *unsent,
640                    *refused,
641                )
642            })
643            .collect();
644        assert_eq!(
645            summary,
646            [
647                (
648                    Some((2, module_path!().to_owned(), "first".to_owned())),
649                    0,
650                    true
651                ),
652                (
653                    Some((1, "detcore::fifo_peer".to_owned(), "second".to_owned())),
654                    1,
655                    false
656                ),
657                (None, 3, false),
658            ]
659        );
660        assert_eq!(UNSENT.load(Ordering::Acquire), 0);
661    }
662
663    /// What the runtime's own channel received.
664    static OWN: Mutex<Vec<(Level, String)>> = Mutex::new(Vec::new());
665
666    fn own_write(event: &Event<'_>) {
667        let mut fields = Fields::default();
668        event.record(&mut fields);
669        OWN.lock()
670            .unwrap()
671            .push((*event.metadata().level(), fields.0));
672    }
673
674    fn refusing_call(
675        _request: <crate::GlobalState as reverie::GlobalTool>::Request,
676    ) -> io::Result<<crate::GlobalState as reverie::GlobalTool>::Response> {
677        panic!("an event the runtime's own channel takes is not sent");
678    }
679
680    /// The runtime's own channel takes every event up to its level, DETLOG or
681    /// not, in order, and nothing above it; and a subscriber with an own
682    /// channel sends nothing, also above that level (at ERROR, a WARN).
683    #[test]
684    fn the_own_channel_takes_every_event_up_to_its_level_and_nothing_is_sent() {
685        let own = OwnChannel {
686            max_level: Level::INFO,
687            write: own_write,
688        };
689        tracing::subscriber::with_default(subscriber(refusing_call, Some(own)), || {
690            tracing::error!("an error");
691            tracing::warn!("a warning");
692            tracing::info!("DETLOG a record");
693            tracing::info!("an info");
694            tracing::debug!("a debug");
695            tracing::trace!("a trace");
696        });
697        assert_eq!(
698            *OWN.lock().unwrap(),
699            [
700                (Level::ERROR, "an error".to_owned()),
701                (Level::WARN, "a warning".to_owned()),
702                (Level::INFO, "DETLOG a record".to_owned()),
703                (Level::INFO, "an info".to_owned()),
704            ]
705        );
706        let errors_only = OwnChannel {
707            max_level: Level::ERROR,
708            write: own_write,
709        };
710        tracing::subscriber::with_default(subscriber(refusing_call, Some(errors_only)), || {
711            tracing::warn!("above the run's level");
712            assert!(!tracing::enabled!(Level::WARN));
713        });
714        assert_eq!(OWN.lock().unwrap().len(), 4);
715    }
716
717    /// A Tool exit callback's connection to the global state: what it was
718    /// sent, and whether it answers as the coordinator does.
719    struct ExitHookRpc {
720        config: crate::Config,
721        answers: bool,
722        sent: Mutex<Vec<GlobalRequest>>,
723    }
724
725    #[reverie::tool]
726    impl reverie::GlobalRPC<crate::GlobalState> for ExitHookRpc {
727        async fn send_rpc(
728            &self,
729            message: <crate::GlobalState as reverie::GlobalTool>::Request,
730        ) -> <crate::GlobalState as reverie::GlobalTool>::Response {
731            self.sent.lock().unwrap().push(message.2);
732            if self.answers {
733                (None, GlobalResponse::GuestLog(()))
734            } else {
735                (None, GlobalResponse::Retired)
736            }
737        }
738
739        fn config(&self) -> &crate::Config {
740            &self.config
741        }
742    }
743
744    /// The exit hook's flush sends a held count through the hook's own
745    /// connection and clears it; a count the coordinator does not take back
746    /// is kept; with nothing held, nothing is sent.
747    #[test]
748    fn the_exit_hook_sends_a_held_count_through_its_own_connection() {
749        let _count = COUNT_TEST_LOCK
750            .lock()
751            .unwrap_or_else(|poison| poison.into_inner());
752        let rpc = |answers| ExitHookRpc {
753            config: Default::default(),
754            answers,
755            sent: Mutex::new(Vec::new()),
756        };
757        UNSENT.store(0, Ordering::Release);
758        let idle = rpc(true);
759        futures::executor::block_on(flush_unsent_through(&idle));
760        assert!(idle.sent.lock().unwrap().is_empty());
761
762        UNSENT.store(4, Ordering::Release);
763        let refusing = rpc(false);
764        futures::executor::block_on(flush_unsent_through(&refusing));
765        assert_eq!(
766            *refusing.sent.lock().unwrap(),
767            [GlobalRequest::GuestLog(None, 4)]
768        );
769        assert_eq!(UNSENT.load(Ordering::Acquire), 4);
770
771        let answering = rpc(true);
772        futures::executor::block_on(flush_unsent_through(&answering));
773        assert_eq!(
774            *answering.sent.lock().unwrap(),
775            [GlobalRequest::GuestLog(None, 4)]
776        );
777        assert_eq!(UNSENT.load(Ordering::Acquire), 0);
778    }
779}
detcore/guest_log.rs

detcore/
guest_log.rs
