1use std::fmt;
14use std::os::fd::AsRawFd;
15use std::os::fd::OwnedFd;
16use std::sync::Mutex;
17use std::sync::OnceLock;
18use std::sync::atomic::AtomicI32;
19use std::sync::atomic::AtomicU64;
20use std::sync::atomic::Ordering;
21
22use serde::Deserialize;
23use serde::Serialize;
24
25pub const RECORD_SEPARATOR: &str = " DETLOG_RECORD=";
31
32pub const RECORD_SCHEMA: u32 = 1;
34
35#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize)]
37#[serde(tag = "kind", rename_all = "snake_case", deny_unknown_fields)]
38pub enum DetLogEvent {
39 Other,
41 Syscall,
43 SyscallResult {
45 finished_syscall_number: u64,
47 },
48 SchedulerCommit {
50 scheduler_turn: u64,
52 virtual_nanoseconds: u64,
54 internal_io_poll: bool,
56 runtime_maps_read: bool,
58 },
59 SchedulerCommittedTime,
61 SchedulerEmptyQueueKick,
63}
64
65#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize)]
67#[serde(deny_unknown_fields)]
68pub struct DetLogRecord {
69 pub schema: u32,
71 pub event: DetLogEvent,
73}
74
75impl DetLogRecord {
76 pub fn new(event: DetLogEvent) -> Self {
78 Self {
79 schema: RECORD_SCHEMA,
80 event,
81 }
82 }
83
84 pub fn split(message: &str) -> Result<(&str, Option<Self>), String> {
90 let Some((human, encoded)) = message.rsplit_once(RECORD_SEPARATOR) else {
91 return Ok((message, None));
92 };
93 let record: Self = serde_json::from_str(encoded)
94 .map_err(|error| format!("malformed DETLOG record: {error}"))?;
95 if record.schema != RECORD_SCHEMA {
96 return Err(format!(
97 "unsupported DETLOG record schema {}; expected {}",
98 record.schema, RECORD_SCHEMA
99 ));
100 }
101 Ok((human, Some(record)))
102 }
103}
104
105#[doc(hidden)]
107pub fn record_suffix(event: DetLogEvent) -> String {
108 let encoded = serde_json::to_string(&DetLogRecord::new(event))
109 .expect("DETLOG record serialization cannot fail");
110 format!("{RECORD_SEPARATOR}{encoded}")
111}
112
113pub type DetlogForwarder = for<'a> fn(&str, &str, u64, fmt::Arguments<'a>);
118
119#[derive(Debug, Clone, PartialEq, Eq)]
146pub struct ForwardPolicy {
147 default: bool,
148 targets: Vec<(String, bool)>,
149}
150
151impl ForwardPolicy {
152 pub fn all() -> Self {
155 Self {
156 default: true,
157 targets: Vec::new(),
158 }
159 }
160
161 pub fn from_current_subscriber(directives: &str) -> Self {
170 Self::from_probe(directives, info_enabled_for_target)
171 }
172
173 pub fn from_probe(directives: &str, info_enabled: impl Fn(&str) -> bool) -> Self {
175 let mut targets: Vec<(String, bool)> = Vec::new();
176 for directive in directives.split(',') {
177 let target = directive
178 .split(['[', '='])
179 .next()
180 .unwrap_or_default()
181 .trim();
182 if target.is_empty() || targets.iter().any(|(named, _)| named == target) {
183 continue;
184 }
185 targets.push((target.to_owned(), info_enabled(target)));
186 }
187 Self {
188 default: info_enabled(""),
191 targets,
192 }
193 }
194
195 pub fn forwards_any(&self) -> bool {
197 self.default || self.targets.iter().any(|(_, enabled)| *enabled)
198 }
199
200 pub fn forwards(&self, target: &str) -> bool {
202 self.targets
203 .iter()
204 .filter(|(named, _)| target.starts_with(named.as_str()))
205 .max_by_key(|(named, _)| named.len())
206 .map_or(self.default, |(_, enabled)| *enabled)
207 }
208
209 pub fn encode(&self) -> String {
213 let mut encoded = String::from(if self.default { "1" } else { "0" });
214 for (target, enabled) in &self.targets {
215 encoded.push(',');
216 encoded.push_str(target);
217 encoded.push_str(if *enabled { "=1" } else { "=0" });
218 }
219 encoded
220 }
221
222 pub fn decode(encoded: &str) -> Result<Self, String> {
224 fn flag(text: &str) -> Option<bool> {
225 match text {
226 "1" => Some(true),
227 "0" => Some(false),
228 _ => None,
229 }
230 }
231 let mut entries = encoded.split(',');
232 let default = entries
233 .next()
234 .and_then(flag)
235 .ok_or_else(|| format!("DETLOG forwarding policy {encoded:?} lacks a 0/1 default"))?;
236 let mut targets = Vec::new();
237 for entry in entries {
238 let parsed = entry
239 .split_once('=')
240 .filter(|(target, _)| !target.is_empty())
241 .and_then(|(target, enabled)| Some((target.to_owned(), flag(enabled)?)));
242 let Some(parsed) = parsed else {
243 return Err(format!(
244 "DETLOG forwarding policy {encoded:?} has malformed entry {entry:?}"
245 ));
246 };
247 targets.push(parsed);
248 }
249 Ok(Self { default, targets })
250 }
251}
252
253pub fn info_enabled_for_target(target: &str) -> bool {
262 use tracing::Metadata;
263 use tracing::callsite::DefaultCallsite;
264 use tracing::field::FieldSet;
265 use tracing::level_filters::LevelFilter;
266 use tracing::metadata::Kind;
267
268 static HINT_CALLSITE: DefaultCallsite = DefaultCallsite::new(&HINT_METADATA);
270 static HINT_METADATA: Metadata<'static> = Metadata::new(
271 "detlog forwarding hint probe",
272 "detcore::detlog",
273 tracing::Level::INFO,
274 None,
275 None,
276 None,
277 FieldSet::new(&[], tracing::callsite::Identifier(&HINT_CALLSITE)),
278 Kind::HINT,
279 );
280 static PROBE_CALLSITE: DefaultCallsite = DefaultCallsite::new(&PROBE_METADATA);
282 static PROBE_METADATA: Metadata<'static> = Metadata::new(
283 "detlog forwarding probe",
284 "detcore::detlog",
285 tracing::Level::INFO,
286 None,
287 None,
288 None,
289 FieldSet::new(&["message"], tracing::callsite::Identifier(&PROBE_CALLSITE)),
290 Kind::EVENT,
291 );
292
293 if tracing::level_filters::STATIC_MAX_LEVEL < LevelFilter::INFO
294 || LevelFilter::current() < LevelFilter::INFO
295 {
296 return false;
297 }
298 let hint = Metadata::new(
299 "detlog forwarding hint probe",
300 target,
301 tracing::Level::INFO,
302 None,
303 None,
304 Some(target),
305 FieldSet::new(&[], tracing::callsite::Identifier(&HINT_CALLSITE)),
306 Kind::HINT,
307 );
308 let event = Metadata::new(
309 "detlog forwarding probe",
310 target,
311 tracing::Level::INFO,
312 None,
313 None,
314 Some(target),
315 FieldSet::new(&["message"], tracing::callsite::Identifier(&PROBE_CALLSITE)),
316 Kind::EVENT,
317 );
318 tracing::dispatcher::get_default(|dispatch| dispatch.enabled(&hint) && dispatch.enabled(&event))
319}
320
321static FORWARDER: OnceLock<(DetlogForwarder, ForwardPolicy)> = OnceLock::new();
322
323pub fn set_forwarder(
331 forwarder: DetlogForwarder,
332 policy: ForwardPolicy,
333) -> Result<(), (DetlogForwarder, ForwardPolicy)> {
334 FORWARDER.set((forwarder, policy))
335}
336
337#[doc(hidden)]
342pub fn forwarded_line(target: &str, record_suffix: &str, message: fmt::Arguments<'_>) -> Vec<u8> {
343 format!("INFO {target}: DETLOG {message}{record_suffix}\n").into_bytes()
344}
345
346pub const PLAIN_INFO_MAGIC: &[u8; 8] = b"HINFO\0\0\0";
349const PLAIN_INFO_HEADER: usize = 20;
350const PLAIN_INFO_MAX: usize = 64 * 1024;
351
352fn plain_info_target(target: &str) -> bool {
353 if target == "detcore" || target == "reverie::guest" {
354 return true;
355 }
356 target.strip_prefix("detcore::").is_some_and(|rest| {
357 rest.split("::").all(|segment| {
358 let mut bytes = segment.bytes();
359 bytes
360 .next()
361 .is_some_and(|first| first.is_ascii_alphabetic() || first == b'_')
362 && bytes.all(|byte| byte.is_ascii_alphanumeric() || byte == b'_')
363 })
364 })
365}
366
367pub fn validate_plain_info_directives(directives: &str) -> Result<(), &'static str> {
371 for directive in directives
372 .split(',')
373 .map(str::trim)
374 .filter(|entry| !entry.is_empty())
375 {
376 let level =
377 |text: &str| matches!(text, "off" | "error" | "warn" | "info" | "debug" | "trace");
378 if level(directive) {
379 continue;
380 }
381 let (target, setting) = directive
382 .split_once('=')
383 .map_or((directive, None), |(t, l)| (t, Some(l)));
384 if target.is_empty()
385 || !target
386 .bytes()
387 .all(|byte| byte.is_ascii_alphanumeric() || b"_:-.".contains(&byte))
388 || setting.is_some_and(|setting| !level(setting))
389 {
390 return Err("ordered plain INFO requires target-only log directives");
391 }
392 }
393 Ok(())
394}
395
396pub fn encode_plain_info(target: &str, message: &str) -> Result<Vec<u8>, &'static str> {
399 if !plain_info_target(target) || target.len() > 4096 {
400 return Err("plain INFO target outside the Detcore module class");
401 }
402 if message
405 .bytes()
406 .any(|byte| matches!(byte, b'\r' | b'\n' | 0))
407 {
408 return Err("plain INFO multiline/control message is unsupported");
409 }
410 let length = PLAIN_INFO_HEADER
411 .checked_add(target.len())
412 .and_then(|n| n.checked_add(message.len()))
413 .filter(|length| *length <= PLAIN_INFO_MAX)
414 .ok_or("plain INFO envelope too large")?;
415 let mut bytes = Vec::with_capacity(length);
416 bytes.extend_from_slice(PLAIN_INFO_MAGIC);
417 bytes.extend_from_slice(&[1, 1, 3, 0]); bytes.extend_from_slice(&(target.len() as u32).to_le_bytes());
419 bytes.extend_from_slice(&(message.len() as u32).to_le_bytes());
420 bytes.extend_from_slice(target.as_bytes());
421 bytes.extend_from_slice(message.as_bytes());
422 Ok(bytes)
423}
424
425pub fn decode_plain_info(bytes: &[u8]) -> Result<(&str, &str), &'static str> {
428 if bytes.len() < PLAIN_INFO_HEADER
429 || bytes.len() > PLAIN_INFO_MAX
430 || bytes.get(..8) != Some(PLAIN_INFO_MAGIC.as_slice())
431 || bytes.get(8..12) != Some(&[1, 1, 3, 0])
432 {
433 return Err("plain INFO header/class is invalid");
434 }
435 let target_len = u32::from_le_bytes(
436 bytes[12..16]
437 .try_into()
438 .map_err(|_| "plain INFO target length")?,
439 ) as usize;
440 let message_len = u32::from_le_bytes(
441 bytes[16..20]
442 .try_into()
443 .map_err(|_| "plain INFO message length")?,
444 ) as usize;
445 let split = PLAIN_INFO_HEADER
446 .checked_add(target_len)
447 .ok_or("plain INFO target overflow")?;
448 let end = split
449 .checked_add(message_len)
450 .ok_or("plain INFO message overflow")?;
451 if end != bytes.len() || target_len > 4096 {
452 return Err("plain INFO lengths mismatch");
453 }
454 let target = std::str::from_utf8(
455 bytes
456 .get(PLAIN_INFO_HEADER..split)
457 .ok_or("plain INFO target truncated")?,
458 )
459 .map_err(|_| "plain INFO target UTF-8")?;
460 let message = std::str::from_utf8(
461 bytes
462 .get(split..end)
463 .ok_or("plain INFO message truncated")?,
464 )
465 .map_err(|_| "plain INFO message UTF-8")?;
466 if !plain_info_target(target)
467 || message
468 .bytes()
469 .any(|byte| matches!(byte, b'\r' | b'\n' | 0))
470 {
471 return Err("plain INFO target/message class is invalid");
472 }
473 Ok((target, message))
474}
475
476pub type PlainInfoForwarder = for<'a> fn(&str, u64, fmt::Arguments<'a>);
480static PLAIN_INFO_FORWARDER: OnceLock<PlainInfoForwarder> = OnceLock::new();
481
482pub fn set_plain_info_forwarder(forwarder: PlainInfoForwarder) -> Result<(), &'static str> {
485 if FORWARDER.get().is_none() {
486 return Err("plain INFO requires the existing counted forwarder");
487 }
488 PLAIN_INFO_FORWARDER
489 .set(forwarder)
490 .map_err(|_| "plain INFO forwarder installed twice")
491}
492
493#[doc(hidden)]
496pub fn plain_info_forwarding() -> bool {
497 PLAIN_INFO_FORWARDER.get().is_some()
498}
499
500#[doc(hidden)]
504pub fn emit_plain_info(target: &str, message: fmt::Arguments<'_>) {
505 if !forwards_target(target) {
506 return;
507 }
508 let index = count_forwarded();
509 PLAIN_INFO_FORWARDER
510 .get()
511 .expect("plain INFO forwarder disappeared")(target, index, message);
512}
513
514#[macro_export]
518macro_rules! ordered_info {
519 ($format:literal $(, $argument:expr)* $(,)?) => {{
520 if $crate::detlog::plain_info_forwarding() {
521 if $crate::detlog::forwards_target(module_path!()) {
522 $crate::detlog::emit_plain_info(module_path!(), format_args!($format $(, $argument)*));
523 }
524 } else {
525 tracing::info!($format $(, $argument)*);
526 }
527 }};
528}
529
530pub fn send_plain_info_record(
534 socket: Option<libc::c_int>,
535 target: &str,
536 index: u64,
537 message: fmt::Arguments<'_>,
538) {
539 if let Some(socket) = socket {
540 send_forwarded_payload(socket, index, || {
541 match encode_plain_info(target, &message.to_string()) {
542 Ok(bytes) => bytes,
543 Err(reason) => format!("{FORWARDING_LOSS_NOTICE} 0 0 {reason}\n").into_bytes(),
544 }
545 });
546 }
547}
548
549fn preserving_errno(operation: impl FnOnce()) {
553 let errno = unsafe { libc::__errno_location() };
555 let saved = unsafe { *errno };
557 operation();
558 unsafe { *errno = saved };
560}
561
562pub fn forward_to_stderr(
572 target: &str,
573 record_suffix: &str,
574 _index: u64,
575 message: fmt::Arguments<'_>,
576) {
577 preserving_errno(|| {
578 let line = forwarded_line(target, record_suffix, message);
579 let mut rest = line.as_slice();
580 while !rest.is_empty() {
581 let written = unsafe {
583 libc::write(
584 libc::STDERR_FILENO,
585 rest.as_ptr().cast::<libc::c_void>(),
586 rest.len(),
587 )
588 };
589 if written > 0 {
590 rest = &rest[written as usize..];
591 } else if written == 0
592 || std::io::Error::last_os_error().kind() != std::io::ErrorKind::Interrupted
593 {
594 return;
595 }
596 }
597 });
598}
599
600pub const FORWARDING_LOSS_NOTICE: &str = "HERMIT_DETLOG_RECORD_LOST";
604
605pub const FORWARDING_RETIRED_NOTICE: &[u8] = b"HERMIT_DETLOG_RECORD_LOST 0 0 socket retired\n";
609
610static UNREPORTED_LOSSES: AtomicU64 = AtomicU64::new(0);
613
614pub fn send_forwarded_record(
624 socket: libc::c_int,
625 target: &str,
626 record_suffix: &str,
627 index: u64,
628 message: fmt::Arguments<'_>,
629) {
630 send_forwarded_payload(socket, index, || {
631 forwarded_line(target, record_suffix, message)
632 });
633}
634
635fn send_forwarded_payload(socket: libc::c_int, index: u64, payload: impl FnOnce() -> Vec<u8>) {
636 let send = |bytes: &[u8]| loop {
637 let sent = unsafe {
639 libc::send(
640 socket,
641 bytes.as_ptr().cast::<libc::c_void>(),
642 bytes.len(),
643 libc::MSG_NOSIGNAL,
644 )
645 };
646 if sent >= 0 {
647 return Ok(());
648 }
649 let error = std::io::Error::last_os_error();
650 if error.kind() != std::io::ErrorKind::Interrupted {
651 return Err(error);
652 }
653 };
654 let notice = |length: usize, errno: i32| format!("{FORWARDING_LOSS_NOTICE} {length} {errno}\n");
655 preserving_errno(|| {
656 let unreported = UNREPORTED_LOSSES.swap(0, Ordering::AcqRel);
657 if unreported > 0 && send(notice(0, 0).as_bytes()).is_err() {
658 UNREPORTED_LOSSES.fetch_add(unreported, Ordering::AcqRel);
659 }
660 let line = tagged_forwarded_message(current_tid(), index, &payload());
661 if let Err(error) = send(&line) {
662 let errno = error.raw_os_error().unwrap_or(0);
663 if send(notice(line.len(), errno).as_bytes()).is_err() {
664 UNREPORTED_LOSSES.fetch_add(1, Ordering::AcqRel);
665 }
666 }
667 });
668}
669
670pub fn socket_identity(fd: libc::c_int) -> Option<(u64, u64)> {
673 let mut metadata: libc::stat = unsafe { std::mem::zeroed() };
677 let status = unsafe {
678 crate::util::raw_syscall(
679 libc::SYS_fstat,
680 [fd as u64, (&raw mut metadata) as u64, 0, 0, 0, 0],
681 )
682 };
683 (status == 0 && metadata.st_mode & libc::S_IFMT == libc::S_IFSOCK)
684 .then_some((metadata.st_dev, metadata.st_ino))
685}
686
687pub fn tool_output_env_value(fd: libc::c_int) -> std::io::Result<String> {
697 let (dev, ino) = socket_identity(fd).ok_or_else(|| {
698 std::io::Error::new(
699 std::io::ErrorKind::InvalidInput,
700 "a Tool output descriptor must be a socket",
701 )
702 })?;
703 Ok(format!("{fd}:{dev:016x}:{ino:016x}"))
704}
705
706pub fn parse_tool_output_env_value(value: &str) -> Option<(libc::c_int, (u64, u64))> {
708 let mut fields = value.split(':');
709 let fd = fields.next()?.parse::<libc::c_int>().ok()?;
710 let hex = |field: Option<&str>| {
711 field
712 .filter(|field| field.len() == 16)
713 .and_then(|field| u64::from_str_radix(field, 16).ok())
714 };
715 let identity = (hex(fields.next())?, hex(fields.next())?);
716 fields.next().is_none().then_some((fd, identity))
717}
718
719pub fn tool_output_env_target(value: &str) -> Option<libc::c_int> {
722 let (fd, identity) = parse_tool_output_env_value(value)?;
723 (socket_identity(fd) == Some(identity)).then_some(fd)
724}
725
726fn current_tid() -> i32 {
728 unsafe { libc::syscall(libc::SYS_gettid) as i32 }
730}
731
732pub fn tagged_forwarded_message(tid: i32, index: u64, line: &[u8]) -> Vec<u8> {
739 let mut message = format!("T{tid}.{index} ").into_bytes();
740 message.extend_from_slice(line);
741 message
742}
743
744pub fn split_forwarded_message(message: &[u8]) -> Option<(i32, u64, &[u8])> {
749 let rest = message.strip_prefix(b"T")?;
750 let space = rest.iter().position(|&byte| byte == b' ')?;
751 let tag = std::str::from_utf8(&rest[..space]).ok()?;
752 let (tid, index) = tag.split_once('.')?;
753 let decimal = |digits: &str| !digits.is_empty() && digits.bytes().all(|b| b.is_ascii_digit());
754 if !decimal(tid) || !decimal(index) {
755 return None;
756 }
757 Some((tid.parse().ok()?, index.parse().ok()?, &rest[space + 1..]))
758}
759
760pub type ForwardedRecordSink = Box<dyn FnMut(&[u8]) + Send>;
763
764#[derive(Clone, Copy, Debug, PartialEq, Eq)]
767enum Runner {
768 NoTurnYet,
770 Root(i32),
773 Exclusive(i32),
775 None,
777}
778
779#[derive(Debug)]
784pub(crate) struct ForwardedOrder {
785 pending: std::collections::BTreeMap<i32, Vec<Vec<u8>>>,
786 runner: Runner,
787 ambiguous: bool,
789 legacy: bool,
791 received: std::collections::BTreeMap<i32, ReceivedInterval>,
794}
795
796#[derive(Clone, Copy, Debug, Default, PartialEq, Eq)]
798pub(crate) struct ReceivedInterval {
799 pub(crate) count: u64,
801 pub(crate) out_of_sequence: Option<(u64, u64)>,
803}
804
805pub const FORWARDING_UNTAGGED_RECORD_NOTICE: &[u8] =
809 b"HERMIT_DETLOG_RECORD_LOST 0 0 untagged forwarded record from an older runtime\n";
810
811pub const FORWARDING_AMBIGUOUS_ORDER_NOTICE: &[u8] =
815 b"HERMIT_DETLOG_RECORD_LOST 0 0 forwarded order ambiguous: more than one root\n";
816
817impl ForwardedOrder {
818 pub(crate) fn new() -> Self {
819 Self {
820 pending: Default::default(),
821 runner: Runner::NoTurnYet,
822 ambiguous: false,
823 legacy: false,
824 received: Default::default(),
825 }
826 }
827
828 pub(crate) fn queue(&mut self, tid: i32, record: Vec<u8>) {
830 self.pending.entry(tid).or_default().push(record);
831 }
832
833 pub(crate) fn arrived(&mut self, tid: i32, index: u64) {
838 let interval = self.received.entry(tid).or_default();
839 interval.count += 1;
840 if index != interval.count && interval.out_of_sequence.is_none() {
841 interval.out_of_sequence = Some((interval.count, index));
842 }
843 }
844
845 pub(crate) fn received_since_check(&mut self, tid: i32) -> ReceivedInterval {
848 self.received.remove(&tid).unwrap_or_default()
849 }
850
851 pub(crate) fn at_request(&mut self, tid: i32) -> Vec<Vec<u8>> {
854 match self.runner {
855 Runner::NoTurnYet => {
856 self.runner = Runner::Root(tid);
857 self.pending.remove(&tid).unwrap_or_default()
858 }
859 Runner::Root(root) | Runner::Exclusive(root) if root == tid => {
860 self.pending.remove(&tid).unwrap_or_default()
861 }
862 Runner::Root(_) if !self.ambiguous => {
863 self.ambiguous = true;
869 vec![FORWARDING_AMBIGUOUS_ORDER_NOTICE.to_vec()]
870 }
871 _ => Vec::new(),
872 }
873 }
874
875 pub(crate) fn at_commit(&mut self, tid: i32, exclusive: bool) -> Vec<Vec<u8>> {
878 self.runner = if exclusive {
879 Runner::Exclusive(tid)
880 } else {
881 Runner::None
882 };
883 self.pending.remove(&tid).unwrap_or_default()
884 }
885
886 pub(crate) fn untagged(&mut self, message: &[u8]) -> Vec<Vec<u8>> {
892 if message.starts_with(FORWARDING_LOSS_NOTICE.as_bytes()) {
893 return vec![message.to_vec()];
894 }
895 let mut out = Vec::new();
896 if !self.legacy {
897 self.legacy = true;
898 out.push(FORWARDING_UNTAGGED_RECORD_NOTICE.to_vec());
899 }
900 out.push(message.to_vec());
901 out
902 }
903
904 pub(crate) fn finish(&mut self) -> Vec<Vec<u8>> {
906 std::mem::take(&mut self.pending)
907 .into_values()
908 .flatten()
909 .collect()
910 }
911}
912
913struct ForwardedSource {
916 socket: OwnedFd,
917 sink: ForwardedRecordSink,
918 order: ForwardedOrder,
919 transport_failure: Option<ForwardedSourceError>,
922 loss_seen: bool,
923}
924
925#[derive(Clone, Copy, Debug, PartialEq, Eq)]
926enum ForwardedSourceError {
927 Closed,
928 Io(i32),
929 Poll(i16),
930 MessageChanged,
931}
932
933static FORWARDED_SOURCE: Mutex<Option<ForwardedSource>> = Mutex::new(None);
934
935pub const DETERMINISM_LOSS_RECORD_TARGET: &str = "detcore::determinism_loss";
941
942static FORWARDED_GENERATION: AtomicU64 = AtomicU64::new(0);
945static RECEIVER_GENERATION: AtomicU64 = AtomicU64::new(0);
947static RECEIVER_STOP: Mutex<Option<tokio::sync::oneshot::Sender<()>>> = Mutex::new(None);
950
951static DETERMINISM_LOSS: Mutex<Option<String>> = Mutex::new(None);
955
956pub fn record_determinism_loss(reason: &str) {
962 let mut loss = DETERMINISM_LOSS.lock().unwrap();
963 if loss.is_none() {
964 *loss = Some(reason.to_owned());
965 }
966}
967
968static REPLAY_REFUSAL: Mutex<Option<String>> = Mutex::new(None);
969
970pub fn record_replay_refusal(reason: &str) {
975 write_loss_notice(reason);
976 let mut refusal = REPLAY_REFUSAL.lock().unwrap();
977 if refusal.is_none() {
978 *refusal = Some(reason.to_owned());
979 }
980}
981
982pub fn replay_refusal() -> Option<String> {
985 REPLAY_REFUSAL.lock().unwrap().clone()
986}
987
988pub fn determinism_loss() -> Option<String> {
991 DETERMINISM_LOSS.lock().unwrap().clone()
992}
993
994pub fn write_loss_notice(reason: &str) {
998 let line = format!("{FORWARDING_LOSS_NOTICE} 0 0 {reason}\n");
999 record_determinism_loss(reason);
1000 if let Some(source) = FORWARDED_SOURCE.lock().unwrap().as_mut() {
1001 (source.sink)(line.as_bytes());
1002 }
1003}
1004
1005fn emit(source: &mut ForwardedSource, record: &[u8]) {
1008 if record.starts_with(FORWARDING_LOSS_NOTICE.as_bytes()) {
1009 source.loss_seen = true;
1010 record_determinism_loss(&String::from_utf8_lossy(record));
1011 }
1012 (source.sink)(record);
1013}
1014
1015pub fn set_forwarded_source(socket: OwnedFd, sink: ForwardedRecordSink) {
1069 let mut source = FORWARDED_SOURCE.lock().unwrap();
1070 FORWARDED_GENERATION.fetch_add(1, Ordering::SeqCst);
1071 stop_forwarded_receiver();
1072 *source = Some(ForwardedSource {
1073 socket,
1074 sink,
1075 order: ForwardedOrder::new(),
1076 transport_failure: None,
1077 loss_seen: false,
1078 });
1079}
1080
1081fn start_forwarded_receiver() {
1086 let generation = FORWARDED_GENERATION.load(Ordering::SeqCst);
1087 if RECEIVER_GENERATION.load(Ordering::SeqCst) == generation {
1088 return;
1089 }
1090 let Ok(runtime) = tokio::runtime::Handle::try_current() else {
1091 return;
1092 };
1093 let watched = match FORWARDED_SOURCE.lock().unwrap().as_ref() {
1097 Some(source) => match source.socket.try_clone() {
1098 Ok(watched) => watched,
1099 Err(_) => return,
1100 },
1101 None => return,
1102 };
1103 if RECEIVER_GENERATION.swap(generation, Ordering::SeqCst) == generation {
1104 return;
1105 }
1106 let (stop, stopped) = tokio::sync::oneshot::channel();
1107 stop_forwarded_receiver();
1108 *RECEIVER_STOP.lock().unwrap() = Some(stop);
1109 runtime.spawn(receive_forwarded(watched, generation, stopped));
1110}
1111
1112fn stop_forwarded_receiver() {
1114 if let Some(stop) = RECEIVER_STOP.lock().unwrap().take() {
1115 let _ = stop.send(());
1116 }
1117}
1118
1119async fn receive_forwarded(
1128 watched: OwnedFd,
1129 generation: u64,
1130 mut stopped: tokio::sync::oneshot::Receiver<()>,
1131) {
1132 let Ok(readiness) =
1133 tokio::io::unix::AsyncFd::with_interest(watched, tokio::io::Interest::READABLE)
1134 else {
1135 let _ =
1138 RECEIVER_GENERATION.compare_exchange(generation, 0, Ordering::SeqCst, Ordering::SeqCst);
1139 return;
1140 };
1141 loop {
1142 let ready = tokio::select! {
1143 ready = readiness.readable() => ready,
1144 _ = &mut stopped => return,
1145 };
1146 let Ok(mut ready) = ready else {
1147 let _ = RECEIVER_GENERATION.compare_exchange(
1148 generation,
1149 0,
1150 Ordering::SeqCst,
1151 Ordering::SeqCst,
1152 );
1153 return;
1154 };
1155 {
1156 let mut source = FORWARDED_SOURCE.lock().unwrap();
1157 if FORWARDED_GENERATION.load(Ordering::SeqCst) != generation {
1158 return;
1159 }
1160 match source.as_mut() {
1161 Some(source) => {
1162 collect_forwarded(source);
1163 if source.transport_failure.is_some() {
1164 return;
1165 }
1166 }
1167 None => return,
1168 }
1169 }
1170 ready.clear_ready();
1172 }
1173}
1174
1175pub fn clear_forwarded_source() {
1179 let mut source = FORWARDED_SOURCE.lock().unwrap();
1180 FORWARDED_GENERATION.fetch_add(1, Ordering::SeqCst);
1181 stop_forwarded_receiver();
1182 if let Some(source) = source.as_mut() {
1183 collect_forwarded(source);
1184 let records = source.order.finish();
1185 write_records(source, records);
1186 }
1187 source.take();
1188}
1189
1190pub unsafe trait NativePhysicalExitCompletion {
1200 fn retained_pidfd(&self) -> std::os::fd::BorrowedFd<'_>;
1202 fn process_id(&self) -> i32;
1204 fn birth_identity(&self) -> u64;
1206}
1207
1208pub unsafe trait NativePhysicalWatchIdentity {
1216 fn retained_pidfd(&self) -> std::os::fd::BorrowedFd<'_>;
1218 fn process_id(&self) -> i32;
1220 fn birth_identity(&self) -> u64;
1222 fn watch_is_healthy(&self) -> bool;
1224}
1225
1226#[derive(Debug)]
1229pub struct NativeForwardedSourceReceipt {
1230 generation: u64,
1231 identity: (u64, u64),
1232 owner: (i32, u64),
1233}
1234
1235pub fn retain_native_forwarded_source(
1238 watch: &dyn NativePhysicalWatchIdentity,
1239) -> Result<NativeForwardedSourceReceipt, CoordinatorForwardingCutError> {
1240 use std::os::fd::AsRawFd;
1241 let owner = (watch.process_id(), watch.birth_identity());
1242 let fd = watch.retained_pidfd().as_raw_fd();
1243 let mut stat: libc::stat = unsafe { std::mem::zeroed() };
1244 let mut fs: libc::statfs = unsafe { std::mem::zeroed() };
1245 let mut poll = libc::pollfd {
1246 fd,
1247 events: libc::POLLIN,
1248 revents: 0,
1249 };
1250 if owner.0 <= 0
1251 || owner.1 == 0
1252 || !watch.watch_is_healthy()
1253 || unsafe { libc::fstat(fd, &mut stat) } != 0
1254 || unsafe { libc::fstatfs(fd, &mut fs) } != 0
1255 || fs.f_type as i64 != 0x5049_4446
1256 || stat.st_ino != owner.1
1257 || unsafe { libc::poll(&mut poll, 1, 0) } != 0
1258 {
1259 return Err(CoordinatorForwardingCutError::InvalidOwner);
1260 }
1261 let mut source = FORWARDED_SOURCE.lock().unwrap();
1262 let source = source
1263 .as_mut()
1264 .ok_or(CoordinatorForwardingCutError::MissingSource)?;
1265 Ok(NativeForwardedSourceReceipt {
1266 generation: FORWARDED_GENERATION.load(Ordering::SeqCst),
1267 identity: source_identity_for_cut(source)?,
1268 owner,
1269 })
1270}
1271
1272fn verify_native_physical_completion(
1273 receipt: &dyn NativePhysicalExitCompletion,
1274) -> Result<(), CoordinatorForwardingCutError> {
1275 use std::os::fd::AsRawFd;
1276 let fd = receipt.retained_pidfd().as_raw_fd();
1277 let mut stat: libc::stat = unsafe { std::mem::zeroed() };
1278 let mut fs: libc::statfs = unsafe { std::mem::zeroed() };
1279 if receipt.process_id() <= 0
1280 || receipt.birth_identity() == 0
1281 || unsafe { libc::fstat(fd, &mut stat) } != 0
1282 || unsafe { libc::fstatfs(fd, &mut fs) } != 0
1283 || fs.f_type as i64 != 0x5049_4446
1284 || stat.st_ino != receipt.birth_identity()
1285 {
1286 return Err(CoordinatorForwardingCutError::InvalidOwner);
1287 }
1288 let mut poll = libc::pollfd {
1289 fd,
1290 events: libc::POLLIN,
1291 revents: 0,
1292 };
1293 let result = unsafe { libc::poll(&mut poll, 1, 0) };
1294 if result < 0 {
1295 return Err(CoordinatorForwardingCutError::SourceIo(
1296 std::io::Error::last_os_error()
1297 .raw_os_error()
1298 .unwrap_or(libc::EIO),
1299 ));
1300 }
1301 if result != 1
1302 || poll.revents & libc::POLLIN == 0
1303 || poll.revents & (libc::POLLERR | libc::POLLNVAL) != 0
1304 {
1305 return Err(CoordinatorForwardingCutError::InvalidOwner);
1306 }
1307 Ok(())
1308}
1309
1310fn inspect_native_final_source(
1311 source: &mut ForwardedSource,
1312 identity: (u64, u64),
1313 owner: (i32, u64),
1314 completion: &dyn NativePhysicalExitCompletion,
1315) -> Result<(), CoordinatorForwardingCutError> {
1316 if (completion.process_id(), completion.birth_identity()) != owner {
1317 return Err(CoordinatorForwardingCutError::InvalidOwner);
1318 }
1319 verify_native_physical_completion(completion)?;
1320 if socket_identity(source.socket.as_raw_fd()) != Some(identity) {
1321 return Err(CoordinatorForwardingCutError::SourceChanged);
1322 }
1323 collect_forwarded(source);
1324 match source.transport_failure {
1327 Some(ForwardedSourceError::Closed) => {}
1328 Some(error) => return Err(error.into()),
1329 None => return Err(CoordinatorForwardingCutError::ClosedSource),
1330 }
1331 let mut poll = libc::pollfd {
1332 fd: source.socket.as_raw_fd(),
1333 events: libc::POLLIN,
1334 revents: 0,
1335 };
1336 let result = unsafe { libc::poll(&mut poll, 1, 0) };
1337 if result < 0 {
1338 return Err(CoordinatorForwardingCutError::SourceIo(
1339 std::io::Error::last_os_error()
1340 .raw_os_error()
1341 .unwrap_or(libc::EIO),
1342 ));
1343 }
1344 if result != 1
1345 || poll.revents & libc::POLLHUP == 0
1346 || poll.revents & (libc::POLLERR | libc::POLLNVAL) != 0
1347 {
1348 return Err(CoordinatorForwardingCutError::ClosedSource);
1349 }
1350 if source.loss_seen || source.order.legacy || source.order.ambiguous {
1351 return Err(CoordinatorForwardingCutError::DeterminismLoss);
1352 }
1353 for (tid, interval) in &source.order.received {
1354 if let Some((expected, sent)) = interval.out_of_sequence {
1355 return Err(CoordinatorForwardingCutError::OutOfSequence { expected, sent });
1356 }
1357 if interval.count != 0 {
1358 return Err(CoordinatorForwardingCutError::OtherOwnerPending(*tid));
1361 }
1362 }
1363 if let Some(tid) = source.order.pending.keys().next() {
1364 return Err(CoordinatorForwardingCutError::OtherOwnerPending(*tid));
1365 }
1366 Ok(())
1367}
1368
1369pub fn finish_native_forwarded_source_after_exit(
1375 expected: &NativeForwardedSourceReceipt,
1376 completion: &dyn NativePhysicalExitCompletion,
1377) -> Result<(), CoordinatorForwardingCutError> {
1378 let mut registered = FORWARDED_SOURCE.lock().unwrap();
1379 if FORWARDED_GENERATION.load(Ordering::SeqCst) != expected.generation {
1380 return Err(CoordinatorForwardingCutError::SourceChanged);
1381 }
1382 let source = registered
1383 .as_mut()
1384 .ok_or(CoordinatorForwardingCutError::MissingSource)?;
1385 if DETERMINISM_LOSS.lock().unwrap().is_some() {
1386 return Err(CoordinatorForwardingCutError::DeterminismLoss);
1387 }
1388 inspect_native_final_source(source, expected.identity, expected.owner, completion)?;
1389 FORWARDED_GENERATION.fetch_add(1, Ordering::SeqCst);
1390 stop_forwarded_receiver();
1391 registered.take();
1392 Ok(())
1393}
1394
1395pub fn drain_forwarded() {
1400 if let Some(source) = FORWARDED_SOURCE.lock().unwrap().as_mut() {
1401 collect_forwarded(source);
1402 }
1403}
1404
1405pub fn write_forwarded_for(tid: i32, exclusive: bool) {
1410 start_forwarded_receiver();
1411 if let Some(source) = FORWARDED_SOURCE.lock().unwrap().as_mut() {
1412 collect_forwarded(source);
1413 let records = source.order.at_commit(tid, exclusive);
1414 write_records(source, records);
1415 }
1416}
1417
1418pub fn drain_forwarded_at_request(tid: i32) {
1422 start_forwarded_receiver();
1423 if let Some(source) = FORWARDED_SOURCE.lock().unwrap().as_mut() {
1424 collect_forwarded(source);
1425 let records = source.order.at_request(tid);
1426 write_records(source, records);
1427 }
1428}
1429
1430pub fn check_forwarded_count(tid: i32, produced: u64) {
1445 if let Some(source) = FORWARDED_SOURCE.lock().unwrap().as_mut() {
1446 collect_forwarded(source);
1447 let interval = source.order.received_since_check(tid);
1448 if let Some(failure) = forwarded_count_failure(produced, interval) {
1449 report_forwarded_count_failure(source, tid, failure);
1450 }
1451 }
1452}
1453
1454#[derive(Clone, Copy, Debug, PartialEq, Eq)]
1455enum ForwardedCountFailure {
1456 Uncounted,
1457 Sequence { expected: u64, sent: u64 },
1458 Count { produced: u64, received: u64 },
1459}
1460
1461fn forwarded_count_failure(
1462 produced: u64,
1463 interval: ReceivedInterval,
1464) -> Option<ForwardedCountFailure> {
1465 if produced == UNCOUNTED {
1466 Some(ForwardedCountFailure::Uncounted)
1467 } else if let Some((expected, sent)) = interval.out_of_sequence {
1468 Some(ForwardedCountFailure::Sequence { expected, sent })
1469 } else if interval.count != produced {
1470 Some(ForwardedCountFailure::Count {
1471 produced,
1472 received: interval.count,
1473 })
1474 } else {
1475 None
1476 }
1477}
1478
1479fn report_forwarded_count_failure(
1480 source: &mut ForwardedSource,
1481 tid: i32,
1482 failure: ForwardedCountFailure,
1483) {
1484 let reason = match failure {
1485 ForwardedCountFailure::Uncounted => format!(
1486 "forwarded records uncounted: a guest thread's records could not be counted (reported by thread {tid})"
1487 ),
1488 ForwardedCountFailure::Sequence { expected, sent } if sent > expected => format!(
1489 "forwarded records lost: thread {tid} sent record {sent} of its interval where {expected} was next"
1490 ),
1491 ForwardedCountFailure::Sequence { expected, sent } => format!(
1492 "forwarded records not the Tool's: thread {tid} sent record {sent} of its interval where {expected} was next"
1493 ),
1494 ForwardedCountFailure::Count { produced, received } if received < produced => format!(
1495 "forwarded records lost: thread {tid} produced {produced} since its last counted request and {received} arrived"
1496 ),
1497 ForwardedCountFailure::Count { produced, received } => format!(
1498 "forwarded records not the Tool's: thread {tid} produced {produced} since its last counted request and {received} arrived"
1499 ),
1500 };
1501 record_determinism_loss(&reason);
1502 source.loss_seen = true;
1503 let line = format!("{FORWARDING_LOSS_NOTICE} 0 0 {reason}\n");
1504 (source.sink)(line.as_bytes());
1505}
1506
1507#[derive(Clone, Copy, Debug, PartialEq, Eq)]
1514pub struct CoordinatorForwardingReceipt {
1515 owner_tid: i32,
1516 generation: u64,
1517 socket_identity: (u64, u64),
1518}
1519
1520#[derive(Clone, Copy, Debug, PartialEq, Eq)]
1522pub enum CoordinatorForwardingCutError {
1523 InvalidOwner,
1525 MissingSource,
1527 SourceChanged,
1529 InvalidSource,
1531 ClosedSource,
1533 SourceIo(i32),
1535 SourcePoll(i16),
1537 MessageChanged,
1539 DeterminismLoss,
1541 Uncounted,
1543 OutOfSequence {
1545 expected: u64,
1547 sent: u64,
1549 },
1550 CountMismatch {
1552 produced: u64,
1554 received: u64,
1556 },
1557 OtherOwnerPending(i32),
1559 NotOwnerBoundary,
1561 PendingOwnerRecords,
1563}
1564
1565impl From<ForwardedSourceError> for CoordinatorForwardingCutError {
1566 fn from(error: ForwardedSourceError) -> Self {
1567 match error {
1568 ForwardedSourceError::Closed => Self::ClosedSource,
1569 ForwardedSourceError::Io(errno) => Self::SourceIo(errno),
1570 ForwardedSourceError::Poll(flags) => Self::SourcePoll(flags),
1571 ForwardedSourceError::MessageChanged => Self::MessageChanged,
1572 }
1573 }
1574}
1575
1576impl From<ForwardedCountFailure> for CoordinatorForwardingCutError {
1577 fn from(error: ForwardedCountFailure) -> Self {
1578 match error {
1579 ForwardedCountFailure::Uncounted => Self::Uncounted,
1580 ForwardedCountFailure::Sequence { expected, sent } => {
1581 Self::OutOfSequence { expected, sent }
1582 }
1583 ForwardedCountFailure::Count { produced, received } => {
1584 Self::CountMismatch { produced, received }
1585 }
1586 }
1587 }
1588}
1589
1590pub fn check_native_exec_forwarding_cut(
1607 owner_tid: i32,
1608 produced: u64,
1609 previous: Option<&CoordinatorForwardingReceipt>,
1610) -> Result<CoordinatorForwardingReceipt, CoordinatorForwardingCutError> {
1611 let mut source = FORWARDED_SOURCE.lock().unwrap();
1612 let generation = FORWARDED_GENERATION.load(Ordering::SeqCst);
1613 inspect_coordinator_forwarding_cut(
1614 source.as_mut(),
1615 generation,
1616 owner_tid,
1617 produced,
1618 previous,
1619 || DETERMINISM_LOSS.lock().unwrap().is_some(),
1620 )
1621}
1622
1623fn source_identity_for_cut(
1624 source: &mut ForwardedSource,
1625) -> Result<(u64, u64), CoordinatorForwardingCutError> {
1626 if let Some(error) = source.transport_failure {
1627 return Err(error.into());
1628 }
1629 let fd = source.socket.as_raw_fd();
1630 let identity = socket_identity(fd).ok_or(CoordinatorForwardingCutError::InvalidSource)?;
1631 let mut kind = 0i32;
1632 let mut length;
1633 loop {
1634 length = std::mem::size_of_val(&kind) as libc::socklen_t;
1635 let result = unsafe {
1637 libc::getsockopt(
1638 fd,
1639 libc::SOL_SOCKET,
1640 libc::SO_TYPE,
1641 (&mut kind as *mut i32).cast(),
1642 &mut length,
1643 )
1644 };
1645 if result >= 0 {
1646 break;
1647 }
1648 let errno = std::io::Error::last_os_error().raw_os_error().unwrap();
1649 if errno == libc::EINTR {
1650 continue;
1651 }
1652 let error = ForwardedSourceError::Io(errno);
1653 source.transport_failure = Some(error);
1654 return Err(error.into());
1655 }
1656 if length as usize != std::mem::size_of_val(&kind) || kind != libc::SOCK_SEQPACKET {
1657 return Err(CoordinatorForwardingCutError::InvalidSource);
1658 }
1659 let mut peer: libc::sockaddr_storage = unsafe { std::mem::zeroed() };
1661 loop {
1662 length = std::mem::size_of_val(&peer) as libc::socklen_t;
1663 let result = unsafe {
1665 libc::getpeername(
1666 fd,
1667 (&mut peer as *mut libc::sockaddr_storage).cast(),
1668 &mut length,
1669 )
1670 };
1671 if result >= 0 {
1672 break;
1673 }
1674 let errno = std::io::Error::last_os_error().raw_os_error().unwrap();
1675 if errno == libc::EINTR {
1676 continue;
1677 }
1678 let error = ForwardedSourceError::Io(errno);
1679 source.transport_failure = Some(error);
1680 return Err(error.into());
1681 }
1682 if (length as usize) < std::mem::size_of_val(&peer.ss_family)
1683 || i32::from(peer.ss_family) != libc::AF_UNIX
1684 {
1685 return Err(CoordinatorForwardingCutError::InvalidSource);
1686 }
1687 let mut poll = libc::pollfd {
1688 fd,
1689 events: libc::POLLIN | libc::POLLRDHUP,
1690 revents: 0,
1691 };
1692 loop {
1693 let result = unsafe { libc::poll(&mut poll, 1, 0) };
1695 if result < 0 {
1696 let errno = std::io::Error::last_os_error().raw_os_error().unwrap();
1697 if errno == libc::EINTR {
1698 continue;
1699 }
1700 let error = ForwardedSourceError::Io(errno);
1701 source.transport_failure = Some(error);
1702 return Err(error.into());
1703 }
1704 let error = if poll.revents & (libc::POLLHUP | libc::POLLRDHUP) != 0 {
1705 Some(ForwardedSourceError::Closed)
1706 } else if poll.revents & (libc::POLLERR | libc::POLLNVAL) != 0 {
1707 Some(ForwardedSourceError::Poll(poll.revents))
1708 } else {
1709 None
1710 };
1711 if let Some(error) = error {
1712 source.transport_failure = Some(error);
1713 return Err(error.into());
1714 }
1715 return Ok(identity);
1716 }
1717}
1718
1719fn check_cut_state(
1720 source: &ForwardedSource,
1721 owner_tid: i32,
1722 has_loss: &impl Fn() -> bool,
1723) -> Result<(), CoordinatorForwardingCutError> {
1724 if has_loss() || source.loss_seen || source.order.legacy || source.order.ambiguous {
1725 return Err(CoordinatorForwardingCutError::DeterminismLoss);
1726 }
1727 if let Some((&tid, _)) = source
1728 .order
1729 .pending
1730 .iter()
1731 .find(|(tid, records)| **tid != owner_tid && !records.is_empty())
1732 {
1733 return Err(CoordinatorForwardingCutError::OtherOwnerPending(tid));
1734 }
1735 if let Some((&tid, _)) = source
1736 .order
1737 .received
1738 .iter()
1739 .find(|(tid, _)| **tid != owner_tid)
1740 {
1741 return Err(CoordinatorForwardingCutError::OtherOwnerPending(tid));
1742 }
1743 match source.order.runner {
1744 Runner::NoTurnYet => Ok(()),
1745 Runner::Root(tid) | Runner::Exclusive(tid) if tid == owner_tid => Ok(()),
1746 _ => Err(CoordinatorForwardingCutError::NotOwnerBoundary),
1747 }
1748}
1749
1750fn inspect_coordinator_forwarding_cut(
1751 source: Option<&mut ForwardedSource>,
1752 generation: u64,
1753 owner_tid: i32,
1754 produced: u64,
1755 previous: Option<&CoordinatorForwardingReceipt>,
1756 has_loss: impl Fn() -> bool,
1757) -> Result<CoordinatorForwardingReceipt, CoordinatorForwardingCutError> {
1758 if owner_tid <= 0 {
1759 return Err(CoordinatorForwardingCutError::InvalidOwner);
1760 }
1761 let source = source.ok_or(CoordinatorForwardingCutError::MissingSource)?;
1762 let receipt = CoordinatorForwardingReceipt {
1763 owner_tid,
1764 generation,
1765 socket_identity: source_identity_for_cut(source)?,
1766 };
1767 if previous.is_some_and(|previous| *previous != receipt) {
1768 return Err(CoordinatorForwardingCutError::SourceChanged);
1769 }
1770 collect_forwarded(source);
1771 source_identity_for_cut(source)?;
1772 check_cut_state(source, owner_tid, &has_loss)?;
1773 let interval = source
1774 .order
1775 .received
1776 .get(&owner_tid)
1777 .copied()
1778 .unwrap_or_default();
1779 if let Some(failure) = forwarded_count_failure(produced, interval) {
1780 report_forwarded_count_failure(source, owner_tid, failure);
1781 return Err(failure.into());
1782 }
1783 let records = source.order.at_request(owner_tid);
1784 for record in &records {
1785 emit(source, record);
1786 }
1787 collect_forwarded(source);
1790 let final_check = (|| {
1791 if source_identity_for_cut(source)? != receipt.socket_identity {
1792 return Err(CoordinatorForwardingCutError::SourceChanged);
1793 }
1794 check_cut_state(source, owner_tid, &has_loss)?;
1795 let current = source
1796 .order
1797 .received
1798 .get(&owner_tid)
1799 .copied()
1800 .unwrap_or_default();
1801 if let Some(failure) = forwarded_count_failure(produced, current) {
1802 report_forwarded_count_failure(source, owner_tid, failure);
1803 return Err(failure.into());
1804 }
1805 if source
1806 .order
1807 .pending
1808 .get(&owner_tid)
1809 .is_some_and(|records| !records.is_empty())
1810 {
1811 return Err(CoordinatorForwardingCutError::PendingOwnerRecords);
1812 }
1813 Ok(())
1814 })();
1815 if let Err(error) = final_check {
1816 if !records.is_empty() {
1819 let mut retained = records;
1820 if let Some(mut later) = source.order.pending.remove(&owner_tid) {
1821 retained.append(&mut later);
1822 }
1823 source.order.pending.insert(owner_tid, retained);
1824 }
1825 return Err(error);
1826 }
1827 source.order.received_since_check(owner_tid);
1828 Ok(receipt)
1829}
1830
1831fn write_records(source: &mut ForwardedSource, records: Vec<Vec<u8>>) {
1832 for record in records {
1833 emit(source, &record);
1834 }
1835}
1836
1837fn collect_forwarded(source: &mut ForwardedSource) {
1838 let fd = source.socket.as_raw_fd();
1839 let mut buffer = Vec::new();
1840 loop {
1841 let size = unsafe {
1845 libc::recv(
1846 fd,
1847 std::ptr::null_mut(),
1848 0,
1849 libc::MSG_PEEK | libc::MSG_TRUNC | libc::MSG_DONTWAIT,
1850 )
1851 };
1852 if size < 0 {
1853 let errno = std::io::Error::last_os_error().raw_os_error().unwrap();
1854 if errno == libc::EINTR {
1855 continue;
1856 }
1857 if errno != libc::EAGAIN && errno != libc::EWOULDBLOCK {
1858 source
1859 .transport_failure
1860 .get_or_insert(ForwardedSourceError::Io(errno));
1861 }
1862 return;
1863 }
1864 if size == 0 {
1865 source
1866 .transport_failure
1867 .get_or_insert(ForwardedSourceError::Closed);
1868 return;
1869 }
1870 buffer.resize(size as usize, 0);
1871 let received = loop {
1873 let received = unsafe {
1874 libc::recv(
1875 fd,
1876 buffer.as_mut_ptr().cast::<libc::c_void>(),
1877 buffer.len(),
1878 libc::MSG_DONTWAIT | libc::MSG_TRUNC,
1879 )
1880 };
1881 if received < 0 && std::io::Error::last_os_error().raw_os_error() == Some(libc::EINTR) {
1882 continue;
1883 }
1884 break received;
1885 };
1886 if received < 0 {
1887 let errno = std::io::Error::last_os_error().raw_os_error().unwrap();
1888 let error = if errno == libc::EAGAIN || errno == libc::EWOULDBLOCK {
1889 ForwardedSourceError::MessageChanged
1890 } else {
1891 ForwardedSourceError::Io(errno)
1892 };
1893 source.transport_failure.get_or_insert(error);
1894 return;
1895 }
1896 if received == 0 {
1897 source
1898 .transport_failure
1899 .get_or_insert(ForwardedSourceError::Closed);
1900 return;
1901 }
1902 if received != size {
1903 source
1904 .transport_failure
1905 .get_or_insert(ForwardedSourceError::MessageChanged);
1906 }
1907 let message = &buffer[..(received as usize).min(buffer.len())];
1911 match split_forwarded_message(message) {
1912 Some((tid, index, record)) => {
1913 source.order.arrived(tid, index);
1914 source.order.queue(tid, record.to_vec());
1915 }
1916 None => {
1917 for record in source.order.untagged(message) {
1918 emit(source, &record);
1919 }
1920 }
1921 }
1922 }
1923}
1924
1925#[doc(hidden)]
1928pub fn forwards_target(target: &str) -> bool {
1929 FORWARDER
1930 .get()
1931 .is_some_and(|(_, policy)| policy.forwards(target))
1932}
1933
1934#[doc(hidden)]
1938pub fn emit_forwarded(target: &str, record_suffix: &str, message: fmt::Arguments<'_>) {
1939 tracing::info!("DETLOG {}{}", message, record_suffix);
1940 let index = count_forwarded();
1941 FORWARDER.get().expect("forwarder disappeared").0(target, record_suffix, index, message);
1942}
1943
1944struct ForwardedCount {
1947 tid: AtomicI32,
1948 pid: AtomicI32,
1951 count: AtomicU64,
1952}
1953
1954static FORWARDED_COUNTS: [ForwardedCount; 512] = [const {
1962 ForwardedCount {
1963 tid: AtomicI32::new(0),
1964 pid: AtomicI32::new(0),
1965 count: AtomicU64::new(0),
1966 }
1967}; 512];
1968
1969static FORWARDING_UNCOUNTED: std::sync::atomic::AtomicBool =
1971 std::sync::atomic::AtomicBool::new(false);
1972
1973static FORWARDING_STARTED: std::sync::atomic::AtomicBool =
1980 std::sync::atomic::AtomicBool::new(false);
1981
1982#[derive(Clone, Copy, Debug, Eq, PartialEq)]
1984pub enum ForwardingCutError {
1985 Uncounted,
1987 UnreportedLosses(u64),
1989 PendingRecords {
1991 pid: i32,
1993 tid: i32,
1995 count: u64,
1997 },
1998}
1999
2000pub fn check_empty_forwarding_cut() -> Result<(), ForwardingCutError> {
2011 inspect_empty_forwarding_cut(
2012 &FORWARDED_COUNTS,
2013 FORWARDING_UNCOUNTED.load(Ordering::Acquire),
2014 UNREPORTED_LOSSES.load(Ordering::Acquire),
2015 )
2016}
2017
2018fn inspect_empty_forwarding_cut(
2019 slots: &[ForwardedCount],
2020 uncounted: bool,
2021 losses: u64,
2022) -> Result<(), ForwardingCutError> {
2023 if uncounted {
2024 return Err(ForwardingCutError::Uncounted);
2025 }
2026 if losses != 0 {
2027 return Err(ForwardingCutError::UnreportedLosses(losses));
2028 }
2029 for slot in slots {
2030 let count = slot.count.load(Ordering::Acquire);
2031 if count != 0 {
2032 return Err(ForwardingCutError::PendingRecords {
2033 pid: slot.pid.load(Ordering::Acquire),
2034 tid: slot.tid.load(Ordering::Acquire),
2035 count,
2036 });
2037 }
2038 }
2039 Ok(())
2040}
2041
2042pub const UNCOUNTED: u64 = u64::MAX;
2045
2046fn current_pid() -> i32 {
2047 unsafe { crate::util::raw_syscall(libc::SYS_getpid, [0; 6]) as i32 }
2051}
2052
2053fn forwarded_count_slot(tid: i32) -> Option<&'static ForwardedCount> {
2054 let pid = current_pid();
2055 let start = tid.unsigned_abs() as usize % FORWARDED_COUNTS.len();
2056 let probe = || {
2057 (0..FORWARDED_COUNTS.len())
2058 .map(move |offset| &FORWARDED_COUNTS[(start + offset) % FORWARDED_COUNTS.len()])
2059 };
2060 let claim = |slot: &'static ForwardedCount, owner: i32| {
2061 if slot
2062 .tid
2063 .compare_exchange(owner, tid, Ordering::AcqRel, Ordering::Acquire)
2064 .is_ok()
2065 {
2066 slot.pid.store(pid, Ordering::Release);
2067 slot.count.store(0, Ordering::Release);
2068 true
2069 } else {
2070 false
2071 }
2072 };
2073 if let Some(slot) = FORWARDED_COUNTS.iter().find(|slot| {
2076 slot.tid.load(Ordering::Acquire) == tid && slot.pid.load(Ordering::Acquire) == pid
2077 }) {
2078 return Some(slot);
2079 }
2080 for slot in probe() {
2081 if slot.tid.load(Ordering::Acquire) == 0 && claim(slot, 0) {
2082 return Some(slot);
2083 }
2084 }
2085 for slot in probe() {
2090 let owner = slot.tid.load(Ordering::Acquire);
2091 let owner_pid = slot.pid.load(Ordering::Acquire);
2092 if owner != 0 && owner_pid != pid && private_copy(owner_pid, pid) && claim(slot, owner) {
2093 return Some(slot);
2094 }
2095 }
2096 None
2097}
2098
2099fn private_copy(owner: i32, pid: i32) -> bool {
2105 const KCMP_VM: libc::c_int = 1;
2106 let answer = unsafe { libc::syscall(libc::SYS_kcmp, owner, pid, KCMP_VM, 0, 0) };
2108 answer > 0
2109 || (answer < 0 && std::io::Error::last_os_error().raw_os_error() == Some(libc::ESRCH))
2110}
2111
2112fn count_forwarded() -> u64 {
2116 if !FORWARDING_STARTED.load(Ordering::Acquire) {
2119 FORWARDING_STARTED.store(true, Ordering::Release);
2120 }
2121 match forwarded_count_slot(current_tid()) {
2122 Some(slot) => slot.count.fetch_add(1, Ordering::AcqRel) + 1,
2123 None => {
2124 FORWARDING_UNCOUNTED.store(true, Ordering::Release);
2125 0
2126 }
2127 }
2128}
2129
2130pub fn take_forwarded_since_request() -> u64 {
2136 if FORWARDING_UNCOUNTED.load(Ordering::Acquire) {
2137 return UNCOUNTED;
2138 }
2139 if !FORWARDING_STARTED.load(Ordering::Acquire) {
2142 return 0;
2143 }
2144 forwarded_count_slot(current_tid())
2145 .map(|slot| slot.count.swap(0, Ordering::AcqRel))
2146 .unwrap_or(0)
2147}
2148
2149pub fn require_forwarding(expected: &str) {
2156 if FORWARDER
2157 .get()
2158 .is_none_or(|(_, policy)| policy.encode() != expected)
2159 {
2160 FORWARDING_UNCOUNTED.store(true, Ordering::Release);
2161 }
2162}
2163
2164pub fn release_forwarded_count() {
2167 if FORWARDING_STARTED.load(Ordering::Acquire) {
2168 release_count_slot(current_tid());
2169 }
2170}
2171
2172fn release_count_slot(tid: i32) {
2173 let pid = current_pid();
2174 for slot in &FORWARDED_COUNTS {
2175 if slot.tid.load(Ordering::Acquire) == tid && slot.pid.load(Ordering::Acquire) == pid {
2176 slot.count.store(0, Ordering::Release);
2177 let _ = slot
2178 .tid
2179 .compare_exchange(tid, 0, Ordering::AcqRel, Ordering::Acquire);
2180 }
2181 }
2182}
2183
2184pub(crate) fn root_seed_records(tid: i32, user_seed: u64, chaos_seed: u64) {
2188 const TARGET: &str = "detcore::tool_local";
2189 macro_rules! seed {
2190 ($format:literal, $value:expr) => {{
2191 if forwards_target(TARGET) {
2192 let suffix = record_suffix(DetLogEvent::Other);
2193 let index = count_forwarded();
2194 FORWARDER.get().expect("forwarder disappeared").0(
2195 TARGET, &suffix, index, format_args!($format, $value, tid));
2196 } else {
2197 tracing::info!(target: "detcore::tool_local", parent: None,
2198 "DETLOG {}{}", format_args!($format, $value, tid),
2199 record_suffix(DetLogEvent::Other));
2200 }
2201 }};
2202 }
2203 seed!(
2204 "USER RAND: seeding PRNG for root thread with seed {} (root tid {})",
2205 user_seed
2206 );
2207 seed!(
2208 "CHAOSRAND: seeding chaos scheduler with seed {} (root tid {})",
2209 chaos_seed
2210 );
2211}
2212
2213pub fn forward_tail_start(tid: reverie::Pid, number: reverie::syscalls::Sysno) {
2216 emit_plain_info(
2217 "reverie::guest",
2218 format_args!("[tool] (tid {}) admitted tail syscall: {}", tid, number),
2219 );
2220}
2221
2222#[macro_export]
2225macro_rules! detlog {
2226 (event = $event:expr; $($arg:tt)+) => {{
2227 if $crate::detlog::forwards_target(::core::module_path!())
2228 || ::tracing::enabled!(::tracing::Level::INFO)
2229 {
2230 let record_suffix = $crate::detlog::record_suffix($event);
2231 if $crate::detlog::forwards_target(::core::module_path!()) {
2232 $crate::detlog::emit_forwarded(
2233 ::core::module_path!(),
2234 &record_suffix,
2235 format_args!($($arg)+),
2236 );
2237 } else {
2238 ::tracing::info!("DETLOG {}{}", format_args!($($arg)+), record_suffix);
2239 }
2240 }
2241 }};
2242 ($($arg:tt)+) => {{
2243 $crate::detlog!(event = $crate::detlog::DetLogEvent::Other; $($arg)+);
2244 }};
2245}
2246
2247#[macro_export]
2267macro_rules! detlog_observed {
2268 () => {
2269 $crate::detlog::forwards_target(::core::module_path!())
2270 || ::tracing::enabled!(::tracing::Level::INFO)
2271 };
2272}
2273
2274#[macro_export]
2278macro_rules! detlog_debug {
2279 (event = $event:expr; $($arg:tt)+) => {{
2280 if ::tracing::enabled!(::tracing::Level::DEBUG) {
2281 let record_suffix = $crate::detlog::record_suffix($event);
2282 ::tracing::debug!("DETLOG {}{}", format_args!($($arg)+), record_suffix);
2283 }
2284 }};
2285 ($($arg:tt)+) => {{
2286 $crate::detlog_debug!(event = $crate::detlog::DetLogEvent::Other; $($arg)+);
2287 }};
2288}
2289
2290#[cfg(test)]
2291mod tests {
2292 use std::sync::atomic::Ordering;
2293
2294 use tracing::Metadata;
2295 use tracing::span;
2296 use tracing::subscriber::Interest;
2297
2298 use super::DetLogEvent;
2299 use super::DetLogRecord;
2300 use super::ForwardPolicy;
2301 use super::RECORD_SEPARATOR;
2302 use super::record_suffix;
2303
2304 #[test]
2305 fn explicit_plain_emitter_preserves_default_tracing_and_shared_socket_counts() {
2306 const NAME: &str = "detlog::tests::explicit_plain_emitter_preserves_default_tracing_and_shared_socket_counts";
2309 const CHILD: &str = "HERMIT_TWO_SITE_INFO_TEST";
2310 if std::env::var(CHILD).ok().as_deref() != Some(NAME) {
2311 let mut child = std::process::Command::new(std::env::current_exe().unwrap())
2312 .args(["--exact", NAME])
2313 .env(CHILD, NAME)
2314 .stdout(std::process::Stdio::piped())
2315 .stderr(std::process::Stdio::piped())
2316 .spawn()
2317 .unwrap();
2318 let deadline = std::time::Instant::now() + std::time::Duration::from_secs(10);
2319 loop {
2320 if let Some(status) = child.try_wait().unwrap() {
2321 let output = child.wait_with_output().unwrap();
2322 assert!(
2323 status.success(),
2324 "{}",
2325 String::from_utf8_lossy(&output.stderr)
2326 );
2327 assert!(
2328 String::from_utf8_lossy(&output.stdout)
2329 .lines()
2330 .any(|line| line == format!("test {NAME} ... ok"))
2331 );
2332 return;
2333 }
2334 if std::time::Instant::now() >= deadline {
2335 child.kill().unwrap();
2336 child.wait().unwrap();
2337 panic!("plain emitter control timed out");
2338 }
2339 std::thread::sleep(std::time::Duration::from_millis(10));
2340 }
2341 }
2342 use std::os::fd::AsRawFd;
2343 use std::os::fd::FromRawFd;
2344 use std::os::fd::OwnedFd;
2345 use std::sync::Arc;
2346 use std::sync::Mutex;
2347
2348 use tracing::Event;
2349 use tracing::Metadata;
2350 use tracing::Subscriber;
2351 use tracing::span;
2352 struct Message(String);
2353 impl tracing::field::Visit for Message {
2354 fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
2355 assert_eq!(field.name(), "message");
2356 self.0 = format!("{value:?}");
2357 }
2358 }
2359 struct Capture(Arc<Mutex<Vec<(String, String)>>>);
2360 impl Subscriber for Capture {
2361 fn enabled(&self, _: &Metadata<'_>) -> bool {
2362 true
2363 }
2364 fn new_span(&self, _: &span::Attributes<'_>) -> span::Id {
2365 span::Id::from_u64(1)
2366 }
2367 fn record(&self, _: &span::Id, _: &span::Record<'_>) {}
2368 fn record_follows_from(&self, _: &span::Id, _: &span::Id) {}
2369 fn event(&self, event: &Event<'_>) {
2370 let mut message = Message(String::new());
2371 event.record(&mut message);
2372 self.0
2373 .lock()
2374 .unwrap()
2375 .push((event.metadata().target().to_owned(), message.0));
2376 }
2377 fn enter(&self, _: &span::Id) {}
2378 fn exit(&self, _: &span::Id) {}
2379 }
2380 static SOCKET: std::sync::atomic::AtomicI32 = std::sync::atomic::AtomicI32::new(-1);
2381 fn plain(target: &str, index: u64, message: std::fmt::Arguments<'_>) {
2382 let fd = SOCKET.load(Ordering::Acquire);
2383 super::send_plain_info_record((fd >= 0).then_some(fd), target, index, message);
2384 }
2385 fn legacy(target: &str, suffix: &str, index: u64, message: std::fmt::Arguments<'_>) {
2386 super::send_forwarded_record(
2387 SOCKET.load(Ordering::Acquire),
2388 target,
2389 suffix,
2390 index,
2391 message,
2392 );
2393 }
2394 let captured = Arc::new(Mutex::new(Vec::new()));
2395 assert!(!super::plain_info_forwarding());
2396 assert!(
2397 super::set_plain_info_forwarder(plain).is_err(),
2398 "must not activate without real counted policy"
2399 );
2400 tracing::subscriber::with_default(Capture(captured.clone()), || {
2401 crate::ordered_info!(
2402 "Injecting additional fstat to retrieve file metadata on fd {}.",
2403 3
2404 );
2405 });
2406 assert_eq!(
2407 *captured.lock().unwrap(),
2408 vec![(
2409 module_path!().to_owned(),
2410 "Injecting additional fstat to retrieve file metadata on fd 3.".to_owned()
2411 )]
2412 );
2413 assert_eq!(super::take_forwarded_since_request(), 0);
2414 let mut fds = [-1; 2];
2415 assert_eq!(
2418 unsafe {
2419 libc::socketpair(
2420 libc::AF_UNIX,
2421 libc::SOCK_SEQPACKET | libc::SOCK_CLOEXEC,
2422 0,
2423 fds.as_mut_ptr(),
2424 )
2425 },
2426 0
2427 );
2428 let sender = unsafe { OwnedFd::from_raw_fd(fds[0]) };
2429 let receiver = unsafe { OwnedFd::from_raw_fd(fds[1]) };
2430 SOCKET.store(sender.as_raw_fd(), Ordering::Release);
2431 super::set_forwarder(
2432 legacy,
2433 ForwardPolicy::decode("1,detcore::blocked=0").unwrap(),
2434 )
2435 .unwrap();
2436 assert!(!super::plain_info_forwarding());
2438 super::set_plain_info_forwarder(plain).unwrap();
2439 assert!(super::set_plain_info_forwarder(plain).is_err());
2440 tracing::subscriber::with_default(Capture(captured.clone()), || {
2441 crate::ordered_info!("[dtid {}] inbound rdtsc, new logical time: {:?}", 3, 17);
2442 super::emit_forwarded("detcore", "", format_args!("middle"));
2443 crate::ordered_info!(
2444 "Injecting additional fstat to retrieve file metadata on fd {}.",
2445 3
2446 );
2447 super::emit_plain_info("detcore::blocked", format_args!("filtered"));
2448 });
2449 assert_eq!(captured.lock().unwrap().len(), 2);
2452 fn receive(fd: i32, index: u64) -> Vec<u8> {
2453 let mut bytes = [0; 65536];
2454 let n = unsafe {
2456 libc::recv(
2457 fd,
2458 bytes.as_mut_ptr().cast(),
2459 bytes.len(),
2460 libc::MSG_DONTWAIT,
2461 )
2462 };
2463 assert!(n > 0);
2464 let (tid, got, payload) = super::split_forwarded_message(&bytes[..n as usize]).unwrap();
2465 assert_eq!(tid, super::current_tid());
2466 assert_eq!(got, index);
2467 payload.to_vec()
2468 }
2469 assert_eq!(
2470 super::decode_plain_info(&receive(receiver.as_raw_fd(), 1)).unwrap(),
2471 (
2472 module_path!(),
2473 "[dtid 3] inbound rdtsc, new logical time: 17"
2474 )
2475 );
2476 assert_eq!(
2477 receive(receiver.as_raw_fd(), 2),
2478 b"INFO detcore: DETLOG middle\n"
2479 );
2480 assert_eq!(
2481 super::decode_plain_info(&receive(receiver.as_raw_fd(), 3)).unwrap(),
2482 (
2483 module_path!(),
2484 "Injecting additional fstat to retrieve file metadata on fd 3."
2485 )
2486 );
2487 assert_eq!(super::take_forwarded_since_request(), 3);
2488 super::emit_plain_info(module_path!(), format_args!("bad\nline"));
2490 assert!(
2491 receive(receiver.as_raw_fd(), 1).starts_with(super::FORWARDING_LOSS_NOTICE.as_bytes())
2492 );
2493 assert_eq!(super::take_forwarded_since_request(), 1);
2494 super::emit_plain_info(
2495 module_path!(),
2496 format_args!("{}", "x".repeat(super::PLAIN_INFO_MAX)),
2497 );
2498 assert!(
2499 receive(receiver.as_raw_fd(), 1).starts_with(super::FORWARDING_LOSS_NOTICE.as_bytes())
2500 );
2501 assert_eq!(super::take_forwarded_since_request(), 1);
2502 SOCKET.store(-1, Ordering::Release);
2503 super::emit_plain_info(module_path!(), format_args!("identity missing"));
2504 assert_eq!(
2505 super::take_forwarded_since_request(),
2506 1,
2507 "missing socket cannot erase the produced index"
2508 );
2509 let mut byte = 0u8;
2510 assert_eq!(
2511 unsafe {
2512 libc::recv(
2513 receiver.as_raw_fd(),
2514 (&raw mut byte).cast(),
2515 1,
2516 libc::MSG_DONTWAIT,
2517 )
2518 },
2519 -1
2520 );
2521 assert_eq!(
2522 std::io::Error::last_os_error().raw_os_error(),
2523 Some(libc::EAGAIN)
2524 );
2525 }
2526
2527 #[test]
2528 fn plain_info_codec_preserves_the_original_target_and_message_only() {
2529 let bytes = super::encode_plain_info(
2530 "detcore::syscalls::files",
2531 "Injecting additional fstat on fd 3.",
2532 )
2533 .unwrap();
2534 assert!(bytes.starts_with(b"HINFO\0\0\0\x01\x01\x03\0"));
2535 assert_eq!(
2536 super::decode_plain_info(&bytes),
2537 Ok((
2538 "detcore::syscalls::files",
2539 "Injecting additional fstat on fd 3."
2540 ))
2541 );
2542 let ordinary =
2543 super::encode_plain_info("detcore", "DETLOG is just this ordinary message").unwrap();
2544 assert_eq!(
2545 super::decode_plain_info(&ordinary).unwrap().1,
2546 "DETLOG is just this ordinary message"
2547 );
2548 }
2549
2550 #[test]
2551 fn plain_info_codec_rejects_classes_lengths_and_utf8_without_fallback() {
2552 let valid = super::encode_plain_info("detcore", "message").unwrap();
2553 for length in 0..valid.len() {
2554 assert!(
2555 super::decode_plain_info(&valid[..length]).is_err(),
2556 "truncation {length}"
2557 );
2558 }
2559 for offset in [0, 7, 8, 9, 10, 11] {
2560 let mut changed = valid.clone();
2561 changed[offset] ^= 0x80;
2562 assert!(
2563 super::decode_plain_info(&changed).is_err(),
2564 "header {offset}"
2565 );
2566 }
2567 for field in [12, 16] {
2568 let mut changed = valid.clone();
2569 changed[field..field + 4].copy_from_slice(&u32::MAX.to_le_bytes());
2570 assert!(super::decode_plain_info(&changed).is_err());
2571 }
2572 let mut extra = valid.clone();
2573 extra.push(0);
2574 assert!(super::decode_plain_info(&extra).is_err());
2575 let mut utf8 = valid;
2576 *utf8.last_mut().unwrap() = 0xff;
2577 assert!(super::decode_plain_info(&utf8).is_err());
2578 assert!(super::decode_plain_info(b"INFO detcore: arbitrary raw text\n").is_err());
2579 }
2580
2581 #[test]
2582 fn plain_info_codec_limits_and_target_contract_are_exact() {
2583 let allowed =
2584 "x".repeat(super::PLAIN_INFO_MAX - super::PLAIN_INFO_HEADER - "detcore".len());
2585 let encoded = super::encode_plain_info("detcore", &allowed).unwrap();
2586 assert_eq!(encoded.len(), super::PLAIN_INFO_MAX);
2587 assert_eq!(super::decode_plain_info(&encoded).unwrap().1, allowed);
2588 assert!(super::encode_plain_info("detcore", &(allowed + "x")).is_err());
2589 for target in [
2590 "",
2591 "other",
2592 "detcore_bad",
2593 "detcore::",
2594 "detcore:::x",
2595 "detcore::x::",
2596 "detcore::x y",
2597 ] {
2598 assert!(
2599 super::encode_plain_info(target, "text").is_err(),
2600 "{target}"
2601 );
2602 }
2603 for message in ["a\nb", "a\rb", "a\0b"] {
2604 assert!(super::encode_plain_info("detcore", message).is_err());
2605 }
2606 }
2607
2608 #[test]
2609 fn plain_info_admission_refuses_span_field_and_invalid_filter_directives() {
2610 for directives in [
2611 "",
2612 "debug",
2613 "warn,detcore::syscalls=info",
2614 "off,detcore::a=trace",
2615 "detcore",
2616 ] {
2617 assert_eq!(
2618 super::validate_plain_info_directives(directives),
2619 Ok(()),
2620 "{directives}"
2621 );
2622 }
2623 for directives in [
2624 "[syscall.intercept]=info",
2625 "detcore[{fd}]=info",
2626 "detcore[span{fd=3}]=info",
2627 "detcore=bogus",
2628 "=info",
2629 "detcore=info=debug",
2630 ] {
2631 assert!(
2632 super::validate_plain_info_directives(directives).is_err(),
2633 "{directives}"
2634 );
2635 }
2636 }
2637
2638 #[test]
2639 fn native_exec_forwarding_cut_refuses_retained_records_and_loss_state_without_resetting() {
2640 use std::sync::atomic::AtomicI32;
2641 use std::sync::atomic::AtomicU64;
2642
2643 use super::ForwardedCount;
2644 use super::ForwardingCutError;
2645 use super::inspect_empty_forwarding_cut;
2646
2647 let slots = [ForwardedCount {
2648 pid: AtomicI32::new(41),
2649 tid: AtomicI32::new(43),
2650 count: AtomicU64::new(0),
2651 }];
2652 assert_eq!(inspect_empty_forwarding_cut(&slots, false, 0), Ok(()));
2653 slots[0].count.store(3, Ordering::Release);
2654 for _ in 0..2 {
2655 assert_eq!(
2656 inspect_empty_forwarding_cut(&slots, false, 0),
2657 Err(ForwardingCutError::PendingRecords {
2658 pid: 41,
2659 tid: 43,
2660 count: 3,
2661 })
2662 );
2663 assert_eq!(slots[0].count.load(Ordering::Acquire), 3);
2664 }
2665 slots[0].tid.store(0, Ordering::Release);
2667 assert!(matches!(
2668 inspect_empty_forwarding_cut(&slots, false, 0),
2669 Err(ForwardingCutError::PendingRecords {
2670 tid: 0,
2671 count: 3,
2672 ..
2673 })
2674 ));
2675 assert_eq!(
2676 inspect_empty_forwarding_cut(&slots, true, 0),
2677 Err(ForwardingCutError::Uncounted)
2678 );
2679 assert_eq!(
2680 inspect_empty_forwarding_cut(&slots, false, 2),
2681 Err(ForwardingCutError::UnreportedLosses(2))
2682 );
2683 assert_eq!(slots[0].count.load(Ordering::Acquire), 3);
2684 slots[0].count.store(0, Ordering::Release);
2685 assert_eq!(inspect_empty_forwarding_cut(&slots, false, 0), Ok(()));
2686 slots[0].count.store(1, Ordering::Release);
2689 assert!(matches!(
2690 inspect_empty_forwarding_cut(&slots, false, 0),
2691 Err(ForwardingCutError::PendingRecords { count: 1, .. })
2692 ));
2693 }
2694
2695 fn isolated_child(case: &str) -> bool {
2708 const CHILD: &str = "HERMIT_DETLOG_NATIVE_CUT_CHILD";
2709 if std::env::var_os(CHILD).as_deref() == Some(std::ffi::OsStr::new(case)) {
2710 return false;
2711 }
2712 let output = std::process::Command::new(std::env::current_exe().unwrap())
2713 .args(["--exact", case, "--nocapture", "--test-threads=1"])
2714 .env(CHILD, case)
2715 .output()
2716 .unwrap();
2717 assert!(output.status.success(), "{output:?}");
2718 assert!(
2719 String::from_utf8_lossy(&output.stdout).contains("1 passed"),
2720 "{output:?}"
2721 );
2722 true
2723 }
2724
2725 fn global_source_test() -> std::sync::MutexGuard<'static, ()> {
2728 static GLOBAL_SOURCE: std::sync::Mutex<()> = std::sync::Mutex::new(());
2729 GLOBAL_SOURCE
2730 .lock()
2731 .unwrap_or_else(|poisoned| poisoned.into_inner())
2732 }
2733
2734 struct NativeCutSource {
2739 source: super::ForwardedSource,
2740 sender: std::os::fd::OwnedFd,
2741 written: std::sync::Arc<std::sync::Mutex<Vec<Vec<u8>>>>,
2742 }
2743
2744 impl NativeCutSource {
2745 fn new() -> Self {
2746 use std::os::fd::FromRawFd;
2747 let mut fds = [-1; 2];
2748 assert_eq!(
2750 unsafe {
2751 libc::socketpair(
2752 libc::AF_UNIX,
2753 libc::SOCK_SEQPACKET | libc::SOCK_CLOEXEC,
2754 0,
2755 fds.as_mut_ptr(),
2756 )
2757 },
2758 0
2759 );
2760 let written = std::sync::Arc::new(std::sync::Mutex::new(Vec::new()));
2761 let sink = written.clone();
2762 Self {
2763 source: super::ForwardedSource {
2764 socket: unsafe { std::os::fd::OwnedFd::from_raw_fd(fds[0]) },
2765 sink: Box::new(move |record| sink.lock().unwrap().push(record.to_vec())),
2766 order: super::ForwardedOrder::new(),
2767 transport_failure: None,
2768 loss_seen: false,
2769 },
2770 sender: unsafe { std::os::fd::OwnedFd::from_raw_fd(fds[1]) },
2771 written,
2772 }
2773 }
2774
2775 fn send(&self, tid: i32, index: u64, record: &[u8]) {
2776 use std::os::fd::AsRawFd;
2777 let message = super::tagged_forwarded_message(tid, index, record);
2778 assert_eq!(
2780 unsafe {
2781 libc::send(
2782 self.sender.as_raw_fd(),
2783 message.as_ptr().cast(),
2784 message.len(),
2785 libc::MSG_NOSIGNAL,
2786 )
2787 },
2788 message.len() as isize
2789 );
2790 }
2791
2792 fn check(
2793 &mut self,
2794 produced: u64,
2795 ) -> Result<super::CoordinatorForwardingReceipt, super::CoordinatorForwardingCutError>
2796 {
2797 super::inspect_coordinator_forwarding_cut(
2798 Some(&mut self.source),
2799 19,
2800 41,
2801 produced,
2802 None,
2803 || false,
2804 )
2805 }
2806 }
2807
2808 #[test]
2809 fn native_coordinator_cut_checks_zero_and_nonzero_real_socket_intervals() {
2810 if isolated_child(
2811 "detlog::tests::native_coordinator_cut_checks_zero_and_nonzero_real_socket_intervals",
2812 ) {
2813 return;
2814 }
2815 let _guard = global_source_test();
2816 let mut fixture = NativeCutSource::new();
2817 let first = fixture.check(0).unwrap();
2818 assert!(fixture.written.lock().unwrap().is_empty());
2819 assert!(fixture.source.order.received.is_empty());
2820 assert_eq!(
2821 fixture.source.transport_failure, None,
2822 "empty EAGAIN is healthy"
2823 );
2824 fixture.send(41, 1, b"a\n");
2825 fixture.send(41, 2, b"b\n");
2826 let second = super::inspect_coordinator_forwarding_cut(
2827 Some(&mut fixture.source),
2828 19,
2829 41,
2830 2,
2831 Some(&first),
2832 || false,
2833 )
2834 .unwrap();
2835 assert_eq!(first, second);
2836 assert_eq!(
2837 *fixture.written.lock().unwrap(),
2838 vec![b"a\n".to_vec(), b"b\n".to_vec()]
2839 );
2840 assert!(fixture.source.order.pending.is_empty());
2841 assert!(fixture.source.order.received.is_empty());
2842 fixture.send(41, 1, b"c\n");
2844 assert_eq!(fixture.check(1), Ok(first));
2845 assert_eq!(
2846 super::inspect_coordinator_forwarding_cut(
2847 Some(&mut fixture.source),
2848 19,
2849 41,
2850 0,
2851 Some(&first),
2852 || false
2853 ),
2854 Ok(first)
2855 );
2856 assert_eq!(
2857 *fixture.written.lock().unwrap(),
2858 vec![b"a\n".to_vec(), b"b\n".to_vec(), b"c\n".to_vec()]
2859 );
2860 assert!(fixture.source.order.at_commit(41, true).is_empty());
2861 assert_eq!(
2862 fixture.check(0),
2863 Ok(first),
2864 "the actual owner's exclusive point is eligible too"
2865 );
2866 }
2867
2868 #[test]
2869 fn native_coordinator_cut_refuses_unchecked_counts_without_consuming_them() {
2870 if isolated_child(
2871 "detlog::tests::native_coordinator_cut_refuses_unchecked_counts_without_consuming_them",
2872 ) {
2873 return;
2874 }
2875 use super::CoordinatorForwardingCutError as Error;
2876 let _guard = global_source_test();
2877 for (indexes, produced, expected) in [
2878 (
2879 vec![],
2880 1,
2881 Error::CountMismatch {
2882 produced: 1,
2883 received: 0,
2884 },
2885 ),
2886 (
2887 vec![1],
2888 0,
2889 Error::CountMismatch {
2890 produced: 0,
2891 received: 1,
2892 },
2893 ),
2894 (
2895 vec![1],
2896 2,
2897 Error::CountMismatch {
2898 produced: 2,
2899 received: 1,
2900 },
2901 ),
2902 (
2903 vec![1, 2],
2904 1,
2905 Error::CountMismatch {
2906 produced: 1,
2907 received: 2,
2908 },
2909 ),
2910 (
2911 vec![2],
2912 1,
2913 Error::OutOfSequence {
2914 expected: 1,
2915 sent: 2,
2916 },
2917 ),
2918 (
2919 vec![1, 1],
2920 2,
2921 Error::OutOfSequence {
2922 expected: 2,
2923 sent: 1,
2924 },
2925 ),
2926 (vec![1], super::UNCOUNTED, Error::Uncounted),
2927 ] {
2928 let mut fixture = NativeCutSource::new();
2929 for &index in &indexes {
2930 fixture.send(41, index, b"kept\n");
2931 }
2932 assert_eq!(fixture.check(produced), Err(expected));
2933 assert_eq!(
2934 fixture
2935 .source
2936 .order
2937 .received
2938 .get(&41)
2939 .copied()
2940 .unwrap_or_default()
2941 .count,
2942 indexes.len() as u64
2943 );
2944 assert_eq!(
2945 fixture.source.order.pending.get(&41).map_or(0, Vec::len),
2946 indexes.len()
2947 );
2948 assert!(
2949 fixture
2950 .written
2951 .lock()
2952 .unwrap()
2953 .iter()
2954 .all(|record| record.starts_with(super::FORWARDING_LOSS_NOTICE.as_bytes()))
2955 );
2956 assert_eq!(
2957 fixture.check(produced),
2958 Err(Error::DeterminismLoss),
2959 "a later check cannot clear the loss"
2960 );
2961 assert_eq!(
2962 fixture
2963 .source
2964 .order
2965 .received
2966 .get(&41)
2967 .copied()
2968 .unwrap_or_default()
2969 .count,
2970 indexes.len() as u64
2971 );
2972 }
2973 }
2974
2975 #[test]
2976 fn native_coordinator_cut_retains_other_owner_records_and_requires_order_point() {
2977 if isolated_child(
2978 "detlog::tests::native_coordinator_cut_retains_other_owner_records_and_requires_order_point",
2979 ) {
2980 return;
2981 }
2982 use super::CoordinatorForwardingCutError as Error;
2983 let _guard = global_source_test();
2984 let mut fixture = NativeCutSource::new();
2985 fixture.send(41, 1, b"owner\n");
2986 fixture.send(43, 1, b"other\n");
2987 for _ in 0..2 {
2988 assert_eq!(fixture.check(1), Err(Error::OtherOwnerPending(43)));
2989 assert_eq!(fixture.source.order.pending[&41], vec![b"owner\n".to_vec()]);
2990 assert_eq!(fixture.source.order.pending[&43], vec![b"other\n".to_vec()]);
2991 assert_eq!(fixture.source.order.received[&41].count, 1);
2992 assert_eq!(fixture.source.order.received[&43].count, 1);
2993 assert!(fixture.written.lock().unwrap().is_empty());
2994 }
2995 let other = fixture.source.order.at_commit(43, true);
2998 super::write_records(&mut fixture.source, other);
2999 assert_eq!(fixture.check(1), Err(Error::OtherOwnerPending(43)));
3000 assert_eq!(fixture.source.order.received[&43].count, 1);
3001
3002 for runner in [
3003 super::Runner::None,
3004 super::Runner::Exclusive(43),
3005 super::Runner::Root(43),
3006 ] {
3007 let mut fixture = NativeCutSource::new();
3008 fixture.send(41, 1, b"kept\n");
3009 fixture.source.order.runner = runner;
3010 assert_eq!(fixture.check(1), Err(Error::NotOwnerBoundary));
3011 assert_eq!(fixture.source.order.pending[&41], vec![b"kept\n".to_vec()]);
3012 assert_eq!(fixture.source.order.received[&41].count, 1);
3013 assert!(fixture.written.lock().unwrap().is_empty());
3014 }
3015 }
3016
3017 #[test]
3018 fn native_coordinator_cut_requires_a_healthy_actual_message_source() {
3019 if isolated_child(
3020 "detlog::tests::native_coordinator_cut_requires_a_healthy_actual_message_source",
3021 ) {
3022 return;
3023 }
3024 use std::os::fd::FromRawFd;
3025
3026 use super::CoordinatorForwardingCutError as Error;
3027 let _guard = global_source_test();
3028 assert_eq!(
3029 super::inspect_coordinator_forwarding_cut(None, 19, 41, 0, None, || false),
3030 Err(Error::MissingSource)
3031 );
3032 assert_eq!(
3033 super::inspect_coordinator_forwarding_cut(None, 19, 0, 0, None, || false),
3034 Err(Error::InvalidOwner)
3035 );
3036
3037 let mut fixture = NativeCutSource::new();
3038 fixture.source.socket = std::fs::File::open("/dev/null").unwrap().into();
3039 assert_eq!(fixture.check(0), Err(Error::InvalidSource));
3040 super::collect_forwarded(&mut fixture.source);
3041 assert_eq!(
3042 fixture.source.transport_failure,
3043 Some(super::ForwardedSourceError::Io(libc::ENOTSOCK))
3044 );
3045 assert_eq!(fixture.check(0), Err(Error::SourceIo(libc::ENOTSOCK)));
3046
3047 let (stream, _peer) = std::os::unix::net::UnixStream::pair().unwrap();
3048 let mut fixture = NativeCutSource::new();
3049 fixture.source.socket = stream.into();
3050 assert_eq!(
3051 fixture.check(0),
3052 Err(Error::InvalidSource),
3053 "a stream cannot stand in for the counted message transport"
3054 );
3055
3056 let mut fixture = NativeCutSource::new();
3057 let fd =
3059 unsafe { libc::socket(libc::AF_UNIX, libc::SOCK_SEQPACKET | libc::SOCK_CLOEXEC, 0) };
3060 assert!(fd >= 0);
3061 fixture.source.socket = unsafe { std::os::fd::OwnedFd::from_raw_fd(fd) };
3062 assert_eq!(fixture.check(0), Err(Error::SourceIo(libc::ENOTCONN)));
3063
3064 let fixture = NativeCutSource::new();
3065 fixture.send(41, 1, b"retained on closure\n");
3066 let NativeCutSource {
3067 mut source, sender, ..
3068 } = fixture;
3069 drop(sender);
3070 super::collect_forwarded(&mut source);
3073 assert_eq!(
3074 source.transport_failure,
3075 Some(super::ForwardedSourceError::Closed)
3076 );
3077 for _ in 0..2 {
3078 assert_eq!(
3079 super::inspect_coordinator_forwarding_cut(
3080 Some(&mut source),
3081 19,
3082 41,
3083 1,
3084 None,
3085 || false
3086 ),
3087 Err(Error::ClosedSource)
3088 );
3089 assert_eq!(source.order.received[&41].count, 1);
3090 assert_eq!(
3091 source.order.pending[&41],
3092 vec![b"retained on closure\n".to_vec()]
3093 );
3094 }
3095 }
3096
3097 #[test]
3098 fn native_coordinator_cut_receipt_rechecks_generation_socket_and_owner() {
3099 if isolated_child(
3100 "detlog::tests::native_coordinator_cut_receipt_rechecks_generation_socket_and_owner",
3101 ) {
3102 return;
3103 }
3104 use super::CoordinatorForwardingCutError as Error;
3105 let _guard = global_source_test();
3106 let mut fixture = NativeCutSource::new();
3107 let receipt = fixture.check(0).unwrap();
3108 assert_eq!(
3109 super::inspect_coordinator_forwarding_cut(
3110 Some(&mut fixture.source),
3111 20,
3112 41,
3113 0,
3114 Some(&receipt),
3115 || false
3116 ),
3117 Err(Error::SourceChanged)
3118 );
3119 assert_eq!(
3120 super::inspect_coordinator_forwarding_cut(
3121 Some(&mut fixture.source),
3122 19,
3123 43,
3124 0,
3125 Some(&receipt),
3126 || false
3127 ),
3128 Err(Error::SourceChanged)
3129 );
3130 let mut replacement = NativeCutSource::new();
3131 replacement.send(41, 1, b"new source\n");
3132 assert_eq!(
3133 super::inspect_coordinator_forwarding_cut(
3134 Some(&mut replacement.source),
3135 19,
3136 41,
3137 1,
3138 Some(&receipt),
3139 || false
3140 ),
3141 Err(Error::SourceChanged)
3142 );
3143 super::collect_forwarded(&mut replacement.source);
3144 assert_eq!(replacement.source.order.received[&41].count, 1);
3145 assert_eq!(
3146 replacement.source.order.pending[&41],
3147 vec![b"new source\n".to_vec()]
3148 );
3149 }
3150
3151 #[test]
3152 fn native_coordinator_cut_refuses_real_loss_notices_and_persistent_process_loss() {
3153 if isolated_child(
3154 "detlog::tests::native_coordinator_cut_refuses_real_loss_notices_and_persistent_process_loss",
3155 ) {
3156 return;
3157 }
3158 use std::os::fd::AsRawFd;
3159
3160 use super::CoordinatorForwardingCutError as Error;
3161 let _guard = global_source_test();
3162 for message in [
3163 b"HERMIT_DETLOG_RECORD_LOST 0 1 actual forwarding loss\n".as_slice(),
3164 b"untagged actual record\n".as_slice(),
3165 ] {
3166 let mut fixture = NativeCutSource::new();
3167 assert_eq!(
3169 unsafe {
3170 libc::send(
3171 fixture.sender.as_raw_fd(),
3172 message.as_ptr().cast(),
3173 message.len(),
3174 libc::MSG_NOSIGNAL,
3175 )
3176 },
3177 message.len() as isize
3178 );
3179 assert_eq!(fixture.check(0), Err(Error::DeterminismLoss));
3180 assert!(fixture.source.loss_seen);
3181 assert!(
3182 fixture
3183 .written
3184 .lock()
3185 .unwrap()
3186 .iter()
3187 .any(|record| record.starts_with(super::FORWARDING_LOSS_NOTICE.as_bytes()))
3188 );
3189 assert_eq!(fixture.check(0), Err(Error::DeterminismLoss));
3190 }
3191 super::clear_forwarded_source();
3194 super::record_determinism_loss("native cut test persistent loss");
3195 let NativeCutSource { source, sender, .. } = NativeCutSource::new();
3196 super::set_forwarded_source(source.socket, source.sink);
3197 assert_eq!(
3198 super::check_native_exec_forwarding_cut(41, 0, None),
3199 Err(Error::DeterminismLoss)
3200 );
3201 super::clear_forwarded_source();
3202 assert_eq!(
3203 super::check_native_exec_forwarding_cut(41, 0, None),
3204 Err(Error::MissingSource)
3205 );
3206 drop(sender);
3207 }
3208
3209 #[test]
3210 fn native_coordinator_cut_restores_unchecked_queue_after_sink_closure() {
3211 if isolated_child(
3212 "detlog::tests::native_coordinator_cut_restores_unchecked_queue_after_sink_closure",
3213 ) {
3214 return;
3215 }
3216 use super::CoordinatorForwardingCutError as Error;
3217 let _guard = global_source_test();
3218 let fixture = NativeCutSource::new();
3219 fixture.send(41, 1, b"written before closure\n");
3220 let NativeCutSource {
3221 mut source,
3222 sender,
3223 written,
3224 } = fixture;
3225 let mut peer = Some(sender);
3226 let sink = written.clone();
3227 source.sink = Box::new(move |record| {
3228 sink.lock().unwrap().push(record.to_vec());
3229 drop(peer.take());
3230 });
3231 assert_eq!(
3232 super::inspect_coordinator_forwarding_cut(Some(&mut source), 19, 41, 1, None, || false),
3233 Err(Error::ClosedSource)
3234 );
3235 assert_eq!(
3236 *written.lock().unwrap(),
3237 vec![b"written before closure\n".to_vec()]
3238 );
3239 assert_eq!(source.order.received[&41].count, 1);
3240 assert_eq!(
3241 source.order.pending[&41],
3242 vec![b"written before closure\n".to_vec()]
3243 );
3244 }
3245
3246 #[test]
3247 fn native_coordinator_cut_rechecks_loss_reported_by_the_record_sink() {
3248 if isolated_child(
3249 "detlog::tests::native_coordinator_cut_rechecks_loss_reported_by_the_record_sink",
3250 ) {
3251 return;
3252 }
3253 use super::CoordinatorForwardingCutError as Error;
3254 let _guard = global_source_test();
3255 let fixture = NativeCutSource::new();
3256 fixture.send(41, 1, b"sink failure\n");
3257 let NativeCutSource {
3258 mut source,
3259 sender,
3260 written,
3261 } = fixture;
3262 let local_loss = std::sync::Arc::new(std::sync::atomic::AtomicBool::new(false));
3263 let loss_from_sink = local_loss.clone();
3264 let sink = written.clone();
3265 source.sink = Box::new(move |record| {
3266 sink.lock().unwrap().push(record.to_vec());
3267 super::record_determinism_loss("native cut test sink failure");
3270 loss_from_sink.store(true, Ordering::Release);
3271 });
3272 assert_eq!(
3273 super::inspect_coordinator_forwarding_cut(Some(&mut source), 19, 41, 1, None, || {
3274 local_loss.load(Ordering::Acquire)
3275 }),
3276 Err(Error::DeterminismLoss)
3277 );
3278 assert!(super::determinism_loss().is_some());
3279 assert_eq!(*written.lock().unwrap(), vec![b"sink failure\n".to_vec()]);
3280 assert_eq!(source.order.received[&41].count, 1);
3281 assert_eq!(source.order.pending[&41], vec![b"sink failure\n".to_vec()]);
3282 drop(sender);
3283 }
3284
3285 #[test]
3286 fn native_coordinator_cut_retains_actual_packet_that_arrives_during_sink_write() {
3287 if isolated_child(
3288 "detlog::tests::native_coordinator_cut_retains_actual_packet_that_arrives_during_sink_write",
3289 ) {
3290 return;
3291 }
3292 use std::os::fd::AsRawFd;
3293
3294 use super::CoordinatorForwardingCutError as Error;
3295 let _guard = global_source_test();
3296 let fixture = NativeCutSource::new();
3297 fixture.send(41, 1, b"first\n");
3298 let NativeCutSource {
3299 mut source,
3300 sender,
3301 written,
3302 } = fixture;
3303 let sink = written.clone();
3304 let mut sent = false;
3305 source.sink = Box::new(move |record| {
3306 sink.lock().unwrap().push(record.to_vec());
3307 if !sent {
3308 sent = true;
3309 let message = super::tagged_forwarded_message(41, 2, b"late\n");
3310 assert_eq!(
3312 unsafe {
3313 libc::send(
3314 sender.as_raw_fd(),
3315 message.as_ptr().cast(),
3316 message.len(),
3317 libc::MSG_NOSIGNAL,
3318 )
3319 },
3320 message.len() as isize
3321 );
3322 }
3323 });
3324 assert_eq!(
3325 super::inspect_coordinator_forwarding_cut(Some(&mut source), 19, 41, 1, None, || false),
3326 Err(Error::CountMismatch {
3327 produced: 1,
3328 received: 2
3329 })
3330 );
3331 assert_eq!(source.order.received[&41].count, 2);
3332 assert_eq!(
3333 source.order.pending[&41],
3334 vec![b"first\n".to_vec(), b"late\n".to_vec()]
3335 );
3336 assert_eq!(written.lock().unwrap()[0], b"first\n".to_vec());
3337 assert!(source.loss_seen);
3338 }
3339
3340 #[test]
3343 fn forwarded_records_are_counted_per_thread_until_taken() {
3344 std::thread::spawn(|| {
3345 assert_eq!(super::take_forwarded_since_request(), 0);
3346 super::count_forwarded();
3347 super::count_forwarded();
3348 assert_eq!(super::take_forwarded_since_request(), 2);
3349 assert_eq!(super::take_forwarded_since_request(), 0);
3350 super::count_forwarded();
3351 let other = std::thread::spawn(|| {
3353 super::count_forwarded();
3354 super::take_forwarded_since_request()
3355 });
3356 assert_eq!(other.join().unwrap(), 1);
3357 assert_eq!(super::take_forwarded_since_request(), 1);
3358 })
3359 .join()
3360 .unwrap();
3361 }
3362
3363 #[test]
3368 fn count_slots_are_released_and_an_uncounted_thread_is_reported() {
3369 let _source = global_source_test();
3370 for _ in 0..(super::FORWARDED_COUNTS.len() * 2) {
3371 std::thread::spawn(|| {
3372 super::count_forwarded();
3373 assert_eq!(super::take_forwarded_since_request(), 1);
3374 super::release_forwarded_count();
3375 })
3376 .join()
3377 .unwrap();
3378 }
3379 assert!(!super::FORWARDING_UNCOUNTED.load(Ordering::Acquire));
3380
3381 let child = unsafe { libc::fork() };
3382 assert!(child >= 0);
3383 if child == 0 {
3384 unsafe { libc::alarm(20) };
3385 for _ in 0..=super::FORWARDED_COUNTS.len() {
3387 std::thread::spawn(super::count_forwarded).join().unwrap();
3388 }
3389 let reported = super::take_forwarded_since_request();
3390 unsafe { libc::_exit(if reported == super::UNCOUNTED { 0 } else { 1 }) };
3391 }
3392 let mut status = 0;
3393 assert_eq!(unsafe { libc::waitpid(child, &mut status, 0) }, child);
3394 assert!(
3395 libc::WIFEXITED(status) && libc::WEXITSTATUS(status) == 0,
3396 "{status:#x}"
3397 );
3398 }
3399
3400 #[test]
3405 fn counts_are_untouched_until_the_first_record() {
3406 let _source = global_source_test();
3407 let child = unsafe { libc::fork() };
3408 assert!(child >= 0);
3409 if child == 0 {
3410 unsafe { libc::alarm(20) };
3411 for slot in &super::FORWARDED_COUNTS {
3412 slot.tid.store(0, Ordering::Release);
3413 slot.count.store(0, Ordering::Release);
3414 }
3415 super::FORWARDING_STARTED.store(false, Ordering::Release);
3416 let me = super::current_tid();
3417 let claimed = || {
3418 super::FORWARDED_COUNTS
3419 .iter()
3420 .any(|slot| slot.tid.load(Ordering::Acquire) != 0)
3421 };
3422 let ok = super::take_forwarded_since_request() == 0
3423 && !claimed()
3424 && {
3425 super::release_forwarded_count();
3426 !claimed()
3427 }
3428 && super::count_forwarded() == 1
3429 && super::FORWARDING_STARTED.load(Ordering::Acquire)
3430 && super::FORWARDED_COUNTS
3431 .iter()
3432 .any(|slot| slot.tid.load(Ordering::Acquire) == me)
3433 && super::count_forwarded() == 2
3434 && super::take_forwarded_since_request() == 2
3435 && super::take_forwarded_since_request() == 0;
3436 unsafe { libc::_exit(if ok { 0 } else { 1 }) };
3437 }
3438 let mut status = 0;
3439 assert_eq!(unsafe { libc::waitpid(child, &mut status, 0) }, child);
3440 assert!(
3441 libc::WIFEXITED(status) && libc::WEXITSTATUS(status) == 0,
3442 "{status:#x}"
3443 );
3444 }
3445
3446 #[test]
3451 fn a_released_slot_on_the_probe_path_is_not_claimed_twice() {
3452 let _source = global_source_test();
3453 let buckets = super::FORWARDED_COUNTS.len() as i32;
3454 let base = 0x3f00_0000 - 0x3f00_0000 % buckets + 7;
3455 let (first, second, third) = (base, base + buckets, base + 2 * buckets);
3456 let slot = |tid| super::forwarded_count_slot(tid).map(|slot| slot as *const _);
3457 let first_slot = slot(first).unwrap();
3458 let second_slot = slot(second).unwrap();
3459 let third_slot = slot(third).unwrap();
3460 assert_ne!(second_slot, third_slot);
3461 super::release_count_slot(second);
3462 assert_eq!(
3463 slot(third),
3464 Some(third_slot),
3465 "the hole is not a second slot"
3466 );
3467 assert_eq!(slot(first), Some(first_slot));
3468 for tid in [first, third] {
3469 super::release_count_slot(tid);
3470 }
3471
3472 let me = super::current_pid();
3473 assert!(!super::private_copy(me, me));
3474 let child = unsafe { libc::fork() };
3475 assert!(child >= 0);
3476 if child == 0 {
3477 unsafe { libc::_exit(0) };
3478 }
3479 assert!(
3480 super::private_copy(child, me),
3481 "a forked child's memory is its own"
3482 );
3483 let mut status = 0;
3484 assert_eq!(unsafe { libc::waitpid(child, &mut status, 0) }, child);
3485 assert!(
3486 super::private_copy(child, me),
3487 "an exited process holds nothing"
3488 );
3489 extern "C" fn shared_child(parent: *mut libc::c_void) -> libc::c_int {
3492 let own = unsafe { libc::syscall(libc::SYS_getpid) } as i32;
3493 i32::from(super::private_copy(parent as usize as i32, own))
3494 }
3495 let mut stack = vec![0u8; 256 * 1024];
3496 let top = (stack.as_mut_ptr() as usize + stack.len()) & !15;
3497 let shared = unsafe {
3498 libc::clone(
3499 shared_child,
3500 top as *mut libc::c_void,
3501 libc::CLONE_VM | libc::SIGCHLD,
3502 me as usize as *mut libc::c_void,
3503 )
3504 };
3505 assert!(shared > 0, "{}", std::io::Error::last_os_error());
3506 assert_eq!(unsafe { libc::waitpid(shared, &mut status, 0) }, shared);
3507 drop(stack);
3508 assert!(
3509 libc::WIFEXITED(status) && libc::WEXITSTATUS(status) == 0,
3510 "a CLONE_VM child shares this memory: {status:#x}"
3511 );
3512 }
3513
3514 #[test]
3520 fn a_required_forwarder_that_is_missing_or_narrowed_makes_counts_uncounted() {
3521 let _source = global_source_test();
3522 let in_child = |install: Option<&str>, expected: &str| -> bool {
3523 let child = unsafe { libc::fork() };
3524 assert!(child >= 0);
3525 if child == 0 {
3526 unsafe { libc::alarm(20) };
3527 let ok = super::FORWARDER.get().is_none()
3530 && install.is_none_or(|policy| {
3531 let policy = ForwardPolicy::decode(policy).unwrap();
3532 super::set_forwarder(|_, _, _, _| {}, policy).is_ok()
3533 });
3534 super::require_forwarding(expected);
3535 let uncounted = super::take_forwarded_since_request() == super::UNCOUNTED;
3536 unsafe {
3537 libc::_exit(if !ok {
3538 2
3539 } else if uncounted {
3540 1
3541 } else {
3542 0
3543 })
3544 };
3545 }
3546 let mut status = 0;
3547 assert_eq!(unsafe { libc::waitpid(child, &mut status, 0) }, child);
3548 assert!(
3549 libc::WIFEXITED(status) && libc::WEXITSTATUS(status) != 2,
3550 "{status:#x}"
3551 );
3552 libc::WEXITSTATUS(status) == 1
3553 };
3554 let required = "1,detcore::tool_local=1";
3555 assert!(in_child(None, required), "no forwarder: uncounted");
3556 assert!(
3557 in_child(Some("1,detcore::tool_local=0"), required),
3558 "a narrowed policy: uncounted"
3559 );
3560 assert!(
3561 !in_child(Some(required), required),
3562 "the required policy: counted"
3563 );
3564 }
3565
3566 #[test]
3571 fn a_counted_request_with_missing_records_is_a_loss() {
3572 use std::os::fd::FromRawFd;
3573 use std::os::fd::OwnedFd;
3574 use std::sync::Arc;
3575 use std::sync::Mutex;
3576
3577 let _source = global_source_test();
3578 let mut fds = [0; 2];
3579 assert_eq!(
3580 unsafe { libc::socketpair(libc::AF_UNIX, libc::SOCK_SEQPACKET, 0, fds.as_mut_ptr()) },
3581 0
3582 );
3583 let written = Arc::new(Mutex::new(Vec::<Vec<u8>>::new()));
3584 let sink = Arc::clone(&written);
3585 super::set_forwarded_source(
3586 unsafe { OwnedFd::from_raw_fd(fds[0]) },
3587 Box::new(move |record| sink.lock().unwrap().push(record.to_vec())),
3588 );
3589 let send = |tid: i32, index: u64, line: &str| {
3590 let message = super::tagged_forwarded_message(tid, index, line.as_bytes());
3591 let sent = unsafe { libc::send(fds[1], message.as_ptr().cast(), message.len(), 0) };
3592 assert_eq!(sent, message.len() as isize);
3593 };
3594 let notices = |written: &Arc<Mutex<Vec<Vec<u8>>>>| -> Vec<String> {
3597 written
3598 .lock()
3599 .unwrap()
3600 .iter()
3601 .filter(|record| record.starts_with(super::FORWARDING_LOSS_NOTICE.as_bytes()))
3602 .map(|record| String::from_utf8_lossy(record).into_owned())
3603 .filter(|notice| notice.contains("thread 41 ") || notice.contains("thread 41)"))
3604 .collect()
3605 };
3606 send(41, 1, "a\n");
3607 send(41, 2, "b\n");
3608 super::check_forwarded_count(41, 2);
3609 assert_eq!(notices(&written).len(), 0, "as many records as produced");
3610 send(41, 1, "c\n");
3611 super::check_forwarded_count(41, 3);
3612 assert_eq!(notices(&written).len(), 1, "a deficit is a loss");
3613 assert!(
3614 notices(&written)[0].contains(
3615 "lost: thread 41 produced 3 since its last counted request and 1 arrived"
3616 ),
3617 "{:?}",
3618 notices(&written)
3619 );
3620 send(41, 1, "d\n");
3623 send(41, 2, "e\n");
3624 super::check_forwarded_count(41, 1);
3625 assert_eq!(notices(&written).len(), 2, "a surplus is refused too");
3626 assert!(
3627 notices(&written)[1].contains("not the Tool's: thread 41 produced 1"),
3628 "{:?}",
3629 notices(&written)
3630 );
3631 super::check_forwarded_count(41, super::UNCOUNTED);
3632 assert_eq!(notices(&written).len(), 3, "an uncounted thread is refused");
3633 assert!(
3634 notices(&written)[2].contains("uncounted"),
3635 "{:?}",
3636 notices(&written)
3637 );
3638 send(41, 1, "f\n");
3641 send(41, 3, "g\n");
3642 super::check_forwarded_count(41, 2);
3643 assert_eq!(notices(&written).len(), 4, "a skipped index is a loss");
3644 assert!(
3645 notices(&written)[3]
3646 .contains("lost: thread 41 sent record 3 of its interval where 2 was next"),
3647 "{:?}",
3648 notices(&written)
3649 );
3650 send(41, 1, "h\n");
3653 send(41, 1, "padding\n");
3654 super::check_forwarded_count(41, 2);
3655 assert_eq!(notices(&written).len(), 5, "a repeated index is refused");
3656 assert!(
3657 notices(&written)[4].contains(
3658 "not the Tool's: thread 41 sent record 1 of its interval where 2 was next"
3659 ),
3660 "{:?}",
3661 notices(&written)
3662 );
3663 send(41, 1, "i\n");
3665 super::check_forwarded_count(41, 1);
3666 assert_eq!(notices(&written).len(), 5, "a new interval starts at 1");
3667 assert!(super::determinism_loss().is_some());
3668 super::clear_forwarded_source();
3669 unsafe { libc::close(fds[1]) };
3670 }
3671
3672 #[test]
3673 fn a_full_socket_buffer_does_not_wait_for_a_request() {
3674 let _source = global_source_test();
3675 use std::os::fd::FromRawFd;
3676 use std::os::fd::OwnedFd;
3677 use std::sync::Arc;
3678 use std::sync::Mutex;
3679 use std::time::Duration;
3680 use std::time::Instant;
3681
3682 const RECORDS: usize = 2000;
3683 let mut fds = [0; 2];
3684 assert_eq!(
3685 unsafe { libc::socketpair(libc::AF_UNIX, libc::SOCK_SEQPACKET, 0, fds.as_mut_ptr()) },
3686 0
3687 );
3688 let small: libc::c_int = 4096;
3689 for fd in fds {
3690 for option in [libc::SO_SNDBUF, libc::SO_RCVBUF] {
3691 unsafe {
3692 libc::setsockopt(
3693 fd,
3694 libc::SOL_SOCKET,
3695 option,
3696 (&raw const small).cast(),
3697 std::mem::size_of_val(&small) as libc::socklen_t,
3698 )
3699 };
3700 }
3701 }
3702 let written = Arc::new(Mutex::new(Vec::<Vec<u8>>::new()));
3703 let sink = Arc::clone(&written);
3704 super::set_forwarded_source(
3705 unsafe { OwnedFd::from_raw_fd(fds[0]) },
3706 Box::new(move |record| sink.lock().unwrap().push(record.to_vec())),
3707 );
3708 let runtime = tokio::runtime::Builder::new_multi_thread()
3711 .worker_threads(1)
3712 .enable_all()
3713 .build()
3714 .unwrap();
3715 runtime.block_on(async { super::drain_forwarded_at_request(1) });
3716 let sender = fds[1];
3717 let started = Instant::now();
3718 let sending = std::thread::spawn(move || {
3719 for index in 0..RECORDS {
3720 let message = super::tagged_forwarded_message(
3721 7,
3722 index as u64 + 1,
3723 format!("record {index:04}\n").as_bytes(),
3724 );
3725 let sent = unsafe {
3726 libc::send(
3727 sender,
3728 message.as_ptr().cast(),
3729 message.len(),
3730 libc::MSG_NOSIGNAL,
3731 )
3732 };
3733 assert_eq!(sent, message.len() as isize);
3734 }
3735 });
3736 while !sending.is_finished() {
3737 assert!(
3738 started.elapsed() < Duration::from_secs(20),
3739 "the sender stayed blocked on a full socket buffer"
3740 );
3741 std::thread::sleep(Duration::from_millis(10));
3742 }
3743 sending.join().unwrap();
3744 let own = |written: &Arc<Mutex<Vec<Vec<u8>>>>| -> Vec<Vec<u8>> {
3747 written
3748 .lock()
3749 .unwrap()
3750 .iter()
3751 .filter(|record| record.starts_with(b"record "))
3752 .cloned()
3753 .collect()
3754 };
3755 assert!(
3756 own(&written).is_empty(),
3757 "records were written before their point"
3758 );
3759 super::clear_forwarded_source();
3760 let written = own(&written);
3761 assert_eq!(written.len(), RECORDS);
3762 for (index, record) in written.iter().enumerate() {
3763 assert_eq!(record, format!("record {index:04}\n").as_bytes());
3764 }
3765 unsafe { libc::close(sender) };
3766 }
3767
3768 #[test]
3769 fn forwarded_line_names_the_emitting_module() {
3770 assert_eq!(
3771 super::forwarded_line(
3772 "detcore::tool_local",
3773 " DETLOG_RECORD={}",
3774 format_args!("USER RAND: seeding PRNG for root thread with seed {}", 0)
3775 ),
3776 b"INFO detcore::tool_local: DETLOG USER RAND: seeding PRNG for root thread with seed 0 DETLOG_RECORD={}\n"
3777 .to_vec()
3778 );
3779 }
3780
3781 #[test]
3789 fn forwarding_failures_become_loss_notices() {
3790 let mut pair = [-1; 2];
3791 let created = unsafe {
3793 libc::socketpair(
3794 libc::AF_UNIX,
3795 libc::SOCK_SEQPACKET | libc::SOCK_CLOEXEC,
3796 0,
3797 pair.as_mut_ptr(),
3798 )
3799 };
3800 assert_eq!(created, 0);
3801 let [sender, receiver] = pair;
3802 let mut buffer = vec![0u8; 2 << 20];
3803 let mut receive = || {
3804 let received = unsafe {
3806 libc::recv(
3807 receiver,
3808 buffer.as_mut_ptr().cast(),
3809 buffer.len(),
3810 libc::MSG_DONTWAIT,
3811 )
3812 };
3813 assert!(received > 0, "{}", std::io::Error::last_os_error());
3814 String::from_utf8_lossy(&buffer[..received as usize]).into_owned()
3815 };
3816 let is_notice =
3817 |text: &str| text.starts_with(&format!("{} ", super::FORWARDING_LOSS_NOTICE));
3818
3819 unsafe {
3821 *libc::__errno_location() = libc::EAGAIN;
3822 super::send_forwarded_record(-1, "detcore", "", 1, format_args!("lost"));
3823 assert_eq!(*libc::__errno_location(), libc::EAGAIN);
3824 }
3825 let tag = |index: u64| format!("T{}.{index} ", super::current_tid());
3826 super::send_forwarded_record(sender, "detcore", "", 2, format_args!("after"));
3827 let notice = receive();
3828 assert!(is_notice(¬ice), "{notice}");
3829 assert_eq!(receive(), format!("{}INFO detcore: DETLOG after\n", tag(2)));
3830
3831 let small: libc::c_int = 4096;
3832 unsafe {
3834 libc::setsockopt(
3835 sender,
3836 libc::SOL_SOCKET,
3837 libc::SO_SNDBUF,
3838 (&raw const small).cast(),
3839 std::mem::size_of::<libc::c_int>() as libc::socklen_t,
3840 )
3841 };
3842 let huge = "x".repeat(1 << 20);
3843 super::send_forwarded_record(sender, "detcore", "", 1, format_args!("{huge}"));
3844 super::send_forwarded_record(sender, "detcore", "", 2, format_args!("small"));
3845 let notice = receive();
3846 assert!(is_notice(¬ice), "{notice}");
3847 assert_eq!(receive(), format!("{}INFO detcore: DETLOG small\n", tag(2)));
3848 unsafe {
3850 libc::close(sender);
3851 libc::close(receiver);
3852 }
3853 }
3854
3855 #[test]
3861 fn forwarded_records_are_written_at_points_the_schedule_fixes() {
3862 let mut order = super::ForwardedOrder::new();
3863 let text = |records: Vec<Vec<u8>>| -> Vec<String> {
3864 records
3865 .into_iter()
3866 .map(|record| String::from_utf8(record).unwrap())
3867 .collect()
3868 };
3869 let none: Vec<String> = Vec::new();
3870
3871 order.queue(3, b"root-1".to_vec());
3874 assert_eq!(text(order.at_request(3)), ["root-1"]);
3875 assert_eq!(text(order.at_commit(3, true)), none);
3876 order.queue(9, b"child-1".to_vec());
3879 assert_eq!(text(order.at_request(9)), none);
3880 assert_eq!(text(order.at_commit(9, true)), ["child-1"]);
3881 order.queue(3, b"root-2".to_vec());
3884 order.queue(9, b"child-2".to_vec());
3885 assert_eq!(text(order.at_request(9)), ["child-2"]);
3886 assert_eq!(text(order.at_request(3)), none);
3887 assert_eq!(text(order.at_commit(3, false)), ["root-2"]);
3890 order.queue(3, b"root-3".to_vec());
3891 assert_eq!(text(order.at_request(3)), none);
3892 order.queue(12, b"late-12".to_vec());
3894 order.queue(5, b"late-5".to_vec());
3895 assert_eq!(text(order.finish()), ["root-3", "late-5", "late-12"]);
3896 assert_eq!(text(order.finish()), none);
3897
3898 let mut order = super::ForwardedOrder::new();
3901 order.queue(3, b"first-root".to_vec());
3902 order.queue(4, b"second-root".to_vec());
3903 assert_eq!(text(order.at_request(3)), ["first-root"]);
3904 let notice = String::from_utf8(super::FORWARDING_AMBIGUOUS_ORDER_NOTICE.to_vec()).unwrap();
3905 assert!(notice.starts_with(&format!("{} ", super::FORWARDING_LOSS_NOTICE)));
3906 assert_eq!(text(order.at_request(4)), [notice]);
3907 assert_eq!(text(order.at_request(4)), none);
3908 assert_eq!(text(order.at_commit(4, true)), ["second-root"]);
3909
3910 let mut order = super::ForwardedOrder::new();
3913 let retired = String::from_utf8(super::FORWARDING_RETIRED_NOTICE.to_vec()).unwrap();
3914 assert_eq!(
3915 text(order.untagged(super::FORWARDING_RETIRED_NOTICE)),
3916 [retired]
3917 );
3918 let untagged =
3919 String::from_utf8(super::FORWARDING_UNTAGGED_RECORD_NOTICE.to_vec()).unwrap();
3920 assert!(untagged.starts_with(&format!("{} ", super::FORWARDING_LOSS_NOTICE)));
3921 assert_eq!(
3922 text(order.untagged(b"INFO detcore: DETLOG legacy-1\n")),
3923 [untagged, "INFO detcore: DETLOG legacy-1\n".to_string()]
3924 );
3925 assert_eq!(
3926 text(order.untagged(b"INFO detcore: DETLOG legacy-2\n")),
3927 ["INFO detcore: DETLOG legacy-2\n"]
3928 );
3929 }
3930
3931 #[test]
3932 fn a_loss_notice_records_the_determinism_loss_latch() {
3933 let _source = global_source_test();
3934 super::write_loss_notice("test: an unscheduled exit");
3937 let loss = super::determinism_loss().expect("the latch must be set");
3938 assert!(!loss.is_empty());
3939 super::record_determinism_loss("test: a later reason");
3941 assert_eq!(super::determinism_loss(), Some(loss));
3942 }
3943
3944 #[test]
3945 fn split_forwarded_message_reads_the_sender_tag() {
3946 assert_eq!(
3947 super::split_forwarded_message(b"T42.7 INFO detcore: x\n"),
3948 Some((42, 7, &b"INFO detcore: x\n"[..]))
3949 );
3950 assert_eq!(
3952 super::split_forwarded_message(b"T42 INFO detcore: x\n"),
3953 None
3954 );
3955 assert_eq!(super::split_forwarded_message(b"T42. INFO"), None);
3956 assert_eq!(super::split_forwarded_message(b"T42.x INFO"), None);
3957 assert_eq!(
3958 super::split_forwarded_message(super::FORWARDING_RETIRED_NOTICE),
3959 None
3960 );
3961 assert_eq!(super::split_forwarded_message(b"T INFO"), None);
3962 assert_eq!(super::split_forwarded_message(b"Tx1 INFO"), None);
3963 assert_eq!(super::split_forwarded_message(b"INFO detcore"), None);
3964 }
3965
3966 #[test]
3967 fn test_detlog() {
3968 detlog!("Hello : {}. From {:?}", "World", 31337);
3969 }
3970
3971 #[test]
3972 fn structured_record_round_trips_and_refuses_an_incomplete_current_shape() {
3973 let suffix = record_suffix(DetLogEvent::SyscallResult {
3974 finished_syscall_number: 37,
3975 });
3976 let line = format!("INFO detcore: DETLOG finish syscall #999{suffix}");
3977 let (human, record) = DetLogRecord::split(&line).unwrap();
3978 assert_eq!(human, "INFO detcore: DETLOG finish syscall #999");
3979 assert_eq!(
3980 record.unwrap().event,
3981 DetLogEvent::SyscallResult {
3982 finished_syscall_number: 37
3983 }
3984 );
3985
3986 let missing_number = format!(
3987 "INFO detcore: DETLOG finish syscall #999{RECORD_SEPARATOR}{{\"schema\":1,\"event\":{{\"kind\":\"syscall_result\"}}}}"
3988 );
3989 assert!(
3990 DetLogRecord::split(&missing_number)
3991 .unwrap_err()
3992 .contains("finished_syscall_number"),
3993 "an incomplete current record must fail by field name"
3994 );
3995 }
3996
3997 struct AlwaysEnabled;
4004
4005 impl tracing::Subscriber for AlwaysEnabled {
4006 fn register_callsite(&self, _: &'static Metadata<'static>) -> Interest {
4007 Interest::sometimes()
4008 }
4009 fn enabled(&self, _: &Metadata<'_>) -> bool {
4010 true
4011 }
4012 fn new_span(&self, _: &span::Attributes<'_>) -> span::Id {
4013 span::Id::from_u64(1)
4014 }
4015 fn record(&self, _: &span::Id, _: &span::Record<'_>) {}
4016 fn record_follows_from(&self, _: &span::Id, _: &span::Id) {}
4017 fn event(&self, _: &tracing::Event<'_>) {}
4018 fn enter(&self, _: &span::Id) {}
4019 fn exit(&self, _: &span::Id) {}
4020 }
4021
4022 #[test]
4026 fn detlog_observed_is_true_when_a_subscriber_is_listening() {
4027 tracing::subscriber::with_default(AlwaysEnabled, || {
4028 assert!(detlog_observed!());
4029 });
4030 }
4031
4032 #[test]
4043 fn detlog_observed_is_false_when_nothing_is_listening() {
4044 tracing::subscriber::with_default(tracing::subscriber::NoSubscriber::default(), || {
4045 assert!(!detlog_observed!());
4046 });
4047 }
4048
4049 struct RandomAtInfo;
4052
4053 impl tracing::Subscriber for RandomAtInfo {
4054 fn register_callsite(&self, _: &'static Metadata<'static>) -> Interest {
4055 Interest::sometimes()
4056 }
4057 fn enabled(&self, metadata: &Metadata<'_>) -> bool {
4058 *metadata.level() <= tracing::Level::WARN
4059 || (*metadata.level() <= tracing::Level::INFO
4060 && metadata.target().starts_with("detcore::random"))
4061 }
4062 fn max_level_hint(&self) -> Option<tracing::level_filters::LevelFilter> {
4063 Some(tracing::level_filters::LevelFilter::INFO)
4064 }
4065 fn new_span(&self, _: &span::Attributes<'_>) -> span::Id {
4066 span::Id::from_u64(1)
4067 }
4068 fn record(&self, _: &span::Id, _: &span::Record<'_>) {}
4069 fn record_follows_from(&self, _: &span::Id, _: &span::Id) {}
4070 fn event(&self, _: &tracing::Event<'_>) {}
4071 fn enter(&self, _: &span::Id) {}
4072 fn exit(&self, _: &span::Id) {}
4073 }
4074
4075 #[test]
4080 fn forward_policy_answers_per_target_as_the_subscriber_does() {
4081 let policy = tracing::subscriber::with_default(RandomAtInfo, || {
4082 ForwardPolicy::from_current_subscriber("warn,detcore::random=info")
4083 });
4084 assert!(policy.forwards_any());
4085 assert!(policy.forwards("detcore::random"));
4086 assert!(policy.forwards("detcore::random::inner"));
4087 assert!(!policy.forwards("detcore"));
4088 assert!(!policy.forwards("detcore::tool_local"));
4089 assert!(!policy.forwards("detcore::scheduler::runqueue"));
4090 assert_eq!(policy.encode(), "0,warn=0,detcore::random=1");
4091
4092 let everything = tracing::subscriber::with_default(AlwaysEnabled, || {
4093 ForwardPolicy::from_current_subscriber("")
4094 });
4095 assert_eq!(everything, ForwardPolicy::all());
4096
4097 let nothing =
4098 tracing::subscriber::with_default(tracing::subscriber::NoSubscriber::default(), || {
4099 ForwardPolicy::from_current_subscriber("warn,detcore::random=info")
4100 });
4101 assert!(!nothing.forwards_any());
4102 }
4103
4104 #[test]
4107 fn forward_policy_most_specific_target_decides() {
4108 let policy = ForwardPolicy::decode("1,detcore=0,detcore::random=1").unwrap();
4109 assert!(policy.forwards("hermit"));
4110 assert!(!policy.forwards("detcore"));
4111 assert!(!policy.forwards("detcore::tool_local"));
4112 assert!(policy.forwards("detcore::random"));
4113 assert!(policy.forwards("detcore::randomness"));
4114 }
4115
4116 #[test]
4117 fn forward_policy_encoding_round_trips_and_refuses_malformed_values() {
4118 assert_eq!(ForwardPolicy::decode("1").unwrap(), ForwardPolicy::all());
4119 let policy = ForwardPolicy::decode("0,warn=0,detcore::random=1").unwrap();
4120 assert_eq!(ForwardPolicy::decode(&policy.encode()).unwrap(), policy);
4121 for malformed in ["", "2", "1,detcore", "1,=1", "1,detcore=2", "1,detcore=1=0"] {
4122 assert!(
4123 ForwardPolicy::decode(malformed).is_err(),
4124 "{malformed:?} must be refused"
4125 );
4126 }
4127 }
4128 struct ModelPhysicalCompletion {
4129 fd: std::os::fd::OwnedFd,
4130 pid: i32,
4131 identity: u64,
4132 }
4133 unsafe impl super::NativePhysicalExitCompletion for ModelPhysicalCompletion {
4136 fn retained_pidfd(&self) -> std::os::fd::BorrowedFd<'_> {
4137 use std::os::fd::AsFd;
4138 self.fd.as_fd()
4139 }
4140 fn process_id(&self) -> i32 {
4141 self.pid
4142 }
4143 fn birth_identity(&self) -> u64 {
4144 self.identity
4145 }
4146 }
4147 fn model_completion(dead: bool) -> ModelPhysicalCompletion {
4148 use std::os::fd::FromRawFd;
4149 let mut child = dead.then(|| std::process::Command::new("true").spawn().unwrap());
4150 let pid = child
4151 .as_ref()
4152 .map_or(std::process::id(), std::process::Child::id);
4153 let raw = unsafe { libc::syscall(libc::SYS_pidfd_open, pid, 0) };
4154 assert!(raw >= 0);
4155 let fd = unsafe { std::os::fd::OwnedFd::from_raw_fd(raw as i32) };
4156 let mut stat: libc::stat = unsafe { std::mem::zeroed() };
4157 use std::os::fd::AsRawFd;
4158 assert_eq!(unsafe { libc::fstat(fd.as_raw_fd(), &mut stat) }, 0);
4159 if let Some(child) = child.as_mut() {
4160 assert!(child.wait().unwrap().success());
4161 }
4162 ModelPhysicalCompletion {
4163 fd,
4164 pid: pid as i32,
4165 identity: stat.st_ino,
4166 }
4167 }
4168 #[test]
4169 fn model_native_final_drain_requires_actual_death_and_credited_real_source() {
4170 if isolated_child(
4171 "detlog::tests::model_native_final_drain_requires_actual_death_and_credited_real_source",
4172 ) {
4173 return;
4174 }
4175 use std::os::fd::AsRawFd;
4176
4177 use super::CoordinatorForwardingCutError as Error;
4178 let mut fixture = NativeCutSource::new();
4179 fixture.send(41, 1, b"credited\n");
4180 fixture.check(1).unwrap();
4181 let identity = super::socket_identity(fixture.source.socket.as_raw_fd()).unwrap();
4182 drop(fixture.sender);
4183 let live = model_completion(false);
4184 assert_eq!(
4185 super::inspect_native_final_source(
4186 &mut fixture.source,
4187 identity,
4188 (live.pid, live.identity),
4189 &live
4190 ),
4191 Err(Error::InvalidOwner)
4192 );
4193 let dead = model_completion(true);
4194 assert!(
4195 super::inspect_native_final_source(
4196 &mut fixture.source,
4197 identity,
4198 (dead.pid, dead.identity),
4199 &dead
4200 )
4201 .is_ok()
4202 );
4203 assert_eq!(*fixture.written.lock().unwrap(), [b"credited\n".to_vec()]);
4204 }
4205 #[test]
4206 fn model_native_final_drain_retains_transport_loss_tail_and_identity_failures() {
4207 if isolated_child(
4208 "detlog::tests::model_native_final_drain_retains_transport_loss_tail_and_identity_failures",
4209 ) {
4210 return;
4211 }
4212 use std::os::fd::AsRawFd;
4213
4214 use super::CoordinatorForwardingCutError as Error;
4215 use super::ForwardedSourceError;
4216 let dead = model_completion(true);
4217 let mut fixture = NativeCutSource::new();
4218 fixture.check(0).unwrap();
4219 let identity = super::socket_identity(fixture.source.socket.as_raw_fd()).unwrap();
4220 drop(fixture.sender);
4221 fixture.source.transport_failure = Some(ForwardedSourceError::Io(libc::EIO));
4222 assert_eq!(
4223 super::inspect_native_final_source(
4224 &mut fixture.source,
4225 identity,
4226 (dead.pid, dead.identity),
4227 &dead
4228 ),
4229 Err(Error::SourceIo(libc::EIO))
4230 );
4231 assert_eq!(
4232 fixture.source.transport_failure,
4233 Some(ForwardedSourceError::Io(libc::EIO))
4234 );
4235 assert_eq!(
4236 super::inspect_native_final_source(
4237 &mut fixture.source,
4238 (identity.0, identity.1 ^ 1),
4239 (dead.pid, dead.identity),
4240 &dead
4241 ),
4242 Err(Error::SourceChanged)
4243 );
4244 let mut tail = NativeCutSource::new();
4245 tail.check(0).unwrap();
4246 tail.send(41, 1, b"uncredited\n");
4247 let identity = super::socket_identity(tail.source.socket.as_raw_fd()).unwrap();
4248 drop(tail.sender);
4249 assert_eq!(
4250 super::inspect_native_final_source(
4251 &mut tail.source,
4252 identity,
4253 (dead.pid, dead.identity),
4254 &dead
4255 ),
4256 Err(Error::OtherOwnerPending(41))
4257 );
4258 assert_eq!(tail.source.order.received[&41].count, 1);
4259 assert!(tail.written.lock().unwrap().is_empty());
4260 tail.source.loss_seen = true;
4261 assert_eq!(
4262 super::inspect_native_final_source(
4263 &mut tail.source,
4264 identity,
4265 (dead.pid, dead.identity),
4266 &dead
4267 ),
4268 Err(Error::DeterminismLoss)
4269 );
4270 }
4271
4272 #[test]
4273 fn model_native_final_drain_refuses_another_births_completion_without_consuming_source() {
4274 if isolated_child(
4275 "detlog::tests::model_native_final_drain_refuses_another_births_completion_without_consuming_source",
4276 ) {
4277 return;
4278 }
4279 use std::os::fd::AsRawFd;
4280
4281 use super::CoordinatorForwardingCutError as Error;
4282 let owner = model_completion(false);
4283 let unrelated = model_completion(true);
4284 assert_ne!(owner.identity, unrelated.identity);
4285 let mut fixture = NativeCutSource::new();
4286 fixture.check(0).unwrap();
4287 let identity = super::socket_identity(fixture.source.socket.as_raw_fd()).unwrap();
4288 drop(fixture.sender);
4289 assert_eq!(
4290 super::inspect_native_final_source(
4291 &mut fixture.source,
4292 identity,
4293 (owner.pid, owner.identity),
4294 &unrelated
4295 ),
4296 Err(Error::InvalidOwner)
4297 );
4298 assert_eq!(fixture.source.transport_failure, None);
4300 assert!(fixture.written.lock().unwrap().is_empty());
4301 }
4302
4303 type ForwardedReceiverStop =
4308 std::sync::Arc<std::sync::Mutex<Option<tokio::sync::oneshot::Sender<()>>>>;
4309
4310 struct ForwardedReceiverTask {
4311 runtime: tokio::runtime::Runtime,
4312 task: Option<tokio::task::JoinHandle<()>>,
4313 stop: ForwardedReceiverStop,
4314 done: Option<std::sync::mpsc::Sender<()>>,
4315 watchdog: Option<std::thread::JoinHandle<()>>,
4316 watchdog_fired: std::sync::Arc<std::sync::atomic::AtomicBool>,
4317 }
4318
4319 impl ForwardedReceiverTask {
4320 fn spawn(watched: std::os::fd::OwnedFd, generation: u64) -> Self {
4321 let runtime = tokio::runtime::Builder::new_multi_thread()
4322 .worker_threads(1)
4323 .enable_all()
4324 .build()
4325 .unwrap();
4326 let (stop, stopped) = tokio::sync::oneshot::channel();
4327 let stop = std::sync::Arc::new(std::sync::Mutex::new(Some(stop)));
4328 let watchdog_stop = stop.clone();
4329 let watchdog_fired = std::sync::Arc::new(std::sync::atomic::AtomicBool::new(false));
4330 let fired = watchdog_fired.clone();
4331 let (done, completed) = std::sync::mpsc::channel();
4332 let watchdog = std::thread::spawn(move || {
4333 if completed
4334 .recv_timeout(std::time::Duration::from_secs(5))
4335 .is_err()
4336 {
4337 fired.store(true, Ordering::SeqCst);
4338 if let Some(stop) = watchdog_stop.lock().unwrap().take() {
4339 let _ = stop.send(());
4340 }
4341 }
4342 });
4343 let task = runtime.spawn(super::receive_forwarded(watched, generation, stopped));
4344 Self {
4345 runtime,
4346 task: Some(task),
4347 stop,
4348 done: Some(done),
4349 watchdog: Some(watchdog),
4350 watchdog_fired,
4351 }
4352 }
4353
4354 fn request_stop(&self) {
4355 if let Some(stop) = self.stop.lock().unwrap().take() {
4356 let _ = stop.send(());
4357 }
4358 }
4359
4360 fn join(&mut self) -> (Result<(), tokio::task::JoinError>, bool) {
4361 let result = self.runtime.block_on(self.task.take().unwrap());
4362 let _ = self.done.take().unwrap().send(());
4363 let watchdog_ok = self.watchdog.take().unwrap().join().is_ok();
4364 (
4365 result,
4366 self.watchdog_fired.load(Ordering::SeqCst) || !watchdog_ok,
4367 )
4368 }
4369
4370 fn is_finished(&self) -> bool {
4371 self.task.as_ref().unwrap().is_finished()
4372 }
4373 }
4374
4375 impl Drop for ForwardedReceiverTask {
4376 fn drop(&mut self) {
4377 if self.task.is_some() {
4378 self.request_stop();
4379 let _ = self.join();
4380 }
4381 }
4382 }
4383
4384 struct ForwardedReceiverSourceCleanup;
4385 impl Drop for ForwardedReceiverSourceCleanup {
4386 fn drop(&mut self) {
4387 super::clear_forwarded_source();
4388 }
4389 }
4390
4391 struct ReceiverSource {
4392 sender: std::os::fd::OwnedFd,
4393 written: std::sync::Arc<std::sync::Mutex<Vec<Vec<u8>>>>,
4394 generation: u64,
4395 identity: (u64, u64),
4396 }
4397
4398 fn install_receiver_source() -> ReceiverSource {
4399 use std::os::fd::AsRawFd;
4400 let NativeCutSource {
4401 source,
4402 sender,
4403 written,
4404 } = NativeCutSource::new();
4405 let identity = super::socket_identity(source.socket.as_raw_fd()).unwrap();
4406 super::set_forwarded_source(source.socket, source.sink);
4407 let generation = super::FORWARDED_GENERATION.load(Ordering::SeqCst);
4408 ReceiverSource {
4409 sender,
4410 written,
4411 generation,
4412 identity,
4413 }
4414 }
4415
4416 fn send_receiver_record(sender: &std::os::fd::OwnedFd, record: &[u8]) {
4417 use std::os::fd::AsRawFd;
4418 let message = super::tagged_forwarded_message(41, 1, record);
4419 let sent = unsafe {
4421 libc::send(
4422 sender.as_raw_fd(),
4423 message.as_ptr().cast(),
4424 message.len(),
4425 libc::MSG_NOSIGNAL,
4426 )
4427 };
4428 assert_eq!(sent, message.len() as isize);
4429 }
4430
4431 fn receiver_watched_socket() -> std::os::fd::OwnedFd {
4432 super::FORWARDED_SOURCE
4433 .lock()
4434 .unwrap()
4435 .as_ref()
4436 .unwrap()
4437 .socket
4438 .try_clone()
4439 .unwrap()
4440 }
4441
4442 fn wait_for_receiver_record() -> bool {
4443 let deadline = std::time::Instant::now() + std::time::Duration::from_secs(2);
4444 while std::time::Instant::now() < deadline {
4445 let received = super::FORWARDED_SOURCE
4446 .lock()
4447 .unwrap()
4448 .as_ref()
4449 .unwrap()
4450 .order
4451 .received
4452 .get(&41)
4453 .is_some_and(|interval| interval.count == 1);
4454 if received {
4455 return true;
4456 }
4457 std::thread::sleep(std::time::Duration::from_millis(1));
4458 }
4459 false
4460 }
4461
4462 #[test]
4463 fn forwarded_receiver_retires_after_real_eof_without_rearming() {
4464 const CHILD: &str = "HERMIT_TEST_FORWARDED_RECEIVER_CHILD";
4465 const CASE: &str =
4466 "detlog::tests::forwarded_receiver_retires_after_real_eof_without_rearming";
4467 if std::env::var_os(CHILD).as_deref() != Some(std::ffi::OsStr::new(CASE)) {
4468 let output = std::process::Command::new(std::env::current_exe().unwrap())
4473 .args(["--exact", CASE, "--nocapture", "--test-threads=1"])
4474 .env(CHILD, CASE)
4475 .output()
4476 .unwrap();
4477 assert!(output.status.success(), "{output:?}");
4478 assert!(
4479 String::from_utf8_lossy(&output.stdout).contains("1 passed"),
4480 "{output:?}"
4481 );
4482 return;
4483 }
4484 use std::os::fd::AsRawFd;
4485 let _guard = global_source_test();
4486 let _cleanup = ForwardedReceiverSourceCleanup;
4487 let ReceiverSource {
4488 sender,
4489 written,
4490 generation,
4491 identity,
4492 } = install_receiver_source();
4493 super::RECEIVER_GENERATION.store(generation, Ordering::SeqCst);
4494 let (marker, mut marker_receiver) = tokio::sync::oneshot::channel();
4497 *super::RECEIVER_STOP.lock().unwrap() = Some(marker);
4498 let mut receiver = ForwardedReceiverTask::spawn(receiver_watched_socket(), generation);
4499 send_receiver_record(&sender, b"credited before EOF\n");
4500 assert!(wait_for_receiver_record(), "actual async task must collect");
4501 assert!(!receiver.is_finished(), "live EAGAIN must keep waiting");
4502 let credited = {
4503 let mut source = super::FORWARDED_SOURCE.lock().unwrap();
4504 super::inspect_coordinator_forwarding_cut(
4505 source.as_mut(),
4506 generation,
4507 41,
4508 1,
4509 None,
4510 || false,
4511 )
4512 };
4513 assert!(credited.is_ok());
4514 assert_eq!(
4515 *written.lock().unwrap(),
4516 [b"credited before EOF\n".to_vec()]
4517 );
4518 drop(sender);
4519 let (joined, watchdog_fired) = receiver.join();
4520 assert!(joined.is_ok(), "actual receiver task must join");
4521 assert!(!watchdog_fired, "EOF must retire without stop or abort");
4522 let retained = {
4523 let source = super::FORWARDED_SOURCE.lock().unwrap();
4524 let source = source.as_ref().unwrap();
4525 (
4526 source.transport_failure,
4527 super::socket_identity(source.socket.as_raw_fd()).unwrap(),
4528 source.order.pending.values().all(Vec::is_empty),
4529 source.order.received.is_empty(),
4530 )
4531 };
4532 assert_eq!(
4533 retained,
4534 (
4535 Some(super::ForwardedSourceError::Closed),
4536 identity,
4537 true,
4538 true
4539 )
4540 );
4541 assert_eq!(
4542 super::FORWARDED_GENERATION.load(Ordering::SeqCst),
4543 generation
4544 );
4545 assert_eq!(
4546 super::RECEIVER_GENERATION.load(Ordering::SeqCst),
4547 generation
4548 );
4549 assert!(matches!(
4550 marker_receiver.try_recv(),
4551 Err(tokio::sync::oneshot::error::TryRecvError::Empty)
4552 ));
4553 receiver
4554 .runtime
4555 .block_on(async { super::start_forwarded_receiver() });
4556 assert!(matches!(
4557 marker_receiver.try_recv(),
4558 Err(tokio::sync::oneshot::error::TryRecvError::Empty)
4559 ));
4560 }
4561
4562 #[test]
4563 fn forwarded_receiver_replacement_preserves_new_generation() {
4564 const CHILD: &str = "HERMIT_TEST_FORWARDED_RECEIVER_CHILD";
4565 const CASE: &str = "detlog::tests::forwarded_receiver_replacement_preserves_new_generation";
4566 if std::env::var_os(CHILD).as_deref() != Some(std::ffi::OsStr::new(CASE)) {
4567 let output = std::process::Command::new(std::env::current_exe().unwrap())
4571 .args(["--exact", CASE, "--nocapture", "--test-threads=1"])
4572 .env(CHILD, CASE)
4573 .output()
4574 .unwrap();
4575 assert!(output.status.success(), "{output:?}");
4576 assert!(
4577 String::from_utf8_lossy(&output.stdout).contains("1 passed"),
4578 "{output:?}"
4579 );
4580 return;
4581 }
4582 let _guard = global_source_test();
4583 let _cleanup = ForwardedReceiverSourceCleanup;
4584 let ReceiverSource {
4585 sender: old_sender,
4586 written: old_written,
4587 generation: old_generation,
4588 ..
4589 } = install_receiver_source();
4590 let old_watched = receiver_watched_socket();
4591 send_receiver_record(&old_sender, b"old queued packet\n");
4592 let ReceiverSource {
4593 sender,
4594 written,
4595 generation,
4596 ..
4597 } = install_receiver_source();
4598 assert_ne!(old_generation, generation);
4599 super::RECEIVER_GENERATION.store(generation, Ordering::SeqCst);
4600 let (marker, mut marker_receiver) = tokio::sync::oneshot::channel();
4601 *super::RECEIVER_STOP.lock().unwrap() = Some(marker);
4602 send_receiver_record(&sender, b"fresh queued packet\n");
4603 let mut stale = ForwardedReceiverTask::spawn(old_watched, old_generation);
4604 let (joined, watchdog_fired) = stale.join();
4605 assert!(joined.is_ok());
4606 assert!(!watchdog_fired, "stale generation must return naturally");
4607 let untouched = {
4608 let source = super::FORWARDED_SOURCE.lock().unwrap();
4609 let source = source.as_ref().unwrap();
4610 source.order.received.is_empty() && source.order.pending.is_empty()
4611 };
4612 assert!(
4613 untouched,
4614 "stale task cannot consume the fresh source packet"
4615 );
4616 assert!(old_written.lock().unwrap().is_empty());
4617 assert!(written.lock().unwrap().is_empty());
4618 assert_eq!(
4619 super::RECEIVER_GENERATION.load(Ordering::SeqCst),
4620 generation
4621 );
4622 assert!(matches!(
4623 marker_receiver.try_recv(),
4624 Err(tokio::sync::oneshot::error::TryRecvError::Empty)
4625 ));
4626 let mut fresh = ForwardedReceiverTask::spawn(receiver_watched_socket(), generation);
4627 assert!(wait_for_receiver_record());
4628 let queued = {
4629 let source = super::FORWARDED_SOURCE.lock().unwrap();
4630 let source = source.as_ref().unwrap();
4631 (source.transport_failure, source.order.pending[&41].clone())
4632 };
4633 assert_eq!(queued, (None, vec![b"fresh queued packet\n".to_vec()]));
4634 assert!(!fresh.is_finished(), "healthy open peer must keep waiting");
4635 fresh.request_stop();
4636 let (joined, watchdog_fired) = fresh.join();
4637 assert!(joined.is_ok());
4638 assert!(!watchdog_fired, "explicit healthy-source stop must join");
4639 assert!(written.lock().unwrap().is_empty());
4640 assert_eq!(
4641 super::RECEIVER_GENERATION.load(Ordering::SeqCst),
4642 generation
4643 );
4644 drop(sender);
4645 drop(old_sender);
4646 }
4647
4648 #[test]
4649 fn forwarded_receiver_retirement_preserves_uncredited_tail_refusal() {
4650 const CHILD: &str = "HERMIT_TEST_FORWARDED_RECEIVER_CHILD";
4651 const CASE: &str =
4652 "detlog::tests::forwarded_receiver_retirement_preserves_uncredited_tail_refusal";
4653 if std::env::var_os(CHILD).as_deref() != Some(std::ffi::OsStr::new(CASE)) {
4654 let output = std::process::Command::new(std::env::current_exe().unwrap())
4658 .args(["--exact", CASE, "--nocapture", "--test-threads=1"])
4659 .env(CHILD, CASE)
4660 .output()
4661 .unwrap();
4662 assert!(output.status.success(), "{output:?}");
4663 assert!(
4664 String::from_utf8_lossy(&output.stdout).contains("1 passed"),
4665 "{output:?}"
4666 );
4667 return;
4668 }
4669 use std::os::fd::AsRawFd;
4670
4671 use super::CoordinatorForwardingCutError as Error;
4672 let _guard = global_source_test();
4673 let _cleanup = ForwardedReceiverSourceCleanup;
4674 let ReceiverSource {
4675 sender,
4676 written,
4677 generation,
4678 identity,
4679 } = install_receiver_source();
4680 super::RECEIVER_GENERATION.store(generation, Ordering::SeqCst);
4681 let mut receiver = ForwardedReceiverTask::spawn(receiver_watched_socket(), generation);
4682 send_receiver_record(&sender, b"uncredited tail\n");
4683 drop(sender);
4684 let (joined, watchdog_fired) = receiver.join();
4685 assert!(joined.is_ok());
4686 assert!(!watchdog_fired, "EOF must retire without stop or abort");
4687 let dead = model_completion(true);
4690 let refusal = {
4691 let mut source = super::FORWARDED_SOURCE.lock().unwrap();
4692 super::inspect_native_final_source(
4693 source.as_mut().unwrap(),
4694 identity,
4695 (dead.pid, dead.identity),
4696 &dead,
4697 )
4698 };
4699 assert_eq!(refusal, Err(Error::OtherOwnerPending(41)));
4700 let retained = {
4701 let source = super::FORWARDED_SOURCE.lock().unwrap();
4702 let source = source.as_ref().unwrap();
4703 (
4704 source.transport_failure,
4705 super::socket_identity(source.socket.as_raw_fd()).unwrap(),
4706 source.order.received[&41].count,
4707 source.order.pending[&41].clone(),
4708 )
4709 };
4710 assert_eq!(
4711 retained,
4712 (
4713 Some(super::ForwardedSourceError::Closed),
4714 identity,
4715 1,
4716 vec![b"uncredited tail\n".to_vec()]
4717 )
4718 );
4719 assert!(written.lock().unwrap().is_empty());
4720 assert_eq!(
4721 super::FORWARDED_GENERATION.load(Ordering::SeqCst),
4722 generation
4723 );
4724 }
4725}
4726
4727#[cfg(test)]
4728mod root_lifecycle_record_tests {
4729 use std::io::Write;
4730 use std::os::fd::AsRawFd;
4731 use std::os::fd::FromRawFd;
4732 use std::os::fd::OwnedFd;
4733 use std::sync::Arc;
4734 use std::sync::Mutex;
4735
4736 use super::*;
4737
4738 #[derive(Clone)]
4739 struct Writer(Arc<Mutex<Vec<u8>>>);
4740 impl Write for Writer {
4741 fn write(&mut self, bytes: &[u8]) -> std::io::Result<usize> {
4742 self.0.lock().unwrap().extend_from_slice(bytes);
4743 Ok(bytes.len())
4744 }
4745 fn flush(&mut self) -> std::io::Result<()> {
4746 Ok(())
4747 }
4748 }
4749 impl<'a> tracing_subscriber::fmt::MakeWriter<'a> for Writer {
4750 type Writer = Self;
4751 fn make_writer(&'a self) -> Self {
4752 self.clone()
4753 }
4754 }
4755
4756 #[test]
4757 fn root_seed_parent_and_counted_shared_tail_are_real_production_routes() {
4758 const TEST: &str = "detlog::root_lifecycle_record_tests::root_seed_parent_and_counted_shared_tail_are_real_production_routes";
4759 const CHILD: &str = "HERMIT_ROOT_LIFECYCLE_RECORD_CHILD";
4760 if std::env::var_os(CHILD).as_deref() != Some(std::ffi::OsStr::new(TEST)) {
4761 let output = std::process::Command::new(std::env::current_exe().unwrap())
4762 .args(["--exact", TEST, "--nocapture", "--test-threads=1"])
4763 .env(CHILD, TEST)
4764 .output()
4765 .unwrap();
4766 assert!(output.status.success(), "{output:?}");
4767 assert!(
4768 String::from_utf8_lossy(&output.stdout).contains("1 passed"),
4769 "{output:?}"
4770 );
4771 return;
4772 }
4773 let output = Writer(Arc::new(Mutex::new(Vec::new())));
4774 let subscriber = tracing_subscriber::fmt()
4775 .without_time()
4776 .with_ansi(false)
4777 .with_max_level(tracing::Level::DEBUG)
4778 .with_writer(output.clone())
4779 .finish();
4780 let _subscriber = tracing::subscriber::set_default(subscriber);
4781 root_seed_records(3, 17, 29);
4782 let expected = output.0.lock().unwrap().clone();
4783 output.0.lock().unwrap().clear();
4784 {
4785 let span =
4786 tracing::debug_span!(target: "reverie_ptrace::lifecycle", "tracee.attach", pid = 3);
4787 let _entered = span.enter();
4788 root_seed_records(3, 17, 29);
4789 }
4790 assert_eq!(*output.0.lock().unwrap(), expected);
4791 let text = String::from_utf8(expected.clone()).unwrap();
4792 assert!(!text.contains("tracee.attach"));
4793 assert_eq!(text.lines().count(), 2);
4794 assert!(text.contains("INFO detcore::tool_local: DETLOG USER RAND: seeding PRNG for root thread with seed 17 (root tid 3)"));
4795 assert!(text.contains("INFO detcore::tool_local: DETLOG CHAOSRAND: seeding chaos scheduler with seed 29 (root tid 3)"));
4796 assert_eq!(text.matches(RECORD_SEPARATOR).count(), 2);
4797 output.0.lock().unwrap().clear();
4799 {
4800 let span = tracing::debug_span!("ordinary_parent", real = 7);
4801 let _entered = span.enter();
4802 crate::detlog!("ordinary event");
4803 }
4804 assert!(
4805 String::from_utf8(output.0.lock().unwrap().clone())
4806 .unwrap()
4807 .contains("ordinary_parent{real=7}")
4808 );
4809 output.0.lock().unwrap().clear();
4810 {
4811 let span = tracing::debug_span!("backend_setup", pid = 3);
4812 let _entered = span.enter();
4813 reverie::observe_tail_start(
4814 reverie::Pid::from_raw(3),
4815 reverie::syscalls::Sysno::exit_group,
4816 );
4817 }
4818 let native_tail = output.0.lock().unwrap().clone();
4819 assert!(
4820 !String::from_utf8(native_tail.clone())
4821 .unwrap()
4822 .contains("backend_setup")
4823 );
4824 assert!(
4825 String::from_utf8(native_tail.clone())
4826 .unwrap()
4827 .contains("INFO reverie::guest: [tool] (tid 3) admitted tail syscall: exit_group")
4828 );
4829 output.0.lock().unwrap().clear();
4830
4831 static SOCKET: AtomicI32 = AtomicI32::new(-1);
4832 fn records(target: &str, suffix: &str, index: u64, message: fmt::Arguments<'_>) {
4833 send_forwarded_record(
4834 SOCKET.load(Ordering::Acquire),
4835 target,
4836 suffix,
4837 index,
4838 message,
4839 );
4840 }
4841 fn plain(target: &str, index: u64, message: fmt::Arguments<'_>) {
4842 send_plain_info_record(Some(SOCKET.load(Ordering::Acquire)), target, index, message);
4843 }
4844 let mut fds = [-1; 2];
4845 assert_eq!(
4847 unsafe {
4848 libc::socketpair(
4849 libc::AF_UNIX,
4850 libc::SOCK_SEQPACKET | libc::SOCK_CLOEXEC,
4851 0,
4852 fds.as_mut_ptr(),
4853 )
4854 },
4855 0
4856 );
4857 let sender = unsafe { OwnedFd::from_raw_fd(fds[0]) };
4859 let receiver = unsafe { OwnedFd::from_raw_fd(fds[1]) };
4860 SOCKET.store(sender.as_raw_fd(), Ordering::Release);
4861 assert_eq!(take_forwarded_since_request(), 0);
4862 set_forwarder(records, ForwardPolicy::decode("1").unwrap()).unwrap();
4863 set_plain_info_forwarder(plain).unwrap();
4864 reverie::set_tail_start_forwarder(forward_tail_start).unwrap();
4865 assert!(reverie::set_tail_start_forwarder(forward_tail_start).is_err());
4866 {
4867 let span = tracing::debug_span!("backend_setup", pid = 3);
4868 let _entered = span.enter();
4869 root_seed_records(3, 17, 29);
4870 reverie::observe_tail_start(
4871 reverie::Pid::from_raw(3),
4872 reverie::syscalls::Sysno::exit_group,
4873 );
4874 }
4875 let mut rendered = Vec::new();
4876 for index in 1..=3 {
4877 let mut bytes = [0_u8; 65536];
4878 let n = unsafe {
4880 libc::recv(
4881 receiver.as_raw_fd(),
4882 bytes.as_mut_ptr().cast(),
4883 bytes.len(),
4884 libc::MSG_DONTWAIT,
4885 )
4886 };
4887 assert!(n > 0);
4888 let (tid, got, payload) = split_forwarded_message(&bytes[..n as usize]).unwrap();
4889 assert_eq!(tid, current_tid());
4890 assert_eq!(got, index);
4891 if index < 3 {
4892 rendered.push(b' ');
4893 rendered.extend_from_slice(payload);
4894 } else {
4895 let (target, message) = decode_plain_info(payload).unwrap();
4896 assert_eq!(target, "reverie::guest");
4897 let full = format!(" INFO {target}: {message}\n");
4898 assert_eq!(full.as_bytes(), native_tail);
4899 }
4900 }
4901 assert_eq!(rendered, expected);
4902 assert_eq!(take_forwarded_since_request(), 3);
4903 assert!(
4904 output.0.lock().unwrap().is_empty(),
4905 "forwarded branch must not duplicate tracing"
4906 );
4907 let mut byte = [0];
4908 assert_eq!(
4910 unsafe {
4911 libc::recv(
4912 receiver.as_raw_fd(),
4913 byte.as_mut_ptr().cast(),
4914 1,
4915 libc::MSG_DONTWAIT,
4916 )
4917 },
4918 -1
4919 );
4920 assert_eq!(
4921 std::io::Error::last_os_error().raw_os_error(),
4922 Some(libc::EAGAIN)
4923 );
4924 let blocked = ForwardPolicy::decode("1,reverie::guest=0").unwrap();
4927 assert!(!blocked.forwards("reverie::guest"));
4928 assert!(blocked.forwards("detcore::tool_local"));
4929 for target in ["reverie", "reverie::guest::extra", "reverie_ptrace::task"] {
4930 assert!(
4931 encode_plain_info(target, "not admitted").is_err(),
4932 "{target}"
4933 );
4934 }
4935 }
4936}