use core::fmt::Display;
use core::fmt::Formatter;
use core::fmt::Result;
use std::cmp::Ordering;
use std::collections::HashMap;
use std::io::Write;
use std::path::Path;
use std::process::Command;
use std::str::FromStr;
use std::sync::LazyLock;
use clap;
use clap::Parser;
use regex::Regex;
use tempfile::NamedTempFile;
use crate::detlog::DetLogEvent;
use crate::detlog::DetLogRecord;
pub const TRUNCATION_MARKER: &str = "=== HERMIT LOG TRUNCATED: reached the configured size bound \
(HERMIT_LOG_MAX_BYTES). Output beyond this point was DISCARDED. The run itself continued and \
was NOT affected. ===";
pub const STRIP_WALL_CLOCK_PREFIX_V1: &str = "real-wall-clock-prefix/v1";
pub const CANON_ADDRESS_ORDINAL_V1: &str = "host-address-to-first-appearance-ordinal/v1";
pub fn log_was_truncated(log_text: &str) -> bool {
let trimmed = log_text.trim_end_matches(['\n', '\r']);
if !trimmed.ends_with(TRUNCATION_MARKER) {
return false;
}
let marker_start = trimmed.len() - TRUNCATION_MARKER.len();
marker_start == 0 || trimmed.as_bytes()[marker_start - 1] == b'\n'
}
#[derive(Debug, Default, Clone, Copy, PartialEq, Eq)]
pub enum LogComparisonMode {
#[default]
Deterministic,
Info,
FullTrace,
}
#[derive(Debug, Clone, PartialEq, Eq)]
pub struct ComparisonSideLabels {
pub left: String,
pub right: String,
}
impl ComparisonSideLabels {
pub fn new(left: impl Into<String>, right: impl Into<String>) -> Self {
Self {
left: left.into(),
right: right.into(),
}
}
}
impl Default for ComparisonSideLabels {
fn default() -> Self {
Self::new("run 1", "run 2")
}
}
#[derive(Debug, Parser, Clone)]
pub struct LogDiffOpts {
#[clap(long = "unsafe-strip-lines")]
pub strip_lines: bool,
#[clap(long = "canonicalize-host-addresses")]
pub canonicalize_addresses: bool,
#[clap(skip)]
pub comparison: LogComparisonMode,
#[clap(skip)]
pub side_labels: ComparisonSideLabels,
#[clap(skip)]
pub require_structured_events: bool,
#[clap(long)]
pub print_logs: bool,
#[clap(long, default_value = "20")]
pub limit: u64,
#[clap(long)]
pub ignore_lines: Vec<String>,
#[clap(long, default_value = "0")]
pub syscall_history: u64,
#[clap(long)]
pub no_color: bool,
#[clap(long)]
pub skip_commit: bool,
#[clap(long)]
pub skip_detlog: bool,
#[clap(long)]
pub git_diff: bool,
#[clap(long, default_values = &["syscall", "syscallresult", "other"])]
pub include_detlogs: Vec<DetLogFilter>,
}
impl LogDiffOpts {
fn is_skip(&self, filter: DetLogFilter) -> bool {
!self.include_detlogs.contains(&filter)
}
fn skip_detlog(&self, entry: &LogMessage<'_>) -> bool {
if self.skip_detlog {
return true;
}
if is_detlog_syscall(entry) && self.is_skip(DetLogFilter::Syscall) {
return true;
}
if is_detlog_syscall_result(entry) && self.is_skip(DetLogFilter::SyscallResult) {
return true;
}
if !is_detlog_syscall(entry)
&& !is_detlog_syscall_result(entry)
&& self.is_skip(DetLogFilter::Other)
{
return true;
}
false
}
fn filter_deterministic<'a>(&self, v: &[LogMessage<'a>]) -> Vec<LogMessage<'a>> {
v.iter()
.filter_map(|message| {
if (is_detlog(message)
&& !self.skip_detlog(message)
&& !is_scheduler_committed_time(message))
|| (is_commit(message)
&& !self.skip_commit
&& !is_internal_io_poll_commit(message))
{
Some(*message)
} else {
None
}
})
.collect()
}
}
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
enum LogNormalization {
Exact,
Stripped,
Canonical,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
struct LogComparisonPolicy {
comparison: LogComparisonMode,
normalization: LogNormalization,
}
impl LogComparisonPolicy {
fn from_options(options: &LogDiffOpts) -> Self {
let normalization = if options.strip_lines {
LogNormalization::Stripped
} else if options.canonicalize_addresses {
LogNormalization::Canonical
} else {
LogNormalization::Exact
};
Self {
comparison: options.comparison,
normalization,
}
}
fn name(self) -> &'static str {
match (self.comparison, self.normalization) {
(LogComparisonMode::Deterministic, LogNormalization::Exact) => "Deterministic",
(LogComparisonMode::Deterministic, LogNormalization::Stripped) => "Stripped",
(LogComparisonMode::Deterministic, LogNormalization::Canonical) => {
"Deterministic with Canonical host-address normalization"
}
(LogComparisonMode::Info, LogNormalization::Exact) => "Info",
(LogComparisonMode::Info, LogNormalization::Stripped) => {
"Info with Stripped normalization"
}
(LogComparisonMode::Info, LogNormalization::Canonical) => "Canonical",
(LogComparisonMode::FullTrace, LogNormalization::Exact) => "FullTrace",
(LogComparisonMode::FullTrace, LogNormalization::Stripped) => {
"FullTrace with Stripped normalization"
}
(LogComparisonMode::FullTrace, LogNormalization::Canonical) => {
"FullTrace with Canonical host-address normalization"
}
}
}
}
#[derive(Debug, Clone, PartialEq, Eq)]
pub enum DetLogFilter {
Syscall,
SyscallResult,
Other,
}
impl FromStr for DetLogFilter {
type Err = anyhow::Error;
fn from_str(s: &str) -> std::result::Result<Self, Self::Err> {
match s.to_lowercase().as_str() {
"syscall" => Ok(DetLogFilter::Syscall),
"syscallresult" => Ok(DetLogFilter::SyscallResult),
"other" => Ok(DetLogFilter::Other),
_ => Err(anyhow::Error::msg(format!(
"unknown value {} for DetLogFilter",
s
))),
}
}
}
impl Default for LogDiffOpts {
fn default() -> Self {
let v: Vec<String> = vec![];
LogDiffOpts::parse_from(v.iter())
}
}
pub fn strip_log_entry(log: &str) -> String {
static RE0: LazyLock<Regex> = LazyLock::new(|| Regex::new(r"\b0[xX][A-Fa-f0-9]+\b").unwrap());
static RE1: LazyLock<Regex> =
LazyLock::new(|| Regex::new(r"\b[\d][\d_]*(?:\.[\d][\d_]*)?(?:ns|us|µs|ms)?\b").unwrap());
static RE2: LazyLock<Regex> = LazyLock::new(|| Regex::new(r#"/tmp/[^"]*""#).unwrap());
static RE3: LazyLock<Regex> = LazyLock::new(|| Regex::new(r"/proc/[\d]+/").unwrap());
static RE4: LazyLock<Regex> = LazyLock::new(|| Regex::new(r"\b[\d][\d_.]*s\b").unwrap());
let log = RE4.replace_all(log, "<NANOSECONDS>");
let log = RE3.replace_all(&log, "/proc/<PID>/");
let log = RE0.replace_all(&log, "<ADDR>");
let log = RE1.replace_all(&log, "<NUM>");
let log = RE2.replace_all(&log, "/tmp/<somewhere>\"");
String::from(log)
}
pub fn host_addr(addr: usize) -> String {
format!("<hostaddr {addr:#x}>")
}
fn canonicalize_addresses_in_line(
line: &str,
map: &mut HashMap<String, usize>,
next: &mut usize,
) -> String {
static RE_HOSTADDR: LazyLock<Regex> =
LazyLock::new(|| Regex::new(r"<hostaddr (0[xX][A-Fa-f0-9]+)>").unwrap());
RE_HOSTADDR
.replace_all(line, |caps: ®ex::Captures| {
let addr = &caps[1];
let ord = match map.get(addr) {
Some(existing) => *existing,
None => {
let assigned = *next;
*next += 1;
map.insert(addr.to_string(), assigned);
assigned
}
};
format!("<addr{ord}>")
})
.into_owned()
}
fn messages_for_comparison(
messages: &[LogMessage<'_>],
policy: LogComparisonPolicy,
) -> Vec<String> {
match policy.normalization {
LogNormalization::Stripped => messages
.iter()
.map(|message| strip_log_entry(message.text))
.collect(),
LogNormalization::Canonical => {
let mut addresses = HashMap::new();
let mut next_address = 1usize;
messages
.iter()
.map(|message| {
canonicalize_addresses_in_line(message.text, &mut addresses, &mut next_address)
})
.collect()
}
LogNormalization::Exact => messages
.iter()
.map(|message| message.text.to_owned())
.collect(),
}
}
#[cfg(test)]
fn canonical_info_from_str(contents: &str) -> std::io::Result<Vec<String>> {
canonical_info_from_str_with_filter(contents, |_| true)
}
fn canonical_info_from_str_with_filter(
contents: &str,
keep_record: impl Fn(&str) -> bool,
) -> std::io::Result<Vec<String>> {
let info = filter_infos(
&extract_log_messages(contents)?
.into_iter()
.filter(|record| keep_record(record.text))
.collect::<Vec<_>>(),
);
let opts = LogDiffOpts {
canonicalize_addresses: true,
comparison: LogComparisonMode::Info,
..Default::default()
};
Ok(messages_for_comparison(
&info,
LogComparisonPolicy::from_options(&opts),
))
}
pub fn write_canonical_info(file: &Path, writer: &mut impl Write) -> std::io::Result<usize> {
write_canonical_info_with_filter(file, writer, |_| true)
}
pub fn write_bitwise_info_v1_bytes(
bytes: &[u8],
side_label: &str,
writer: &mut impl Write,
) -> std::io::Result<usize> {
let contents = std::str::from_utf8(bytes).map_err(|error| {
std::io::Error::new(
std::io::ErrorKind::InvalidData,
format!("{side_label} is not UTF-8: {error}"),
)
})?;
if log_was_truncated(contents) {
return Err(std::io::Error::new(
std::io::ErrorKind::InvalidData,
format!("{side_label} was truncated at the configured size bound"),
));
}
let records = extract_log_messages(contents)
.map_err(|error| std::io::Error::new(error.kind(), format!("{side_label} {error}")))?;
validate_structured_events(side_label, &records, true)?;
let info = filter_infos(&records);
let options = bitwise_info_v1_options(ComparisonSideLabels::new(side_label, side_label));
let messages = messages_for_comparison(&info, LogComparisonPolicy::from_options(&options));
for message in &messages {
writeln!(writer, "{message}")?;
}
Ok(messages.len())
}
pub fn write_canonical_info_with_filter(
file: &Path,
writer: &mut impl Write,
keep_record: impl Fn(&str) -> bool,
) -> std::io::Result<usize> {
let bytes = std::fs::read(file)?;
let contents = std::str::from_utf8(&bytes).map_err(|error| {
std::io::Error::new(
std::io::ErrorKind::InvalidData,
format!("{} is not UTF-8: {error}", file.display()),
)
})?;
let messages = canonical_info_from_str_with_filter(contents, keep_record)?;
for message in &messages {
writeln!(writer, "{message}")?;
}
Ok(messages.len())
}
static RECORD_START: LazyLock<Regex> = LazyLock::new(|| {
Regex::new(r"((Jan|Feb|Mar|Apr|May|Jun|Jul|Aug|Sep|Oct|Nov|Dec) \d\d \d\d:\d\d:\d\d\.\d+|\d+-\d\d-\d\dT\d\d:\d\d:\d\d.\d+Z) +")
.unwrap()
});
fn record_starts(contents: &str) -> Vec<usize> {
RECORD_START
.find_iter(contents)
.map(|m| m.start())
.collect()
}
pub fn complete_record_count(contents: &str) -> usize {
record_starts(contents).len().saturating_sub(1)
}
pub fn take_complete_records(contents: &str, n: usize) -> Option<&str> {
let starts = record_starts(contents);
if n == 0 {
return Some(&contents[..0]);
}
starts.get(n).map(|end| &contents[..*end])
}
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
struct LogMessage<'a> {
index: usize,
text: &'a str,
event: Option<DetLogEvent>,
}
fn extract_log_messages(contents: &str) -> std::io::Result<Vec<LogMessage<'_>>> {
let ts = &*RECORD_START;
let tag = Regex::new("^(ERROR|WARN|INFO|DEBUG|TRACE) ").unwrap();
ts.split(contents) .enumerate()
.map(|(i, s)| (i, s.trim()))
.filter(|(_, s)| !s.is_empty())
.map(|(i, s)| {
if !tag.is_match(s) {
return Err(std::io::Error::new(
std::io::ErrorKind::InvalidData,
format!(
"log line {i} has no ERROR/WARN/INFO/DEBUG/TRACE tag, so it cannot be \
placed in the compared record stream: {s}"
),
));
}
let (text, record) = DetLogRecord::split(s).map_err(|error| {
std::io::Error::new(
std::io::ErrorKind::InvalidData,
format!("log record {i} has an invalid structured DETLOG result: {error}"),
)
})?;
Ok(LogMessage {
index: i,
text,
event: record.map(|record| record.event),
})
})
.collect()
}
fn is_info(message: &LogMessage<'_>) -> bool {
message.text.starts_with("INFO ")
}
fn historical_is_commit(line: &str) -> bool {
line.contains(" COMMIT ")
}
fn historical_is_detlog(line: &str) -> bool {
line.contains(" DETLOG ")
}
fn is_commit(message: &LogMessage<'_>) -> bool {
match message.event {
Some(DetLogEvent::SchedulerCommit { .. }) => true,
Some(_) => false,
None => historical_is_commit(message.text),
}
}
fn is_detlog(message: &LogMessage<'_>) -> bool {
match message.event {
Some(
DetLogEvent::Other
| DetLogEvent::Syscall
| DetLogEvent::SyscallResult { .. }
| DetLogEvent::SchedulerCommittedTime,
) => true,
Some(_) => false,
None => historical_is_detlog(message.text),
}
}
fn is_internal_io_poll_commit(message: &LogMessage<'_>) -> bool {
match message.event {
Some(DetLogEvent::SchedulerCommit {
internal_io_poll, ..
}) => internal_io_poll,
Some(_) => false,
None => {
historical_is_commit(message.text)
&& (message.text.contains("{InternalIOPolling: ")
|| message.text.contains(" [sabre-internal-pipe-io]")
|| message.text.contains(" [sabre-loopback-poll-zero-timeout]"))
}
}
}
fn is_scheduler_committed_time(message: &LogMessage<'_>) -> bool {
match message.event {
Some(DetLogEvent::SchedulerCommittedTime) => true,
Some(_) => false,
None => message.text.contains("advancing committed_time from "),
}
}
fn is_detcore(message: &LogMessage<'_>) -> bool {
static PREFIX: LazyLock<Regex> =
LazyLock::new(|| Regex::new("^(ERROR|WARN|INFO|DEBUG|TRACE).* detcore:").unwrap());
PREFIX.is_match(message.text)
}
fn is_detlog_syscall(message: &LogMessage<'_>) -> bool {
match message.event {
Some(DetLogEvent::Syscall | DetLogEvent::SyscallResult { .. }) => true,
Some(_) => false,
None => historical_is_detlog(message.text) && message.text.contains("[syscall]"),
}
}
fn is_detlog_syscall_result(message: &LogMessage<'_>) -> bool {
match message.event {
Some(DetLogEvent::SyscallResult { .. }) => true,
Some(_) => false,
None => is_detlog_syscall(message) && message.text.contains("finish syscall"),
}
}
fn event_matches_human_record(event: DetLogEvent, text: &str) -> bool {
match event {
DetLogEvent::Other
| DetLogEvent::Syscall
| DetLogEvent::SyscallResult { .. }
| DetLogEvent::SchedulerCommittedTime => historical_is_detlog(text),
DetLogEvent::SchedulerCommit { .. } => historical_is_commit(text),
DetLogEvent::SchedulerEmptyQueueKick => text.contains(SCHEDULER_EMPTY_QUEUE_KICK),
}
}
fn validate_structured_events(
label: &str,
messages: &[LogMessage<'_>],
require: bool,
) -> std::io::Result<()> {
for message in messages {
let is_semantic_record = historical_is_detlog(message.text)
|| historical_is_commit(message.text)
|| message.text.contains(SCHEDULER_EMPTY_QUEUE_KICK);
if require && is_semantic_record && message.event.is_none() {
return Err(std::io::Error::new(
std::io::ErrorKind::InvalidData,
format!(
"{label} log record {} is missing its structured DETLOG result",
message.index
),
));
}
if let Some(event) = message.event
&& !event_matches_human_record(event, message.text)
{
return Err(std::io::Error::new(
std::io::ErrorKind::InvalidData,
format!(
"{label} log record {} has structured DETLOG kind {:?} that disagrees with its human record",
message.index, event
),
));
}
}
Ok(())
}
fn _truncate_messages(_v: &[&str]) -> String {
unimplemented!()
}
fn filter_infos<'a>(v: &[LogMessage<'a>]) -> Vec<LogMessage<'a>> {
v.iter()
.filter(|message| is_info(message))
.copied()
.collect()
}
fn filter_detcore<'a>(v: &[LogMessage<'a>]) -> Vec<LogMessage<'a>> {
v.iter()
.filter(|message| is_detcore(message))
.copied()
.collect()
}
const SCHEDULER_EMPTY_QUEUE_KICK: &str = "zero threads left anywhere, fizzling.";
fn count_empty_queue_kicks(v: &[LogMessage<'_>]) -> usize {
v.iter()
.filter(|message| match message.event {
Some(DetLogEvent::SchedulerEmptyQueueKick) => true,
Some(_) => false,
None => message.text.contains(SCHEDULER_EMPTY_QUEUE_KICK),
})
.count()
}
const RUNTIME_MAPS_READ_RESOURCE: &str = r#"Path("/proc/self/maps")"#;
fn describe_maps_commit(first: Option<(u64, Option<u64>)>) -> String {
match first {
Some((turn, Some(nanoseconds))) => {
format!("first at turn {turn}, committed virtual time {nanoseconds}ns")
}
Some((turn, None)) => format!("first at turn {turn}, committed virtual time unrecorded"),
None => "no such record".to_string(),
}
}
fn maps_read_commits(v: &[LogMessage<'_>]) -> (usize, Option<(u64, Option<u64>)>) {
let mut count = 0;
let mut first = None;
for message in v {
let reads_runtime_maps = match message.event {
Some(DetLogEvent::SchedulerCommit {
runtime_maps_read, ..
}) => runtime_maps_read,
Some(_) => false,
None => message.text.contains(RUNTIME_MAPS_READ_RESOURCE),
};
if !reads_runtime_maps {
continue;
}
let Some(position) = commit_position(message) else {
continue;
};
count += 1;
if first.is_none() {
first = Some(position);
}
}
(count, first)
}
fn filter_ignored<'a>(lines: Vec<LogMessage<'a>>, omits: &Vec<String>) -> Vec<LogMessage<'a>> {
lines
.into_iter()
.filter(|message| {
let mut keep = true;
for omit in omits {
if message.text.contains(omit) {
keep = false
}
}
keep
})
.collect()
}
fn collect_syscalls<'a>(v: &[LogMessage<'a>]) -> Vec<LogMessage<'a>> {
v.iter()
.filter(|entry| is_detlog_syscall(entry))
.copied()
.collect()
}
fn matched_prefix_length(compared_left: &[String], compared_right: &[String]) -> usize {
compared_left
.iter()
.zip(compared_right)
.take_while(|(left, right)| left == right)
.count()
}
fn matched_prefix_for_verdict(
diff_found: bool,
prefix: usize,
compared_left: usize,
compared_right: usize,
) -> Option<usize> {
let consistent = if diff_found {
prefix < compared_left.max(compared_right)
} else {
prefix == compared_left && prefix == compared_right
};
consistent.then_some(prefix)
}
fn first_different_message_indices(
left: &[LogMessage<'_>],
compared_left: &[String],
right: &[LogMessage<'_>],
compared_right: &[String],
) -> Option<(Option<usize>, Option<usize>)> {
let common = compared_left.len().min(compared_right.len());
let position = matched_prefix_length(compared_left, compared_right);
if position < common {
return Some((Some(left[position].index), Some(right[position].index)));
}
match compared_left.len().cmp(&compared_right.len()) {
Ordering::Less => Some((None, Some(right[common].index))),
Ordering::Greater => Some((Some(left[common].index), None)),
Ordering::Equal => None,
}
}
fn first_divergent_message(message: &LogMessage<'_>) -> String {
static FINISHED_SYSCALL: LazyLock<Regex> =
LazyLock::new(|| Regex::new(r"(finish syscall #)[0-9][0-9_]*").unwrap());
static COMMIT_TURN: LazyLock<Regex> =
LazyLock::new(|| Regex::new(r"(\bCOMMIT turn )[0-9][0-9_]*\b").unwrap());
static COMMITTED_TIME: LazyLock<Regex> = LazyLock::new(|| {
Regex::new(r"(\b(?:at time|on previously committed) )[0-9][0-9_]*(?:\.[0-9_]+)?(?:ns|s)?\b")
.unwrap()
});
let (first_line, continuation) = match message.text.split_once('\n') {
Some((first_line, continuation)) => (first_line, Some(continuation)),
None => (message.text, None),
};
let first_line =
if is_detlog_syscall_result(message) && finished_syscall_number(message).is_some() {
FINISHED_SYSCALL
.replace_all(first_line, "${1}<NUM>")
.into_owned()
} else {
first_line.to_string()
};
let first_line = if is_commit(message) && commit_position(message).is_some() {
let first_line = COMMIT_TURN.replace_all(&first_line, "${1}<NUM>");
COMMITTED_TIME
.replace_all(&first_line, "${1}<NANOSECONDS>")
.into_owned()
} else {
first_line
};
match continuation {
Some(continuation) => format!("{first_line}\n{continuation}"),
None => first_line,
}
}
fn compared_message_at_record(
records: &[LogMessage<'_>],
compared: &[String],
record: Option<usize>,
) -> Option<String> {
let record = record?;
let position = records.iter().position(|message| message.index == record)?;
let original = records.get(position)?;
let prepared = LogMessage {
index: original.index,
text: compared.get(position)?,
event: original.event,
};
Some(first_divergent_message(&prepared))
}
fn parse_underscored_u64(value: &str) -> Option<u64> {
value.replace('_', "").parse().ok()
}
fn parse_virtual_nanoseconds(value: &str, unit: Option<&str>) -> Option<u64> {
match unit {
None | Some("ns") if !value.contains('.') => parse_underscored_u64(value),
Some("s") => {
let value = value.replace('_', "");
let (seconds, fraction) = value.split_once('.').unwrap_or((&value, ""));
if fraction.len() > 9 || !fraction.bytes().all(|byte| byte.is_ascii_digit()) {
return None;
}
let seconds = seconds.parse::<u64>().ok()?;
let fraction = if fraction.is_empty() {
0
} else {
let digits = fraction.parse::<u64>().ok()?;
digits.checked_mul(10_u64.pow((9 - fraction.len()) as u32))?
};
seconds.checked_mul(1_000_000_000)?.checked_add(fraction)
}
_ => None,
}
}
fn historical_commit_position(message: &str) -> Option<(u64, Option<u64>)> {
static TURN: LazyLock<Regex> =
LazyLock::new(|| Regex::new(r"\bCOMMIT turn ([0-9][0-9_]*)\b").unwrap());
static TIME: LazyLock<Regex> = LazyLock::new(|| {
Regex::new(r"\b(?:at time|on previously committed) ([0-9][0-9_]*(?:\.[0-9_]+)?)(ns|s)?\b")
.unwrap()
});
let turn = parse_underscored_u64(TURN.captures(message)?.get(1)?.as_str())?;
let virtual_nanoseconds = TIME.captures(message).and_then(|captures| {
parse_virtual_nanoseconds(
captures.get(1)?.as_str(),
captures.get(2).map(|unit| unit.as_str()),
)
});
Some((turn, virtual_nanoseconds))
}
fn commit_position(message: &LogMessage<'_>) -> Option<(u64, Option<u64>)> {
match message.event {
Some(DetLogEvent::SchedulerCommit {
scheduler_turn,
virtual_nanoseconds,
..
}) => Some((scheduler_turn, Some(virtual_nanoseconds))),
Some(_) => None,
None => historical_commit_position(message.text),
}
}
fn commit_position_at_or_before(
messages: &[LogMessage<'_>],
message_index: usize,
) -> Option<(u64, Option<u64>)> {
messages
.iter()
.rev()
.filter(|message| message.index <= message_index)
.find_map(commit_position)
}
fn historical_finished_syscall_number(line: &str) -> Option<u64> {
let rest = line.split("finish syscall #").nth(1)?;
let digits: String = rest.chars().take_while(char::is_ascii_digit).collect();
digits.parse().ok()
}
fn finished_syscall_number(message: &LogMessage<'_>) -> Option<u64> {
match message.event {
Some(DetLogEvent::SyscallResult {
finished_syscall_number,
}) => Some(finished_syscall_number),
Some(_) => None,
None => historical_finished_syscall_number(message.text),
}
}
fn finished_syscall_at_or_before(v: &[LogMessage<'_>], message_index: usize) -> Option<u64> {
v.iter()
.rev()
.filter(|message| message.index <= message_index)
.find_map(finished_syscall_number)
}
fn syscall_at_or_before<'a>(
syscalls: &'a [LogMessage<'a>],
index: usize,
) -> Option<LogMessage<'a>> {
syscalls
.iter()
.rev()
.find(|message| message.index <= index)
.copied()
}
fn sentence_case_label(label: &str) -> String {
let mut characters = label.chars();
match characters.next() {
Some(first) => first.to_uppercase().collect::<String>() + characters.as_str(),
None => String::new(),
}
}
fn write_syscall_context(
w: &mut impl std::io::Write,
left_index: usize,
right_index: usize,
left_syscalls: &[LogMessage<'_>],
right_syscalls: &[LogMessage<'_>],
labels: &ComparisonSideLabels,
history_count: u64,
) -> std::io::Result<()> {
if history_count == 0 {
return Ok(());
}
let left_current = syscall_at_or_before(left_syscalls, left_index);
let right_current = syscall_at_or_before(right_syscalls, right_index);
if left_current.is_none() && right_current.is_none() {
return Ok(());
}
writeln!(w, "Divergent syscall context:")?;
for (label, current) in [
(labels.left.as_str(), left_current),
(labels.right.as_str(), right_current),
] {
if let Some(syscall) = current {
writeln!(
w,
" {label}, log message {}: {}",
syscall.index, syscall.text
)?;
} else {
writeln!(w, " {label}: <no syscall observed>")?;
}
}
let history_limit = usize::try_from(history_count).unwrap_or(usize::MAX);
for (label, index, syscalls) in [
(labels.left.as_str(), left_index, left_syscalls),
(labels.right.as_str(), right_index, right_syscalls),
] {
let history_boundary =
syscall_at_or_before(syscalls, index).map_or(index, |current| current.index);
let mut history = syscalls
.iter()
.rev()
.filter(|entry| entry.index < history_boundary && is_detlog_syscall_result(entry))
.take(history_limit)
.copied()
.collect::<Vec<_>>();
history.reverse();
if !history.is_empty() {
writeln!(w, " Prior completed syscalls for {label}:")?;
for syscall in history {
writeln!(w, " {}", syscall.text)?;
}
}
}
writeln!(w)?;
Ok(())
}
pub struct Comparison<'a> {
left: &'a str,
right: &'a str,
no_color: bool,
}
impl<'a> Comparison<'a> {
pub fn new(no_color: bool, left: &'a str, right: &'a str) -> Comparison<'a> {
Comparison {
left,
right,
no_color,
}
}
}
impl<'a> Display for Comparison<'a> {
fn fmt(&self, f: &mut Formatter) -> Result {
if self.no_color {
writeln!(f, "Diff < left / right > :")?;
writeln!(f, "<\"{}\"", self.left)?;
writeln!(f, ">\"{}\"", self.right)
} else {
pretty_assertions::Comparison::new(&self.left, &self.right).fmt(f)
}
}
}
fn diff_vecs(
which: &str,
left: (&[LogMessage<'_>], &[String]),
right: (&[LogMessage<'_>], &[String]),
opts: &LogDiffOpts,
w: &mut impl std::io::Write,
left_syscalls: &[LogMessage<'_>],
right_syscalls: &[LogMessage<'_>],
) -> std::io::Result<bool> {
let (v1, compared_left) = left;
let (v2, compared_right) = right;
writeln!(w, " Comparing {which} messages...\n")?;
if v1.is_empty() && v2.is_empty() {
return Ok(false);
}
let mut diff_count = 0;
for (position, (left, right)) in v1.iter().zip(v2.iter()).enumerate() {
let left_compared = &compared_left[position];
let right_compared = &compared_right[position];
if left_compared == right_compared {
continue;
}
if diff_count >= opts.limit && opts.limit != 0 {
writeln!(
w,
"More than {} differences, eliding the rest...",
opts.limit
)?;
break;
}
write!(
w,
"({which}) Mismatch at log messages {} ({}) and {} ({}): {}",
left.index,
opts.side_labels.left,
right.index,
opts.side_labels.right,
Comparison::new(opts.no_color, left_compared, right_compared)
)?;
if opts.strip_lines || opts.canonicalize_addresses {
write!(
w,
"({which}) Original entries before normalization: {}",
Comparison::new(opts.no_color, left.text, right.text)
)?;
}
write_syscall_context(
w,
left.index,
right.index,
left_syscalls,
right_syscalls,
&opts.side_labels,
opts.syscall_history,
)?;
diff_count += 1;
}
match v1.len().cmp(&v2.len()) {
Ordering::Less => {
writeln!(
w,
"{} contains {} extra messages not matched in {}. Displaying up to 10:",
sentence_case_label(&opts.side_labels.right),
v2.len() - v1.len(),
opts.side_labels.left,
)?;
diff_count += 1;
let start = v2.len() - std::cmp::min(10, v2.len() - v1.len());
for message in &compared_right[start..] {
writeln!(w, "{message}")?;
}
}
Ordering::Greater => {
writeln!(
w,
"{} contains {} extra messages not matched in {}. Displaying up to 10:",
sentence_case_label(&opts.side_labels.left),
v1.len() - v2.len(),
opts.side_labels.right,
)?;
diff_count += 1;
let start = v1.len() - std::cmp::min(10, v1.len() - v2.len());
for message in &compared_left[start..] {
writeln!(w, "{message}")?;
}
}
Ordering::Equal => {}
}
Ok(diff_count > 0)
}
fn write_compared_messages(
writer: &mut impl std::io::Write,
messages: &[String],
) -> std::io::Result<()> {
for message in messages {
writeln!(writer, "{message}")?;
}
Ok(())
}
fn write_compared_logs(
writer: &mut impl std::io::Write,
policy: LogComparisonPolicy,
compared_left: &[String],
compared_right: &[String],
labels: &ComparisonSideLabels,
) -> std::io::Result<()> {
writeln!(writer, "Comparison policy: {}", policy.name())?;
writeln!(writer, "--- begin {} compared log ---", labels.left)?;
write_compared_messages(writer, compared_left)?;
writeln!(writer, "--- end {} compared log ---", labels.left)?;
writeln!(writer, "--- begin {} compared log ---", labels.right)?;
write_compared_messages(writer, compared_right)?;
writeln!(writer, "--- end {} compared log ---", labels.right)?;
Ok(())
}
fn git_diff(
which: &str,
left: (&[LogMessage<'_>], &[String]),
right: (&[LogMessage<'_>], &[String]),
opts: &LogDiffOpts,
w: &mut impl std::io::Write,
left_syscalls: &[LogMessage<'_>],
right_syscalls: &[LogMessage<'_>],
) -> std::io::Result<bool> {
let (v1, compared_left) = left;
let (v2, compared_right) = right;
writeln!(w, " Comparing {which} messages...\n")?;
let mut file1 = NamedTempFile::new()?;
let mut file2 = NamedTempFile::new()?;
write_compared_messages(&mut file1, compared_left)?;
write_compared_messages(&mut file2, compared_right)?;
match Command::new("git")
.args(["diff", "--color", "--color-words", "-w"])
.arg(file1.path())
.arg(file2.path())
.status()
{
Ok(code) => Ok(!code.success()),
Err(error) => {
eprintln!("Error launching git, falling back to basic diff: {error}");
diff_vecs(
which,
(v1, compared_left),
(v2, compared_right),
opts,
w,
left_syscalls,
right_syscalls,
)
}
}
}
#[derive(Debug, Clone, PartialEq, Eq)]
pub struct LogDiffSummary {
pub diff_found: bool,
pub compared_left: usize,
pub compared_right: usize,
pub first_divergent_scheduler_turn: Option<u64>,
pub first_divergent_virtual_nanoseconds: Option<u64>,
pub first_divergent_record: Option<usize>,
pub matched_prefix_messages: Option<usize>,
pub first_divergent_syscall: Option<u64>,
pub first_divergent_left_message: Option<String>,
pub first_divergent_right_message: Option<String>,
pub refusal_reason: Option<String>,
}
impl LogDiffSummary {
pub fn matched_with_evidence(&self) -> bool {
self.refusal_reason.is_none()
&& !self.diff_found
&& self.compared_left > 0
&& self.compared_right > 0
}
}
pub fn log_diff(file_a: &Path, file_b: &Path, opts: &LogDiffOpts) -> bool {
log_diff_detailed(file_a, file_b, opts).diff_found
}
pub fn log_diff_detailed(file_a: &Path, file_b: &Path, opts: &LogDiffOpts) -> LogDiffSummary {
try_log_diff_detailed(file_a, file_b, opts).expect("could not read or compare log inputs")
}
pub fn try_log_diff_detailed(
file_a: &Path,
file_b: &Path,
opts: &LogDiffOpts,
) -> std::io::Result<LogDiffSummary> {
try_log_diff_detailed_with_filter(file_a, file_b, opts, |_| true)
}
pub fn try_compare_bitwise_info_v1(
file_a: &Path,
file_b: &Path,
side_labels: ComparisonSideLabels,
) -> std::io::Result<LogDiffSummary> {
try_compare_bitwise_info_v1_with_records(file_a, file_b, side_labels)
.map(|(summary, _, _)| summary)
}
pub fn try_compare_bitwise_info_v1_with_records(
file_a: &Path,
file_b: &Path,
side_labels: ComparisonSideLabels,
) -> std::io::Result<(LogDiffSummary, usize, usize)> {
let bytes_a = std::fs::read(file_a)?;
let bytes_b = std::fs::read(file_b)?;
try_compare_bitwise_info_v1_bytes_with_records(&bytes_a, &bytes_b, side_labels)
}
pub fn try_compare_bitwise_info_v1_bytes_with_records(
bytes_a: &[u8],
bytes_b: &[u8],
side_labels: ComparisonSideLabels,
) -> std::io::Result<(LogDiffSummary, usize, usize)> {
try_compare_bitwise_info_v1_bytes_with_records_and_diagnostics(
bytes_a,
bytes_b,
side_labels,
BitwiseInfoV1Diagnostics::default(),
&mut std::io::stderr(),
)
}
#[derive(Clone, Copy, Debug, PartialEq, Eq)]
pub struct BitwiseInfoV1Diagnostics {
pub difference_limit: u64,
pub syscall_history: u64,
pub no_color: bool,
pub print_logs: bool,
}
impl Default for BitwiseInfoV1Diagnostics {
fn default() -> Self {
Self {
difference_limit: 20,
syscall_history: 5,
no_color: false,
print_logs: false,
}
}
}
pub fn try_compare_bitwise_info_v1_with_records_and_diagnostics(
file_a: &Path,
file_b: &Path,
side_labels: ComparisonSideLabels,
diagnostics: BitwiseInfoV1Diagnostics,
writer: &mut impl Write,
) -> std::io::Result<(LogDiffSummary, usize, usize)> {
let bytes_a = std::fs::read(file_a)?;
let bytes_b = std::fs::read(file_b)?;
try_compare_bitwise_info_v1_bytes_with_records_and_diagnostics(
&bytes_a,
&bytes_b,
side_labels,
diagnostics,
writer,
)
}
pub fn try_compare_bitwise_info_v1_with_diagnostics(
file_a: &Path,
file_b: &Path,
side_labels: ComparisonSideLabels,
diagnostics: BitwiseInfoV1Diagnostics,
writer: &mut impl Write,
) -> std::io::Result<LogDiffSummary> {
try_compare_bitwise_info_v1_with_records_and_diagnostics(
file_a,
file_b,
side_labels,
diagnostics,
writer,
)
.map(|(summary, _, _)| summary)
}
pub fn try_compare_bitwise_info_v1_bytes_with_records_and_diagnostics(
bytes_a: &[u8],
bytes_b: &[u8],
side_labels: ComparisonSideLabels,
diagnostics: BitwiseInfoV1Diagnostics,
writer: &mut impl Write,
) -> std::io::Result<(LogDiffSummary, usize, usize)> {
let str_a = std::str::from_utf8(bytes_a).map_err(|error| {
std::io::Error::new(
std::io::ErrorKind::InvalidData,
format!("{} is not UTF-8: {error}", side_labels.left),
)
})?;
let str_b = std::str::from_utf8(bytes_b).map_err(|error| {
std::io::Error::new(
std::io::ErrorKind::InvalidData,
format!("{} is not UTF-8: {error}", side_labels.right),
)
})?;
let mut options = bitwise_info_v1_options(side_labels);
options.limit = diagnostics.difference_limit;
options.syscall_history = diagnostics.syscall_history;
options.no_color = diagnostics.no_color;
options.print_logs = diagnostics.print_logs;
let records_a = record_count(str_a);
let records_b = record_count(str_b);
let summary = log_diff_summary_from_strs_with_filter(str_a, str_b, &options, writer, |_| true)?;
Ok((summary, records_a, records_b))
}
fn bitwise_info_v1_options(side_labels: ComparisonSideLabels) -> LogDiffOpts {
LogDiffOpts {
strip_lines: false,
canonicalize_addresses: true,
comparison: LogComparisonMode::Info,
side_labels,
require_structured_events: true,
print_logs: false,
limit: 20,
ignore_lines: Vec::new(),
syscall_history: 5,
no_color: false,
skip_commit: false,
skip_detlog: false,
git_diff: false,
include_detlogs: vec![
DetLogFilter::Syscall,
DetLogFilter::SyscallResult,
DetLogFilter::Other,
],
}
}
pub fn try_log_diff_detailed_with_filter(
file_a: &Path,
file_b: &Path,
opts: &LogDiffOpts,
keep_record: impl Fn(&str) -> bool,
) -> std::io::Result<LogDiffSummary> {
let vec_a = std::fs::read(file_a)?;
let vec_b = std::fs::read(file_b)?;
let str_a = String::from_utf8_lossy(&vec_a);
let str_b = String::from_utf8_lossy(&vec_b);
log_diff_summary_from_strs_with_filter(str_a, str_b, opts, &mut std::io::stderr(), keep_record)
}
pub fn record_count(contents: &str) -> usize {
record_starts(contents).len()
}
pub fn try_log_diff_with_records(
file_a: &Path,
file_b: &Path,
opts: &LogDiffOpts,
) -> std::io::Result<(LogDiffSummary, usize, usize)> {
try_log_diff_with_records_and_filter(file_a, file_b, opts, |_| true)
}
pub fn try_log_diff_with_records_and_filter(
file_a: &Path,
file_b: &Path,
opts: &LogDiffOpts,
keep_record: impl Fn(&str) -> bool,
) -> std::io::Result<(LogDiffSummary, usize, usize)> {
let vec_a = std::fs::read(file_a)?;
let vec_b = std::fs::read(file_b)?;
let str_a = String::from_utf8_lossy(&vec_a);
let str_b = String::from_utf8_lossy(&vec_b);
let records_a = record_count(&str_a);
let records_b = record_count(&str_b);
let summary = log_diff_summary_from_strs_with_filter(
&str_a,
&str_b,
opts,
&mut std::io::stderr(),
keep_record,
)?;
Ok((summary, records_a, records_b))
}
#[derive(Debug, Clone, PartialEq, Eq)]
pub struct PrefixComparison {
pub summary: LogDiffSummary,
pub records_available_left: usize,
pub records_available_right: usize,
pub records_compared: usize,
}
impl PrefixComparison {
pub fn one_side_is_ahead(&self) -> bool {
self.records_available_left != self.records_available_right
}
}
pub fn compare_complete_prefix(
contents_a: &str,
contents_b: &str,
opts: &LogDiffOpts,
w: &mut impl std::io::Write,
) -> std::io::Result<PrefixComparison> {
compare_complete_prefix_with_filter(contents_a, contents_b, opts, w, |_| true)
}
pub fn compare_complete_bitwise_info_v1_prefix(
bytes_a: &[u8],
bytes_b: &[u8],
side_labels: ComparisonSideLabels,
diagnostics: BitwiseInfoV1Diagnostics,
w: &mut impl std::io::Write,
) -> std::io::Result<PrefixComparison> {
let contents_a = std::str::from_utf8(bytes_a).map_err(|error| {
std::io::Error::new(
std::io::ErrorKind::InvalidData,
format!("{} is not UTF-8: {error}", side_labels.left),
)
})?;
let contents_b = std::str::from_utf8(bytes_b).map_err(|error| {
std::io::Error::new(
std::io::ErrorKind::InvalidData,
format!("{} is not UTF-8: {error}", side_labels.right),
)
})?;
let truncated_a = log_was_truncated(contents_a);
let truncated_b = log_was_truncated(contents_b);
if truncated_a || truncated_b {
let which_side = match (truncated_a, truncated_b) {
(true, true) => "both logs were",
(true, false) => "the first log was",
(false, true) => "the second log was",
(false, false) => unreachable!("guarded by the condition above"),
};
return Err(std::io::Error::new(
std::io::ErrorKind::InvalidData,
format!(
"{which_side} truncated at the configured size bound; the discarded tail was never written"
),
));
}
let records_available_left = complete_record_count(contents_a);
let records_available_right = complete_record_count(contents_b);
for (label, contents, available) in [
(
side_labels.left.as_str(),
contents_a,
records_available_left,
),
(
side_labels.right.as_str(),
contents_b,
records_available_right,
),
] {
let complete = take_complete_records(contents, available)
.expect("the complete-record count always identifies its own prefix");
let records = extract_log_messages(complete)
.map_err(|error| std::io::Error::new(error.kind(), format!("{label} {error}")))?;
validate_structured_events(label, &records, true)?;
}
let records_compared = records_available_left.min(records_available_right);
let prefix_a = take_complete_records(contents_a, records_compared)
.expect("common prefix never exceeds either side's complete record count");
let prefix_b = take_complete_records(contents_b, records_compared)
.expect("common prefix never exceeds either side's complete record count");
let mut options = bitwise_info_v1_options(side_labels);
options.limit = diagnostics.difference_limit;
options.syscall_history = diagnostics.syscall_history;
options.no_color = diagnostics.no_color;
options.print_logs = diagnostics.print_logs;
let summary =
log_diff_summary_from_strs_with_filter(prefix_a, prefix_b, &options, w, |_| true)?;
Ok(PrefixComparison {
summary,
records_available_left,
records_available_right,
records_compared,
})
}
pub fn compare_complete_prefix_with_filter(
contents_a: &str,
contents_b: &str,
opts: &LogDiffOpts,
w: &mut impl std::io::Write,
keep_record: impl Fn(&str) -> bool,
) -> std::io::Result<PrefixComparison> {
let records_available_left = complete_record_count(contents_a);
let records_available_right = complete_record_count(contents_b);
let records_compared = records_available_left.min(records_available_right);
let prefix_a = take_complete_records(contents_a, records_compared)
.expect("common prefix never exceeds either side's complete record count");
let prefix_b = take_complete_records(contents_b, records_compared)
.expect("common prefix never exceeds either side's complete record count");
let summary = log_diff_summary_from_strs_with_filter(prefix_a, prefix_b, opts, w, keep_record)?;
Ok(PrefixComparison {
summary,
records_available_left,
records_available_right,
records_compared,
})
}
#[cfg(test)]
fn log_diff_from_strs(
file_a_str: impl AsRef<str>,
file_b_str: impl AsRef<str>,
opts: &LogDiffOpts,
w: &mut impl std::io::Write,
) -> std::io::Result<bool> {
Ok(log_diff_summary_from_strs(file_a_str, file_b_str, opts, w)?.diff_found)
}
#[cfg(test)]
fn log_diff_summary_from_strs(
file_a_str: impl AsRef<str>,
file_b_str: impl AsRef<str>,
opts: &LogDiffOpts,
w: &mut impl std::io::Write,
) -> std::io::Result<LogDiffSummary> {
log_diff_summary_from_strs_with_filter(file_a_str, file_b_str, opts, w, |_| true)
}
pub fn log_diff_summary_from_strs_with_filter(
file_a_str: impl AsRef<str>,
file_b_str: impl AsRef<str>,
opts: &LogDiffOpts,
w: &mut impl std::io::Write,
keep_record: impl Fn(&str) -> bool,
) -> std::io::Result<LogDiffSummary> {
let truncated_a = log_was_truncated(file_a_str.as_ref());
let truncated_b = log_was_truncated(file_b_str.as_ref());
if truncated_a || truncated_b {
let which_side = match (truncated_a, truncated_b) {
(true, true) => "both logs were",
(true, false) => "the first log was",
(false, true) => "the second log was",
(false, false) => unreachable!("guarded by the condition above"),
};
let refusal_reason = format!(
"{which_side} truncated at the configured size bound (the log ends with the bounded writer's truncation marker). The discarded tail was never written, so no comparison of these files can establish that the runs agree past that point. Re-run with a larger HERMIT_LOG_MAX_BYTES, or 0 to disable the bound."
);
writeln!(
w,
"REFUSING to compare: {refusal_reason} This is a NO-RESULT, not a difference and not a match."
)?;
return Ok(LogDiffSummary {
diff_found: true,
compared_left: 0,
compared_right: 0,
first_divergent_scheduler_turn: None,
first_divergent_virtual_nanoseconds: None,
first_divergent_record: None,
matched_prefix_messages: None,
first_divergent_syscall: None,
first_divergent_left_message: None,
first_divergent_right_message: None,
refusal_reason: Some(refusal_reason),
});
}
let extracted_a = extract_log_messages(file_a_str.as_ref())?;
let extracted_b = extract_log_messages(file_b_str.as_ref())?;
validate_structured_events(
opts.side_labels.left.as_str(),
&extracted_a,
opts.require_structured_events,
)?;
validate_structured_events(
opts.side_labels.right.as_str(),
&extracted_b,
opts.require_structured_events,
)?;
let all_a = filter_ignored(
extracted_a
.into_iter()
.filter(|record| keep_record(record.text))
.collect(),
&opts.ignore_lines,
);
let all_b = filter_ignored(
extracted_b
.into_iter()
.filter(|record| keep_record(record.text))
.collect(),
&opts.ignore_lines,
);
writeln!(
w,
"Logs contain {} | {} messages total",
all_a.len(),
all_b.len(),
)?;
let detcore_a = filter_detcore(&all_a);
let detcore_b = filter_detcore(&all_b);
let infos_a = filter_infos(&all_a);
let infos_b = filter_infos(&all_b);
let detlogs_a = opts.filter_deterministic(&detcore_a);
let detlogs_b = opts.filter_deterministic(&detcore_b);
let left_syscalls = collect_syscalls(&all_a);
let right_syscalls = collect_syscalls(&all_b);
writeln!(
w,
"Logs contain {} | {} detcore-specific messages",
detcore_a.len(),
detcore_b.len(),
)?;
writeln!(
w,
"Logs contain {} | {} INFO messages",
infos_a.len(),
infos_b.len(),
)?;
writeln!(
w,
"Logs contain {} | {} DETLOG & scheduler COMMIT messages",
detlogs_a.len(),
detlogs_b.len(),
)?;
let policy = LogComparisonPolicy::from_options(opts);
if policy.normalization == LogNormalization::Stripped {
writeln!(
w,
"Normalizing known nondeterministic numerical data before comparison..."
)?;
} else if policy.normalization == LogNormalization::Canonical {
writeln!(
w,
"Canonicalizing host addresses (ordinal by first appearance); comparing everything else exactly..."
)?;
}
let (which, compared_a, compared_b) = match policy.comparison {
LogComparisonMode::Deterministic => ("DETLOG", &detlogs_a, &detlogs_b),
LogComparisonMode::Info => ("INFO", &infos_a, &infos_b),
LogComparisonMode::FullTrace => ("full trace", &all_a, &all_b),
};
let prepared_a = messages_for_comparison(compared_a, policy);
let prepared_b = messages_for_comparison(compared_b, policy);
if opts.print_logs {
write_compared_logs(w, policy, &prepared_a, &prepared_b, &opts.side_labels)?;
}
let first_different =
first_different_message_indices(compared_a, &prepared_a, compared_b, &prepared_b);
let first_position_candidate = first_different.and_then(|(left_index, right_index)| {
left_index
.and_then(|index| commit_position_at_or_before(&all_a, index))
.or_else(|| right_index.and_then(|index| commit_position_at_or_before(&all_b, index)))
});
let first_divergent_syscall_candidate = first_different.and_then(|(left, right)| {
left.and_then(|index| finished_syscall_at_or_before(&all_a, index))
.or_else(|| right.and_then(|index| finished_syscall_at_or_before(&all_b, index)))
});
let first_divergent_left_message = first_different
.and_then(|(left, _)| compared_message_at_record(compared_a, &prepared_a, left));
let first_divergent_right_message = first_different
.and_then(|(_, right)| compared_message_at_record(compared_b, &prepared_b, right));
let diff_found = if opts.git_diff {
git_diff(
which,
(compared_a, &prepared_a),
(compared_b, &prepared_b),
opts,
w,
&left_syscalls,
&right_syscalls,
)?
} else {
diff_vecs(
which,
(compared_a, &prepared_a),
(compared_b, &prepared_b),
opts,
w,
&left_syscalls,
&right_syscalls,
)?
};
let summary = LogDiffSummary {
diff_found,
compared_left: compared_a.len(),
compared_right: compared_b.len(),
first_divergent_scheduler_turn: diff_found
.then_some(first_position_candidate)
.flatten()
.map(|(turn, _)| turn),
first_divergent_virtual_nanoseconds: diff_found
.then_some(first_position_candidate)
.flatten()
.and_then(|(_, time)| time),
first_divergent_record: diff_found
.then_some(first_different)
.flatten()
.and_then(|(left_index, right_index)| left_index.or(right_index)),
matched_prefix_messages: matched_prefix_for_verdict(
diff_found,
matched_prefix_length(&prepared_a, &prepared_b),
compared_a.len(),
compared_b.len(),
),
first_divergent_syscall: diff_found
.then_some(first_divergent_syscall_candidate)
.flatten(),
first_divergent_left_message: diff_found.then_some(first_divergent_left_message).flatten(),
first_divergent_right_message: diff_found
.then_some(first_divergent_right_message)
.flatten(),
refusal_reason: None,
};
if diff_found {
writeln!(w, "Done processing logs, differences found.")?;
} else if summary.compared_left == 0 && summary.compared_right == 0 {
writeln!(
w,
"Done processing logs, but ZERO {which} messages were selected on either side: \
nothing was compared (no-result, not a match)."
)?;
} else {
writeln!(
w,
"Done processing logs, no substantive differences found ({} | {} {which} messages compared).",
summary.compared_left, summary.compared_right,
)?;
writeln!(
w,
"Logs contain {} | {} scheduler empty-run-queue kick messages",
count_empty_queue_kicks(&infos_a),
count_empty_queue_kicks(&infos_b),
)?;
let (maps_left, first_left) = maps_read_commits(&infos_a);
let (maps_right, first_right) = maps_read_commits(&infos_b);
let positions = if first_left.is_none() && first_right.is_none() {
String::new()
} else {
format!(
" ({} {}, {} {})",
opts.side_labels.left,
describe_maps_commit(first_left),
opts.side_labels.right,
describe_maps_commit(first_right),
)
};
writeln!(
w,
"Logs contain {maps_left} | {maps_right} scheduler COMMIT records reading /proc/self/maps{positions}",
)?;
}
Ok(summary)
}
#[cfg(test)]
mod test {
use clap::CommandFactory;
use clap::Parser;
use pretty_assertions::assert_eq;
use super::finished_syscall_at_or_before;
use super::finished_syscall_number;
use crate::detlog::DetLogEvent;
use crate::logdiff::DetLogFilter;
fn record(second: usize, body: &str) -> String {
format!("Apr 09 06:08:{second:02}.100 INFO detcore: {body}\n")
}
fn structured_record(second: usize, body: &str, event: DetLogEvent) -> String {
record(
second,
&format!("{body}{}", crate::detlog::record_suffix(event)),
)
}
fn historical(index: usize, text: &str) -> super::LogMessage<'_> {
super::LogMessage {
index,
text,
event: None,
}
}
fn indexed_text<'a>(messages: &'a [super::LogMessage<'a>]) -> Vec<(usize, &'a str)> {
messages
.iter()
.map(|message| (message.index, message.text))
.collect()
}
fn info_opts() -> super::LogDiffOpts {
super::LogDiffOpts {
comparison: super::LogComparisonMode::Info,
..Default::default()
}
}
fn compare(left: &str, right: &str) -> super::PrefixComparison {
super::compare_complete_prefix(left, right, &info_opts(), &mut Vec::new())
.expect("comparing in-memory strings cannot fail on I/O")
}
fn temp_log(contents: &str) -> tempfile::NamedTempFile {
let file = tempfile::NamedTempFile::new().expect("create temporary log");
std::fs::write(file.path(), contents).expect("write temporary log");
file
}
#[test]
fn bitwise_info_v1_binds_the_complete_policy() {
let labels = super::ComparisonSideLabels::new("left", "right");
let options = super::bitwise_info_v1_options(labels.clone());
assert!(!options.strip_lines);
assert!(options.canonicalize_addresses);
assert_eq!(options.comparison, super::LogComparisonMode::Info);
assert_eq!(options.side_labels, labels);
assert!(options.require_structured_events);
assert!(!options.print_logs);
assert_eq!(options.limit, 20);
assert!(options.ignore_lines.is_empty());
assert_eq!(options.syscall_history, 5);
assert!(!options.no_color);
assert!(!options.skip_commit);
assert!(!options.skip_detlog);
assert!(!options.git_diff);
assert_eq!(
options.include_detlogs,
[
DetLogFilter::Syscall,
DetLogFilter::SyscallResult,
DetLogFilter::Other,
]
);
}
#[test]
fn bitwise_info_v1_matches_and_renders_current_records() -> std::io::Result<()> {
let left_text = structured_record(
1,
&format!("DETLOG allocation={}", super::host_addr(0x1000)),
DetLogEvent::Other,
);
let right_text = structured_record(
1,
&format!("DETLOG allocation={}", super::host_addr(0x9000)),
DetLogEvent::Other,
);
let left = temp_log(&left_text);
let right = temp_log(&right_text);
let summary = super::try_compare_bitwise_info_v1(
left.path(),
right.path(),
super::ComparisonSideLabels::new("left", "right"),
)?;
assert!(summary.matched_with_evidence());
assert_eq!((summary.compared_left, summary.compared_right), (1, 1));
let mut rendered = Vec::new();
assert_eq!(
super::write_bitwise_info_v1_bytes(left_text.as_bytes(), "left", &mut rendered)?,
1
);
let rendered = String::from_utf8(rendered).unwrap();
assert!(rendered.contains("<addr1>"));
assert!(!rendered.contains("0x1000"));
Ok(())
}
#[test]
fn bitwise_info_v1_reports_first_divergence() -> std::io::Result<()> {
let left = structured_record(1, "DETLOG payload=left", DetLogEvent::Other);
let right = structured_record(1, "DETLOG payload=right", DetLogEvent::Other);
let mut diagnostic = Vec::new();
let (summary, records_left, records_right) =
super::try_compare_bitwise_info_v1_bytes_with_records_and_diagnostics(
left.as_bytes(),
right.as_bytes(),
super::ComparisonSideLabels::new("left", "right"),
super::BitwiseInfoV1Diagnostics {
difference_limit: 1,
syscall_history: 0,
no_color: true,
print_logs: false,
},
&mut diagnostic,
)?;
assert!(summary.diff_found);
assert!(summary.refusal_reason.is_none());
assert_eq!(summary.first_divergent_record, Some(1));
assert_eq!((summary.compared_left, summary.compared_right), (1, 1));
assert_eq!((records_left, records_right), (1, 1));
assert!(
String::from_utf8(diagnostic)
.unwrap()
.contains("payload=left")
);
Ok(())
}
#[test]
fn bitwise_info_v1_diagnostics_do_not_change_the_verdict() -> std::io::Result<()> {
let left = structured_record(1, "DETLOG payload=left", DetLogEvent::Other);
let right = structured_record(1, "DETLOG payload=right", DetLogEvent::Other);
let baseline = super::try_compare_bitwise_info_v1_bytes_with_records(
left.as_bytes(),
right.as_bytes(),
super::ComparisonSideLabels::default(),
)?;
let mut diagnostic = Vec::new();
let varied = super::try_compare_bitwise_info_v1_bytes_with_records_and_diagnostics(
left.as_bytes(),
right.as_bytes(),
super::ComparisonSideLabels::default(),
super::BitwiseInfoV1Diagnostics {
difference_limit: 0,
syscall_history: 10,
no_color: true,
print_logs: true,
},
&mut diagnostic,
)?;
assert_eq!(baseline, varied);
assert!(!diagnostic.is_empty());
Ok(())
}
#[test]
fn bitwise_info_v1_refuses_empty_missing_and_unreadable_inputs() -> std::io::Result<()> {
let empty_left = temp_log("");
let empty_right = temp_log("");
let summary = super::try_compare_bitwise_info_v1(
empty_left.path(),
empty_right.path(),
super::ComparisonSideLabels::default(),
)?;
assert!(!summary.matched_with_evidence());
assert_eq!((summary.compared_left, summary.compared_right), (0, 0));
let missing_parent = tempfile::tempdir()?;
let missing = missing_parent.path().join("missing.log");
assert!(
super::try_compare_bitwise_info_v1(
&missing,
empty_right.path(),
super::ComparisonSideLabels::default(),
)
.is_err()
);
let directory = tempfile::tempdir()?;
assert!(
super::try_compare_bitwise_info_v1(
directory.path(),
empty_right.path(),
super::ComparisonSideLabels::default(),
)
.is_err()
);
Ok(())
}
#[test]
fn bitwise_info_v1_refuses_invalid_utf8_and_truncation() -> std::io::Result<()> {
let valid = structured_record(1, "DETLOG payload", DetLogEvent::Other);
let mut invalid = valid.clone().into_bytes();
invalid.insert(invalid.len() - 1, 0x80);
let error = super::try_compare_bitwise_info_v1_bytes_with_records(
&invalid,
valid.as_bytes(),
super::ComparisonSideLabels::new("left", "right"),
)
.expect_err("invalid UTF-8 must refuse");
assert_eq!(error.kind(), std::io::ErrorKind::InvalidData);
assert!(error.to_string().contains("left"));
let truncated = temp_log(&format!("{valid}{}\n", super::TRUNCATION_MARKER));
let complete = temp_log(&valid);
let summary = super::try_compare_bitwise_info_v1(
truncated.path(),
complete.path(),
super::ComparisonSideLabels::default(),
)?;
assert!(summary.diff_found);
assert!(
summary
.refusal_reason
.as_deref()
.is_some_and(|reason| reason.contains("truncated at the configured size bound")),
"the typed result must retain the truncation refusal cause"
);
assert_eq!((summary.compared_left, summary.compared_right), (0, 0));
Ok(())
}
#[test]
fn bitwise_info_v1_requires_current_structured_events() {
let historical = temp_log(&record(1, "DETLOG stable"));
let error = super::try_compare_bitwise_info_v1(
historical.path(),
historical.path(),
super::ComparisonSideLabels::new("left", "right"),
)
.expect_err("prose-only DETLOG must refuse");
assert_eq!(error.kind(), std::io::ErrorKind::InvalidData);
assert!(
error
.to_string()
.contains("missing its structured DETLOG result")
);
}
#[test]
fn bitwise_info_v1_complete_prefix_withholds_the_unfinished_tail() -> std::io::Result<()> {
let common = structured_record(1, "DETLOG common", DetLogEvent::Other);
let left = format!(
"{common}{}",
structured_record(2, "DETLOG unfinished-left", DetLogEvent::Other)
);
let right = format!(
"{common}{}",
structured_record(2, "DETLOG unfinished-right", DetLogEvent::Other)
);
let comparison = super::compare_complete_bitwise_info_v1_prefix(
left.as_bytes(),
right.as_bytes(),
super::ComparisonSideLabels::new("left", "right"),
super::BitwiseInfoV1Diagnostics::default(),
&mut Vec::new(),
)?;
assert_eq!(comparison.records_available_left, 1);
assert_eq!(comparison.records_available_right, 1);
assert_eq!(comparison.records_compared, 1);
assert!(comparison.summary.matched_with_evidence());
assert_eq!(comparison.summary.compared_left, 1);
assert_eq!(comparison.summary.compared_right, 1);
Ok(())
}
#[test]
fn a_record_is_complete_only_once_the_next_one_starts() {
assert_eq!(super::complete_record_count(""), 0);
let one = record(1, "first");
assert_eq!(super::complete_record_count(&one), 0);
let two = format!("{}{}", record(1, "first"), record(2, "second"));
assert_eq!(super::complete_record_count(&two), 1);
let three = format!("{two}{}", record(3, "third"));
assert_eq!(super::complete_record_count(&three), 2);
}
#[test]
fn a_multiline_record_counts_once_and_is_not_split_at_its_newlines() {
let multiline = format!(
"{}{}",
record(1, "first\n continued detail\n more detail"),
record(2, "second")
);
assert_eq!(super::complete_record_count(&multiline), 1);
let prefix = super::take_complete_records(&multiline, 1).unwrap();
assert!(prefix.contains("continued detail"));
assert!(prefix.contains("more detail"));
assert!(!prefix.contains("second"));
}
#[test]
fn asking_past_the_written_end_is_none_not_a_short_answer() {
let two = format!("{}{}", record(1, "first"), record(2, "second"));
assert_eq!(super::take_complete_records(&two, 0), Some(""));
assert!(super::take_complete_records(&two, 1).is_some());
assert_eq!(super::take_complete_records(&two, 2), None);
assert_eq!(super::take_complete_records(&two, 99), None);
}
#[test]
fn a_half_written_final_record_is_never_a_difference() {
let left = format!(
"{}{}{}",
record(1, "same"),
record(2, "same"),
record(3, "TAIL-LEFT")
);
let right = format!(
"{}{}{}",
record(1, "same"),
record(2, "same"),
record(3, "TAIL-RIGHT-AND-LONGER")
);
let comparison = compare(&left, &right);
assert!(
!comparison.summary.diff_found,
"an unfinished record must not read as a divergence"
);
assert_eq!(comparison.records_compared, 2);
assert!(!comparison.one_side_is_ahead());
}
#[test]
fn a_difference_inside_the_completed_prefix_is_found() {
let left = format!(
"{}{}{}",
record(1, "same"),
record(2, "LEFT"),
record(3, "tail")
);
let right = format!(
"{}{}{}",
record(1, "same"),
record(2, "RIGHT"),
record(3, "tail")
);
let comparison = compare(&left, &right);
assert!(comparison.summary.diff_found);
assert_eq!(comparison.records_compared, 2);
}
#[test]
fn comparison_is_bounded_by_the_shorter_log_and_says_so() {
let ahead = format!(
"{}{}{}{}{}",
record(1, "same"),
record(2, "same"),
record(3, "same"),
record(4, "same"),
record(5, "same")
);
let behind = format!(
"{}{}{}",
record(1, "same"),
record(2, "same"),
record(3, "same")
);
let comparison = compare(&ahead, &behind);
assert!(!comparison.summary.diff_found);
assert_eq!(comparison.records_available_left, 4);
assert_eq!(comparison.records_available_right, 2);
assert_eq!(comparison.records_compared, 2);
assert!(
comparison.one_side_is_ahead(),
"the caller must be able to see the comparison was reading-bound"
);
}
#[test]
fn the_first_differing_record_is_located_not_just_bounded() {
let build = |marker: &str| {
(1..=81)
.map(|index| {
let body = if index == 13 { marker } else { "same" };
record(index % 60, &format!("record {index} {body}"))
})
.collect::<String>()
};
let left = build("LEFT");
let right = build("RIGHT");
let found = compare(&left, &right).summary.first_divergent_record;
assert_eq!(
found,
Some(13),
"bisection must name the record, not merely the prefix that contains it"
);
}
#[test]
fn identical_logs_have_no_first_divergent_record() {
let same = format!("{}{}{}", record(1, "a"), record(2, "b"), record(3, "c"));
assert_eq!(compare(&same, &same).summary.first_divergent_record, None);
assert_eq!(compare("", "").summary.first_divergent_record, None);
}
#[test]
fn matched_prefix_counts_leading_equal_compared_messages() {
let log = |bodies: &[&str]| {
bodies
.iter()
.enumerate()
.map(|(index, body)| record(index + 1, body))
.collect::<String>()
};
let summary = |left: &str, right: &str| {
super::log_diff_summary_from_strs(left, right, &info_opts(), &mut Vec::new())
.expect("comparing in-memory strings cannot fail on I/O")
};
let same = log(&["a", "b", "c"]);
let identical = summary(&same, &same);
assert!(!identical.diff_found);
assert_eq!(identical.matched_prefix_messages, Some(3));
let at_first = summary(&log(&["X", "b", "c"]), &log(&["Y", "b", "c"]));
assert!(at_first.diff_found);
assert_eq!(at_first.matched_prefix_messages, Some(0));
assert_eq!(at_first.first_divergent_record, Some(1));
let at_third = summary(&log(&["a", "b", "X", "d"]), &log(&["a", "b", "Y", "d"]));
assert_eq!(at_third.matched_prefix_messages, Some(2));
assert_eq!(at_third.first_divergent_record, Some(3));
let shorter = summary(&log(&["a", "b"]), &log(&["a", "b", "c", "d"]));
assert!(shorter.diff_found);
assert_eq!((shorter.compared_left, shorter.compared_right), (2, 4));
assert_eq!(shorter.matched_prefix_messages, Some(2));
let with_debug = format!(
"{}Apr 09 06:08:02.100 DEBUG detcore: not compared\n{}",
record(1, "a"),
record(3, "X")
);
let unit_mismatch = summary(&with_debug, &log(&["a", "Y"]));
assert_eq!(unit_mismatch.matched_prefix_messages, Some(1));
assert_eq!(unit_mismatch.first_divergent_record, Some(3));
let empty = summary("", "");
assert_eq!(empty.matched_prefix_messages, Some(0));
}
#[test]
fn a_matched_prefix_is_reported_only_where_the_exact_scan_agrees_with_the_verdict() {
for (case, diff_found, prefix, left, right, expected) in [
("full match", false, 3, 3, 3, Some(3)),
("empty match", false, 0, 0, 0, Some(0)),
("divergence inside both", true, 2, 4, 4, Some(2)),
("divergence at the first message", true, 0, 3, 3, Some(0)),
("strict prefix", true, 2, 2, 5, Some(2)),
("match over unequal counts", false, 2, 1, 2, None),
("match of a strict prefix", false, 1, 1, 2, None),
("match the exact scan stops inside", false, 1, 2, 2, None),
("divergence with nothing unmatched", true, 3, 3, 3, None),
("divergence of two empty streams", true, 0, 0, 0, None),
] {
assert_eq!(
super::matched_prefix_for_verdict(diff_found, prefix, left, right),
expected,
"{case}"
);
}
}
#[test]
fn a_git_diff_match_over_unequal_counts_reports_no_matched_prefix() {
let left = "Apr 09 06:08:01.100 INFO detcore: a\nINFO detcore: b\n";
let right = format!("{}{}", record(1, "a"), record(2, "b"));
let git_opts = super::LogDiffOpts {
git_diff: true,
..info_opts()
};
let git = super::log_diff_summary_from_strs(left, &right, &git_opts, &mut Vec::new())
.expect("comparing in-memory strings cannot fail on I/O");
assert_eq!((git.compared_left, git.compared_right), (1, 2));
assert!(
!git.diff_found,
"git diff -w must accept the split record (this test needs git on PATH)"
);
assert_eq!(
git.matched_prefix_messages, None,
"a match over 1 | 2 compared messages has no prefix covering both streams"
);
let exact = super::log_diff_summary_from_strs(left, &right, &info_opts(), &mut Vec::new())
.expect("comparing in-memory strings cannot fail on I/O");
assert_eq!((exact.compared_left, exact.compared_right), (1, 2));
assert!(exact.diff_found);
assert_eq!(exact.matched_prefix_messages, Some(0));
}
#[test]
fn an_untagged_line_is_refused_by_name_rather_than_panicking() {
let log = "detcore-dbt: background client thread entered\n";
let error = super::extract_log_messages(log)
.expect_err("an untagged line must refuse, not be admitted");
assert_eq!(error.kind(), std::io::ErrorKind::InvalidData);
let message = error.to_string();
assert!(
message.contains("detcore-dbt: background client thread entered"),
"the refusal must name the offending line, got: {message}"
);
assert!(
message.contains("no ERROR/WARN/INFO/DEBUG/TRACE tag"),
"the refusal must say why, got: {message}"
);
}
#[test]
fn a_fully_tagged_log_still_parses() {
let log = "2026-08-24T20:16:17.897469Z INFO detcore: DETLOG a\n\
2026-08-24T20:16:17.897470Z WARN detcore: b\n";
let records = super::extract_log_messages(log).expect("tagged log parses");
assert_eq!(records.len(), 2);
}
#[test]
fn historical_syscall_numbers_remain_readable() {
assert_eq!(
finished_syscall_number(&historical(
0,
"DETLOG [syscall][detcore, dtid 3] finish syscall #37: write(1, 0x5, 6) = Ok(6)"
)),
Some(37)
);
assert_eq!(
finished_syscall_number(&historical(
0,
"DETLOG [syscall][detcore, dtid 3] inbound syscall: brk(NULL) = ?"
)),
None
);
assert_eq!(
finished_syscall_number(&historical(0, "no syscall here")),
None
);
}
#[test]
fn the_syscall_count_is_the_last_one_completed_before_the_divergence() {
let finished = |n: u64| format!("finish syscall #{n}: write(1, 0x5, 6) = Ok(6)");
let a = finished(2);
let b = finished(37);
let syscalls = vec![historical(10, a.as_str()), historical(90, b.as_str())];
assert_eq!(finished_syscall_at_or_before(&syscalls, 98), Some(37));
assert_eq!(finished_syscall_at_or_before(&syscalls, 90), Some(37));
assert_eq!(finished_syscall_at_or_before(&syscalls, 50), Some(2));
assert_eq!(
finished_syscall_at_or_before(&syscalls, 9),
None,
"a divergence before any syscall completed has no syscall count, \
and that is a state rather than a missing value"
);
}
#[test]
fn structured_positions_and_syscall_counts_are_authoritative() -> std::io::Result<()> {
let run = |turn: u64, time: u64, syscall: u64, value: u64| {
format!(
"{}{}{}",
structured_record(
1,
"COMMIT turn 999 at time 999",
DetLogEvent::SchedulerCommit {
scheduler_turn: turn,
virtual_nanoseconds: time,
internal_io_poll: false,
runtime_maps_read: false,
},
),
structured_record(
2,
"DETLOG [syscall] finish syscall #999: write = Ok(1)",
DetLogEvent::SyscallResult {
finished_syscall_number: syscall,
},
),
structured_record(3, &format!("DETLOG value={value}"), DetLogEvent::Other),
)
};
let options = super::LogDiffOpts {
require_structured_events: true,
..Default::default()
};
let original = super::log_diff_summary_from_strs(
run(17, 123, 37, 1),
run(17, 123, 37, 2),
&options,
&mut Vec::new(),
)?;
assert_eq!(original.first_divergent_scheduler_turn, Some(17));
assert_eq!(original.first_divergent_virtual_nanoseconds, Some(123));
assert_eq!(original.first_divergent_syscall, Some(37));
let mutated = super::log_diff_summary_from_strs(
run(18, 124, 38, 1),
run(18, 124, 38, 2),
&options,
&mut Vec::new(),
)?;
assert_eq!(mutated.first_divergent_scheduler_turn, Some(18));
assert_eq!(mutated.first_divergent_virtual_nanoseconds, Some(124));
assert_eq!(mutated.first_divergent_syscall, Some(38));
Ok(())
}
#[test]
fn current_verification_refuses_a_missing_structured_record_by_name() {
let options = super::LogDiffOpts {
require_structured_events: true,
..Default::default()
};
let error = super::log_diff_summary_from_strs(
record(1, "DETLOG value=1"),
record(1, "DETLOG value=1"),
&options,
&mut Vec::new(),
)
.expect_err("current verification must not fall back to prose");
assert!(
error
.to_string()
.contains("missing its structured DETLOG result"),
"refusal must name the missing result: {error}"
);
}
#[test]
fn structured_kind_not_the_human_tag_selects_the_syscall_class() {
let text = "INFO detcore: DETLOG [syscall] inbound syscall: read = ?";
let other = super::LogMessage {
index: 0,
text,
event: Some(DetLogEvent::Other),
};
let syscall = super::LogMessage {
event: Some(DetLogEvent::Syscall),
..other
};
assert!(!super::is_detlog_syscall(&other));
assert!(super::is_detlog_syscall(&syscall));
}
#[test]
fn structured_scheduler_flags_control_filtering_and_retained_counts() {
let text = "INFO detcore::scheduler: COMMIT turn 999 at time 999";
let internal = super::LogMessage {
index: 0,
text,
event: Some(DetLogEvent::SchedulerCommit {
scheduler_turn: 17,
virtual_nanoseconds: 123,
internal_io_poll: true,
runtime_maps_read: false,
}),
};
let maps_read = super::LogMessage {
event: Some(DetLogEvent::SchedulerCommit {
scheduler_turn: 17,
virtual_nanoseconds: 123,
internal_io_poll: false,
runtime_maps_read: true,
}),
..internal
};
assert!(
super::LogDiffOpts::default()
.filter_deterministic(&[internal])
.is_empty()
);
assert_eq!(
super::LogDiffOpts::default()
.filter_deterministic(&[maps_read])
.len(),
1
);
assert_eq!(super::maps_read_commits(&[internal]), (0, None));
assert_eq!(
super::maps_read_commits(&[maps_read]),
(1, Some((17, Some(123))))
);
}
#[test]
fn nothing_written_yet_is_a_no_result_not_a_match() {
let comparison = compare(&record(1, "first"), &record(1, "first"));
assert_eq!(comparison.records_compared, 0);
assert!(!comparison.summary.diff_found);
assert!(
!comparison.summary.matched_with_evidence(),
"comparing zero records must never report a match"
);
}
#[test]
fn unsafe_strip_lines_cli_name_and_warning_are_explicit() {
let options = super::LogDiffOpts::try_parse_from(["log-diff", "--unsafe-strip-lines"])
.expect("the explicitly unsafe spelling should parse");
assert!(options.strip_lines);
assert!(super::LogDiffOpts::try_parse_from(["log-diff", "--strip-lines"]).is_err());
let mut help = Vec::new();
super::LogDiffOpts::command()
.write_long_help(&mut help)
.expect("write clap help");
let help = String::from_utf8(help).expect("help is UTF-8");
assert!(help.contains("--unsafe-strip-lines"));
assert!(help.contains("erases timestamps and syscall values"));
assert!(help.contains("make a failing parity diff pass"));
assert!(help.contains("doing so is cheating"));
assert!(!help.contains("--strip-lines"));
}
#[test]
fn test_compare_with_no_color() {
let str1 = "test1";
let str2 = "test2";
assert_eq!(
format!("{}", super::Comparison::new(true, str1, str2))
.split('\n')
.collect::<Vec<&str>>(),
["Diff < left / right > :", "<\"test1\"", ">\"test2\"", "",]
);
}
#[test]
fn test_compare_with_color() {
let str1 = "test1";
let str2 = "test2";
assert_eq!(
format!("{}", super::Comparison::new(false, str1, str2))
.split('\n')
.collect::<Vec<&str>>(),
[
"\u{1b}[1mDiff\u{1b}[0m \u{1b}[31m< left\u{1b}[0m / \u{1b}[32mright >\u{1b}[0m :",
"\u{1b}[31m<\"test\u{1b}[0m\u{1b}[1;48;5;52;31m1\u{1b}[0m\u{1b}[31m\"\u{1b}[0m",
"\u{1b}[32m>\"test\u{1b}[0m\u{1b}[1;48;5;22;32m2\u{1b}[0m\u{1b}[32m\"\u{1b}[0m",
"",
]
);
}
#[test]
fn truncated_logs_are_refused_and_untruncated_logs_still_match() -> std::io::Result<()> {
let body = "2022-09-06T14:15:47.000000Z INFO detcore: DETLOG [syscall] finish syscall #1: read(3, 0x1000, 1) = Ok(1)\n2022-09-06T14:15:48.000000Z INFO detcore: DETLOG [syscall] finish syscall #2: write(1, 0x2000, 1) = Ok(1)";
let marked = format!("{body}\n{}\n", super::TRUNCATION_MARKER);
let options = super::LogDiffOpts {
no_color: true,
..Default::default()
};
let clean = super::log_diff_summary_from_strs(body, body, &options, &mut Vec::new())?;
assert!(!clean.diff_found, "identical untruncated logs must match");
assert!(
clean.matched_with_evidence(),
"the untruncated match must carry nonzero compared counts, got {clean:?}"
);
assert!(clean.refusal_reason.is_none());
for (label, left, right) in [
("left", marked.as_str(), body),
("right", body, marked.as_str()),
("both", marked.as_str(), marked.as_str()),
] {
let mut out = Vec::new();
let summary = super::log_diff_summary_from_strs(left, right, &options, &mut out)?;
assert!(
summary.diff_found,
"{label}: a truncated log must not be reported as a match"
);
assert_eq!(
(summary.compared_left, summary.compared_right),
(0, 0),
"{label}: nothing was compared, so the counts must not claim otherwise"
);
assert!(
summary
.refusal_reason
.as_deref()
.is_some_and(|reason| reason.contains("truncated at the configured size bound")),
"{label}: the typed result must retain the printed refusal cause"
);
assert!(
!summary.matched_with_evidence(),
"{label}: the evidence predicate must also refuse"
);
assert_eq!(
summary.matched_prefix_messages, None,
"{label}: a refused comparison measured no matched prefix"
);
let text = String::from_utf8(out).unwrap();
assert!(
text.contains("REFUSING to compare"),
"{label}: the refusal must be stated, got: {text}"
);
assert!(
!text.contains("no substantive differences found"),
"{label}: a refusal must never print the match line, got: {text}"
);
}
Ok(())
}
#[test]
fn marker_text_in_guest_content_is_not_truncation() -> std::io::Result<()> {
let options = super::LogDiffOpts {
no_color: true,
..Default::default()
};
let marker = super::TRUNCATION_MARKER;
let guest_path_line = format!(
"2022-09-06T14:15:47.000000Z INFO detcore: DETLOG [syscall] inbound syscall: \
statx(-100, 0x7fff -> \"/tmp/{marker} probe\", AtFlags(AT_NO_AUTOMOUNT), 2, 0x7fff) \
= ?"
);
let tail_line = "2022-09-06T14:15:48.000000Z INFO detcore: DETLOG [syscall] finish syscall #2: \
write(1, 0x2000, 1) = Ok(1)";
for (label, text) in [
(
"marker inside the final DETLOG line",
guest_path_line.clone(),
),
(
"marker on its own line, followed by more log",
format!("{guest_path_line}\n{marker}\n{tail_line}"),
),
(
"marker at end of file but mid-line",
format!("{tail_line}\nsomething {marker}"),
),
] {
assert!(
!super::log_was_truncated(&text),
"{label}: an untruncated log must not be classified as truncated"
);
let mut out = Vec::new();
let summary = super::log_diff_summary_from_strs(&text, &text, &options, &mut out)?;
let printed = String::from_utf8(out).unwrap();
assert!(
!printed.contains("REFUSING to compare"),
"{label}: must be compared, not refused, got: {printed}"
);
assert!(
!summary.diff_found,
"{label}: identical logs must compare equal, got {summary:?}"
);
assert!(
summary.matched_with_evidence(),
"{label}: the match must carry nonzero compared counts, got {summary:?}"
);
}
let really_truncated = format!("{guest_path_line}\n{marker}\n");
assert!(
super::log_was_truncated(&really_truncated),
"a log ending in the marker line IS truncated and must still be caught"
);
let mut out = Vec::new();
let summary = super::log_diff_summary_from_strs(
&really_truncated,
&really_truncated,
&options,
&mut out,
)?;
assert!(summary.diff_found, "real truncation must still be refused");
assert_eq!((summary.compared_left, summary.compared_right), (0, 0));
assert!(
String::from_utf8(out)
.unwrap()
.contains("REFUSING to compare"),
"real truncation must still print the refusal"
);
Ok(())
}
#[test]
fn test_log_diff_with_color() -> std::io::Result<()> {
let str1 = "INFO detcore: DETLOG [syscall][detcore, dtid 3] finish syscall #11: mmap(NULL, 3954880, PROT_READ | PROT_EXEC, MAP_PRIVATE | MAP_DENYWRITE, 3, 0) = Ok(140737347883008)";
let str2 = "INFO detcore: DETLOG [syscall][detcore, dtid 3] finish syscall #15: mmap(NULL, 3954880, PROT_READ | PROT_EXEC, MAP_PRIVATE | MAP_DENYWRITE, 3, 0) = Ok(140737347883008)";
let mut result = Vec::<u8>::new();
super::log_diff_from_strs(
str1,
str2,
&super::LogDiffOpts {
limit: 1,
strip_lines: false,
canonicalize_addresses: false,
comparison: super::LogComparisonMode::Deterministic,
side_labels: super::ComparisonSideLabels::default(),
require_structured_events: false,
print_logs: false,
syscall_history: 5,
no_color: false,
skip_commit: false,
skip_detlog: false,
git_diff: false,
ignore_lines: Vec::new(),
include_detlogs: vec![
DetLogFilter::Syscall,
DetLogFilter::SyscallResult,
DetLogFilter::Other,
],
},
&mut result,
)?;
let output = String::from_utf8(result).unwrap();
assert!(output.contains(" Comparing DETLOG messages..."));
assert!(output.contains("Mismatch at log messages 0 (run 1) and 0 (run 2)"));
assert!(output.contains("run 1, log message 0: INFO detcore: DETLOG [syscall][detcore, dtid 3] finish syscall #11"));
assert!(output.contains("run 2, log message 0: INFO detcore: DETLOG [syscall][detcore, dtid 3] finish syscall #15"));
assert!(!output.contains("eliding the rest"));
Ok(())
}
#[test]
fn test_log_diff_reports_each_runs_syscall_context() -> std::io::Result<()> {
let log_a = r#"2022-09-06T14:15:47.000000Z INFO detcore: DETLOG [syscall] finish syscall #1: read(3, 0x1000, 1) = Ok(1)
2022-09-06T14:15:48.000000Z INFO detcore: DETLOG [syscall] finish syscall #2: write(1, 0x2000, 1) = Ok(1)"#;
let log_b = r#"2022-09-06T14:15:47.000000Z INFO detcore: DETLOG [syscall] finish syscall #1: read(3, 0x1000, 1) = Ok(1)
2022-09-06T14:15:48.000000Z INFO detcore: DETLOG [syscall] finish syscall #2: write(1, 0x3000, 1) = Ok(1)"#;
let mut result = Vec::new();
let options = super::LogDiffOpts {
no_color: true,
syscall_history: 1,
..Default::default()
};
assert!(super::log_diff_from_strs(
log_a,
log_b,
&options,
&mut result
)?);
let output = String::from_utf8(result).unwrap();
assert!(output.contains("Mismatch at log messages 2 (run 1) and 2 (run 2)"));
assert!(output.contains("run 1, log message 2: INFO detcore: DETLOG [syscall] finish syscall #2: write(1, 0x2000, 1) = Ok(1)"));
assert!(output.contains("run 2, log message 2: INFO detcore: DETLOG [syscall] finish syscall #2: write(1, 0x3000, 1) = Ok(1)"));
assert!(output.contains("Prior completed syscalls for run 1:"));
assert!(output.contains("Prior completed syscalls for run 2:"));
assert_eq!(output.matches("finish syscall #1: read").count(), 2);
Ok(())
}
#[test]
fn custom_side_labels_cover_mismatch_history_and_tail_diagnostics() -> std::io::Result<()> {
let left = format!(
"{}{}",
record(1, "DETLOG [syscall] finish syscall #1: read = Ok(1)"),
record(2, "DETLOG [syscall] finish syscall #2: write = Ok(1)"),
);
let right = format!(
"{}{}",
record(1, "DETLOG [syscall] finish syscall #1: read = Ok(1)"),
record(2, "DETLOG [syscall] finish syscall #2: write = Err(5)"),
);
let options = super::LogDiffOpts {
side_labels: super::ComparisonSideLabels::new("the recording", "the replay"),
syscall_history: 1,
no_color: true,
..Default::default()
};
let mut output = Vec::new();
assert!(super::log_diff_from_strs(
&left,
&right,
&options,
&mut output
)?);
let output = String::from_utf8(output).unwrap();
assert!(output.contains("Mismatch at log messages 2 (the recording) and 2 (the replay)"));
assert!(output.contains("the recording, log message 2:"));
assert!(output.contains("the replay, log message 2:"));
assert!(output.contains("Prior completed syscalls for the recording:"));
assert!(output.contains("Prior completed syscalls for the replay:"));
assert!(!output.contains("run 1") && !output.contains("run 2"));
let left = record(1, "DETLOG stable");
let right = format!("{left}{}", record(2, "DETLOG extra"));
let mut output = Vec::new();
assert!(super::log_diff_from_strs(
&left,
&right,
&options,
&mut output
)?);
let output = String::from_utf8(output).unwrap();
assert!(
output.contains("The replay contains 1 extra messages not matched in the recording.")
);
assert!(!output.contains("run 1") && !output.contains("run 2"));
let mut output = Vec::new();
assert!(super::log_diff_from_strs(
&right,
&left,
&options,
&mut output
)?);
let output = String::from_utf8(output).unwrap();
assert!(
output.contains("The recording contains 1 extra messages not matched in the replay.")
);
Ok(())
}
fn printed_labeled_log<'a>(output: &'a str, label: &str) -> &'a str {
let start = format!("--- begin {label} compared log ---\n");
let end = format!("--- end {label} compared log ---\n");
output
.split_once(&start)
.expect("printed log start marker")
.1
.split_once(&end)
.expect("printed log end marker")
.0
}
#[test]
fn custom_side_labels_name_printed_logs() -> std::io::Result<()> {
let options = super::LogDiffOpts {
side_labels: super::ComparisonSideLabels::new("the recording", "the replay"),
print_logs: true,
no_color: true,
..Default::default()
};
let mut output = Vec::new();
let summary = super::log_diff_summary_from_strs(
record(1, "DETLOG recorded"),
record(1, "DETLOG replayed"),
&options,
&mut output,
)?;
assert!(summary.diff_found);
let output = String::from_utf8(output).unwrap();
assert_eq!(
printed_labeled_log(&output, "the recording"),
"INFO detcore: DETLOG recorded\n"
);
assert_eq!(
printed_labeled_log(&output, "the replay"),
"INFO detcore: DETLOG replayed\n"
);
assert!(!output.contains("begin run 1") && !output.contains("begin run 2"));
Ok(())
}
fn printed_log(output: &str, run: u8) -> &str {
let start = format!("--- begin run {run} compared log ---\n");
let end = format!("--- end run {run} compared log ---\n");
output
.split_once(&start)
.expect("printed log start marker")
.1
.split_once(&end)
.expect("printed log end marker")
.0
}
#[test]
fn printed_logs_are_the_exact_selected_comparator_inputs() -> std::io::Result<()> {
let left = "2026-08-15T01:02:03.000000Z INFO detcore: DETLOG value=101\n\
2026-08-15T01:02:03.000001Z INFO unrelated: omitted value=303";
let right = "2026-08-15T04:05:06.000000Z INFO detcore: DETLOG value=202\n\
2026-08-15T04:05:06.000001Z INFO unrelated: omitted value=404";
let exact = super::LogDiffOpts {
print_logs: true,
no_color: true,
..Default::default()
};
let mut exact_output = Vec::new();
let exact_summary =
super::log_diff_summary_from_strs(left, right, &exact, &mut exact_output)?;
let exact_output = String::from_utf8(exact_output).unwrap();
assert!(exact_summary.diff_found);
assert!(exact_output.contains("Comparison policy: Deterministic\n"));
assert_eq!(
printed_log(&exact_output, 1).as_bytes(),
b"INFO detcore: DETLOG value=101\n"
);
assert_eq!(
printed_log(&exact_output, 2).as_bytes(),
b"INFO detcore: DETLOG value=202\n"
);
let stripped = super::LogDiffOpts {
strip_lines: true,
print_logs: true,
no_color: true,
..Default::default()
};
let mut stripped_output = Vec::new();
let stripped_summary =
super::log_diff_summary_from_strs(left, right, &stripped, &mut stripped_output)?;
let stripped_output = String::from_utf8(stripped_output).unwrap();
assert!(stripped_summary.matched_with_evidence());
assert!(stripped_output.contains("Comparison policy: Stripped\n"));
assert_eq!(
printed_log(&stripped_output, 1).as_bytes(),
b"INFO detcore: DETLOG value=<NUM>\n"
);
assert_eq!(
printed_log(&stripped_output, 1),
printed_log(&stripped_output, 2)
);
assert_ne!(
printed_log(&exact_output, 1),
printed_log(&stripped_output, 1)
);
Ok(())
}
#[test]
fn printed_policy_name_tracks_the_selected_scope_and_normalization() -> std::io::Result<()> {
let log = "2026-08-15T01:02:03.000000Z INFO detcore: DETLOG stable=1 address=<hostaddr 0xaaaa>\n\
2026-08-15T01:02:03.000001Z DEBUG unrelated: diagnostic=2";
let cases = [
(
super::LogDiffOpts {
comparison: super::LogComparisonMode::Info,
print_logs: true,
no_color: true,
..Default::default()
},
"Comparison policy: Info\n",
"INFO detcore: DETLOG stable=1 address=<hostaddr 0xaaaa>\n",
),
(
super::LogDiffOpts {
comparison: super::LogComparisonMode::FullTrace,
print_logs: true,
no_color: true,
..Default::default()
},
"Comparison policy: FullTrace\n",
"INFO detcore: DETLOG stable=1 address=<hostaddr 0xaaaa>\nDEBUG unrelated: diagnostic=2\n",
),
(
super::LogDiffOpts {
comparison: super::LogComparisonMode::Deterministic,
canonicalize_addresses: true,
print_logs: true,
no_color: true,
..Default::default()
},
"Comparison policy: Deterministic with Canonical host-address normalization\n",
"INFO detcore: DETLOG stable=1 address=<addr1>\n",
),
(
super::LogDiffOpts {
comparison: super::LogComparisonMode::Deterministic,
strip_lines: true,
print_logs: true,
no_color: true,
..Default::default()
},
"Comparison policy: Stripped\n",
"INFO detcore: DETLOG stable=<NUM> address=<hostaddr <ADDR>>\n",
),
];
for (options, expected_name, expected_log) in cases {
let mut output = Vec::new();
let summary = super::log_diff_summary_from_strs(log, log, &options, &mut output)?;
let output = String::from_utf8(output).unwrap();
assert!(summary.matched_with_evidence());
assert!(output.contains(expected_name), "{output}");
assert_eq!(printed_log(&output, 1), expected_log);
assert_eq!(printed_log(&output, 2), expected_log);
}
Ok(())
}
#[test]
fn printed_canonical_policy_uses_the_info_scope_and_address_ordinals() -> std::io::Result<()> {
let left = "2026-08-15T01:02:03.000000Z INFO detcore: DETLOG stable=1\n\
2026-08-15T01:02:03.000001Z INFO unrelated: value=101 address=<hostaddr 0xaaaa>";
let right = "2026-08-15T04:05:06.000000Z INFO detcore: DETLOG stable=1\n\
2026-08-15T04:05:06.000001Z INFO unrelated: value=202 address=<hostaddr 0xbbbb>";
let deterministic = super::LogDiffOpts {
print_logs: true,
no_color: true,
..Default::default()
};
let mut deterministic_output = Vec::new();
let deterministic_summary = super::log_diff_summary_from_strs(
left,
right,
&deterministic,
&mut deterministic_output,
)?;
let deterministic_output = String::from_utf8(deterministic_output).unwrap();
assert!(deterministic_summary.matched_with_evidence());
assert!(deterministic_output.contains("Comparison policy: Deterministic\n"));
assert_eq!(
printed_log(&deterministic_output, 1).as_bytes(),
b"INFO detcore: DETLOG stable=1\n"
);
assert_eq!(
printed_log(&deterministic_output, 1),
printed_log(&deterministic_output, 2)
);
let options = super::LogDiffOpts {
comparison: super::LogComparisonMode::Info,
canonicalize_addresses: true,
print_logs: true,
no_color: true,
..Default::default()
};
let mut output = Vec::new();
let summary = super::log_diff_summary_from_strs(left, right, &options, &mut output)?;
let output = String::from_utf8(output).unwrap();
assert!(summary.diff_found);
assert!(output.contains("Comparison policy: Canonical\n"));
assert_eq!(
printed_log(&output, 1).as_bytes(),
b"INFO detcore: DETLOG stable=1\nINFO unrelated: value=101 address=<addr1>\n"
);
assert_eq!(
printed_log(&output, 2).as_bytes(),
b"INFO detcore: DETLOG stable=1\nINFO unrelated: value=202 address=<addr1>\n"
);
Ok(())
}
#[test]
fn test_full_trace_detects_unnormalized_timing_difference() -> std::io::Result<()> {
let log_a = "INFO detcore: DETLOG [syscall] finish syscall #1: clock_gettime(CLOCK_MONOTONIC, 100) = Ok(0)";
let log_b = "INFO detcore: DETLOG [syscall] finish syscall #1: clock_gettime(CLOCK_MONOTONIC, 101) = Ok(0)";
let normalized = super::LogDiffOpts {
strip_lines: true,
no_color: true,
..Default::default()
};
assert!(!super::log_diff_from_strs(
log_a,
log_b,
&normalized,
&mut Vec::new()
)?);
let verbose = super::LogDiffOpts {
comparison: super::LogComparisonMode::FullTrace,
strip_lines: false,
syscall_history: 1,
no_color: true,
..Default::default()
};
let mut result = Vec::new();
assert!(super::log_diff_from_strs(
log_a,
log_b,
&verbose,
&mut result
)?);
let output = String::from_utf8(result).unwrap();
assert!(output.contains("Comparing full trace messages"));
assert!(output.contains("clock_gettime(CLOCK_MONOTONIC, 100)"));
assert!(output.contains("clock_gettime(CLOCK_MONOTONIC, 101)"));
assert!(output.contains("run 1"));
assert!(output.contains("run 2"));
Ok(())
}
#[test]
fn info_scope_compares_info_exactly_without_promoting_debug_diagnostics() -> std::io::Result<()>
{
let stable_info = "2026-08-06T01:00:00.000000Z INFO detcore: DETLOG [syscall] finish syscall #1: write(1, 0x2, 1) = Ok(1)";
let left = format!(
"{stable_info}\n2026-08-06T01:00:00.000001Z DEBUG detcore: diagnostic host timing=100"
);
let right = format!(
"{stable_info}\n2026-08-06T01:00:00.000002Z DEBUG detcore: diagnostic host timing=200"
);
let info = super::LogDiffOpts {
comparison: super::LogComparisonMode::Info,
no_color: true,
..Default::default()
};
let matched = super::log_diff_summary_from_strs(&left, &right, &info, &mut Vec::new())?;
assert!(matched.matched_with_evidence());
assert_eq!(matched.compared_left, 1);
assert_eq!(matched.compared_right, 1);
let divergent_info = right.replace("write(1, 0x2, 1)", "write(1, 0x6, 1)");
let diverged =
super::log_diff_summary_from_strs(&left, divergent_info, &info, &mut Vec::new())?;
assert!(diverged.diff_found);
let full_trace = super::LogDiffOpts {
comparison: super::LogComparisonMode::FullTrace,
no_color: true,
..Default::default()
};
let debug_diverged =
super::log_diff_summary_from_strs(left, right, &full_trace, &mut Vec::new())?;
assert!(debug_diverged.diff_found);
Ok(())
}
#[test]
fn test_log_diff_compares_detlog() -> std::io::Result<()> {
let log_file_a = r#"2022-09-06T14:15:47.891501Z INFO detcore: DETLOG [memory][detcore, dtid 3] 0x602000-0x623000 rw-p 0 0:0 0 [heap] -> 74b43faf7b78ace9443772ef63a30f66feaf9bd320256c82b8bd880634d19d46
2022-09-06T14:15:48.903997Z INFO detcore: DETLOG [memory][detcore, dtid 3] 0x7ffffffdd000-0x7ffffffff000 rw-p 0 0:0 0 [stack] -> 7984d1aaf386fce67eaa926624ecc1d5a4105828e4f286ee59cc69c0491cd5fe
2022-09-06T14:15:48.904049Z INFO detcore: DETLOG [syscall][detcore, dtid 3] inbound syscall: write(1, 0x6022a0, 70) = ?
2022-09-06T14:15:48.904049Z INFO detcore: COMMIT 2
2022-09-06T14:15:48.904782Z INFO detcore::scheduler: [sched-step5] >>>>>>>"#;
let log_file_b = r#"2022-09-06T14:15:47.891501Z INFO detcore: DETLOG [memory][detcore, dtid 3] 0x602000-0x623000 rw-p 0 0:0 0 [heap] -> 74b43faf7b78ace9443772ef63a30f66feaf9bd320256c82b8bd880634d19d46
2022-09-06T14:15:47.903997Z INFO detcore: DETLOG [memory][detcore, dtid 3] 0x7ffffffdd000-0x7ffffffff000 rw-p 0 0:0 0 [stack] -> 1984d1aaf386fce67eaa926624ecc1d5a4105828e4f286ee59cc69c0491cd5fe
2022-09-06T14:15:47.904049Z INFO detcore: DETLOG [syscall][detcore, dtid 3] inbound syscall: write(1, 0x6022a0, 70) = ?
2022-09-06T14:15:47.904049Z INFO detcore: COMMIT 1
2022-09-06T14:15:47.904782Z INFO detcore::scheduler: [sched-step5] >>>>>>>"#;
let mut result = Vec::<u8>::new();
let log_options = super::LogDiffOpts {
no_color: true,
git_diff: false,
..Default::default()
};
super::log_diff_from_strs(log_file_a, log_file_b, &log_options, &mut result)?;
let output = String::from_utf8(result).unwrap();
assert!(output.contains("Mismatch at log messages 2 (run 1) and 2 (run 2)"));
assert!(output.contains("Mismatch at log messages 4 (run 1) and 4 (run 2)"));
assert!(output.contains("INFO detcore: COMMIT 2"));
assert!(output.contains("INFO detcore: COMMIT 1"));
Ok(())
}
#[test]
fn test_filter_deterministic() {
let opts = super::LogDiffOpts {
include_detlogs: vec![
DetLogFilter::Syscall,
DetLogFilter::SyscallResult,
DetLogFilter::Other,
],
..Default::default()
};
let v = opts.filter_deterministic(
&[
historical(
1,
"INFO detcore: registers [dtid 3]. user_regs_struct { r15...",
),
historical(
2,
"INFO DETLOG detcore: registers [dtid 3]. user_regs_struct { r15...",
),
historical(
3,
"INFO COMMIT turn 5, dettid 2 using resources {Path(\"/proc/2/fd/1\"): W} at time 946684799205300000",
),
],
);
assert_eq!(
indexed_text(&v),
vec![
(
2,
"INFO DETLOG detcore: registers [dtid 3]. user_regs_struct { r15..."
),
(
3,
"INFO COMMIT turn 5, dettid 2 using resources {Path(\"/proc/2/fd/1\"): W} at time 946684799205300000",
),
]
);
}
#[test]
fn test_filter_deterministic_with_filter() {
let opts = super::LogDiffOpts {
include_detlogs: vec![DetLogFilter::Syscall],
skip_commit: true,
..Default::default()
};
let v = opts.filter_deterministic(
&[
historical(
1,
"INFO detcore: registers [dtid 3]. user_regs_struct { r15...",
),
historical(2, "INFO DETLOG detcore:[syscall] syscall 1"),
historical(
3,
"INFO COMMIT turn 5, dettid 2 using resources {Path(\"/proc/2/fd/1\"): W} at time 946684799205300000",
),
],
);
assert_eq!(
indexed_text(&v),
vec![(2, "INFO DETLOG detcore:[syscall] syscall 1")]
);
}
#[test]
fn test_filter_deterministic_drops_io_polling_bookkeeping() {
let opts = super::LogDiffOpts::default();
let v = opts.filter_deterministic(&[
historical(
0,
"INFO detcore::scheduler: [sched-step5] >>> COMMIT turn 17, dettid 5 using resources {InternalIOPolling: W}, on previously committed 1s",
),
historical(
1,
"DEBUG detcore::scheduler: DETLOG [sched-step1] advancing committed_time from 1 to 2",
),
historical(
2,
"INFO detcore: DETLOG [syscall][detcore, dtid 5] finish syscall #9: read(3, 0x1000, 1) = Ok(1)",
),
historical(
3,
"INFO detcore::scheduler: [sched-step5] >>> COMMIT turn 18, dettid 5 using resources {Path(\"/proc/5/fd/3\"): R}, on previously committed 2s",
),
]);
assert_eq!(
indexed_text(&v),
vec![
(
2,
"INFO detcore: DETLOG [syscall][detcore, dtid 5] finish syscall #9: read(3, 0x1000, 1) = Ok(1)"
),
(
3,
"INFO detcore::scheduler: [sched-step5] >>> COMMIT turn 18, dettid 5 using resources {Path(\"/proc/5/fd/3\"): R}, on previously committed 2s"
),
]
);
}
#[test]
fn test_filter_deterministic_drops_sabre_internal_pipe_resource_turn() {
let opts = super::LogDiffOpts::default();
let v = opts.filter_deterministic(&[
historical(
0,
"INFO detcore::scheduler: [sched-step5] >>> COMMIT turn 17, dettid 5 using resources {Device(ContainerStdout): W}, on previously committed 1s [sabre-internal-pipe-io]",
),
historical(
1,
"INFO detcore::scheduler: [sched-step5] >>> COMMIT turn 18, dettid 5 using resources {Device(ContainerStdout): W}, on previously committed 2s",
),
]);
assert_eq!(
indexed_text(&v),
vec![(
1,
"INFO detcore::scheduler: [sched-step5] >>> COMMIT turn 18, dettid 5 using resources {Device(ContainerStdout): W}, on previously committed 2s"
)]
);
}
#[test]
fn test_filter_deterministic_drops_sabre_loopback_poll_yield() {
let opts = super::LogDiffOpts::default();
let v = opts.filter_deterministic(&[
historical(
0,
"INFO detcore::scheduler: [sched-step5] >>> COMMIT turn 17, dettid 5 using resources {SchedYield: W}, on previously committed 1s [sabre-loopback-poll-zero-timeout]",
),
historical(
1,
"INFO detcore::scheduler: [sched-step5] >>> COMMIT turn 18, dettid 5 using resources {SchedYield: W}, on previously committed 2s",
),
]);
assert_eq!(
indexed_text(&v),
vec![(
1,
"INFO detcore::scheduler: [sched-step5] >>> COMMIT turn 18, dettid 5 using resources {SchedYield: W}, on previously committed 2s"
)]
);
}
#[test]
fn test_log_diff_ignores_extra_io_poll_retries() -> std::io::Result<()> {
let common_head = "2022-09-06T14:15:47.000000Z INFO detcore: DETLOG [syscall][detcore, dtid 5] inbound syscall: poll(0x1000, 1, -1) = ?";
let common_tail = "2022-09-06T14:15:47.100000Z INFO detcore: DETLOG [syscall][detcore, dtid 5] finish syscall #9: poll(0x1000, 1, -1) = Ok(1)";
let poll_retry = "2022-09-06T14:15:47.050000Z INFO detcore::scheduler: [sched-step5] >>> COMMIT turn 17, dettid 5 using resources {InternalIOPolling: W}, on previously committed 1s\n2022-09-06T14:15:47.050000Z DEBUG detcore::scheduler: DETLOG [sched-step1] advancing committed_time from 1 to 2";
let run_a = format!("{common_head}\n{poll_retry}\n{common_tail}");
let run_b = format!("{common_head}\n{poll_retry}\n{poll_retry}\n{common_tail}");
let opts = super::LogDiffOpts {
no_color: true,
strip_lines: true,
..Default::default()
};
assert!(!super::log_diff_from_strs(
&run_a,
&run_b,
&opts,
&mut Vec::new()
)?);
let run_c = run_a.replace("= Ok(1)", "= Err(Errno(EBADF))");
assert!(super::log_diff_from_strs(
&run_a,
&run_c,
&opts,
&mut Vec::new()
)?);
Ok(())
}
#[test]
fn canonical_address_only_difference_compares_equal() -> std::io::Result<()> {
let run_a =
"2022-09-06T14:15:47.000000Z INFO detcore: [t] p=<hostaddr 0x1111> q=<hostaddr 0x2222>
2022-09-06T14:15:48.000000Z INFO detcore: [t] use <hostaddr 0x1111> then <hostaddr 0x2222>";
let run_b =
"2022-09-06T14:15:47.000000Z INFO detcore: [t] p=<hostaddr 0xaaaa> q=<hostaddr 0xbbbb>
2022-09-06T14:15:48.000000Z INFO detcore: [t] use <hostaddr 0xaaaa> then <hostaddr 0xbbbb>";
let canonical = super::LogDiffOpts {
comparison: super::LogComparisonMode::FullTrace,
canonicalize_addresses: true,
no_color: true,
..Default::default()
};
assert!(
!super::log_diff_from_strs(run_a, run_b, &canonical, &mut Vec::new())?,
"address-only (ASLR-shift) difference must compare EQUAL under canonicalization"
);
let raw = super::LogDiffOpts {
comparison: super::LogComparisonMode::FullTrace,
canonicalize_addresses: false,
no_color: true,
..Default::default()
};
assert!(
super::log_diff_from_strs(run_a, run_b, &raw, &mut Vec::new())?,
"raw comparison must still see the differing addresses"
);
Ok(())
}
#[test]
fn canonical_allocation_order_difference_compares_unequal() -> std::io::Result<()> {
let run_a = "2022-09-06T14:15:47.000000Z INFO detcore: [t] alloc <hostaddr 0x1111>
2022-09-06T14:15:48.000000Z INFO detcore: [t] alloc <hostaddr 0x2222>
2022-09-06T14:15:49.000000Z INFO detcore: [t] pair <hostaddr 0x1111> <hostaddr 0x2222>";
let run_b = "2022-09-06T14:15:47.000000Z INFO detcore: [t] alloc <hostaddr 0xbbbb>
2022-09-06T14:15:48.000000Z INFO detcore: [t] alloc <hostaddr 0xaaaa>
2022-09-06T14:15:49.000000Z INFO detcore: [t] pair <hostaddr 0xaaaa> <hostaddr 0xbbbb>";
let canonical = super::LogDiffOpts {
comparison: super::LogComparisonMode::FullTrace,
canonicalize_addresses: true,
no_color: true,
..Default::default()
};
assert!(
super::log_diff_from_strs(run_a, run_b, &canonical, &mut Vec::new())?,
"an allocation-order difference must compare UNEQUAL under canonicalization"
);
let stripped = super::LogDiffOpts {
comparison: super::LogComparisonMode::FullTrace,
strip_lines: true,
no_color: true,
..Default::default()
};
assert!(
!super::log_diff_from_strs(run_a, run_b, &stripped, &mut Vec::new())?,
"wholesale stripping erases the allocation-order difference (the defect)"
);
Ok(())
}
#[test]
fn canonical_aliasing_difference_compares_unequal() -> std::io::Result<()> {
let run_a = "2022-09-06T14:15:47.000000Z INFO detcore: [t] two <hostaddr 0x1111> <hostaddr 0x1111>";
let run_b = "2022-09-06T14:15:47.000000Z INFO detcore: [t] two <hostaddr 0xaaaa> <hostaddr 0xbbbb>";
let canonical = super::LogDiffOpts {
comparison: super::LogComparisonMode::FullTrace,
canonicalize_addresses: true,
no_color: true,
..Default::default()
};
assert!(
super::log_diff_from_strs(run_a, run_b, &canonical, &mut Vec::new())?,
"an aliasing difference (1,1 vs 1,2) must compare UNEQUAL"
);
Ok(())
}
#[test]
fn canonical_syscall_arg_hex_difference_compares_unequal() -> std::io::Result<()> {
let run_a = "2022-09-06T14:15:47.000000Z INFO detcore: flock(fd=3, operation=0x2) at <hostaddr 0x1111>";
let run_b = "2022-09-06T14:15:47.000000Z INFO detcore: flock(fd=3, operation=0x6) at <hostaddr 0xaaaa>";
let canonical = super::LogDiffOpts {
comparison: super::LogComparisonMode::FullTrace,
canonicalize_addresses: true,
no_color: true,
..Default::default()
};
assert!(
super::log_diff_from_strs(run_a, run_b, &canonical, &mut Vec::new())?,
"a bare syscall-argument hex difference (0x2 vs 0x6) must compare UNEQUAL: \
it is reproducible and NOT a host address"
);
let addr_only_a = "2022-09-06T14:15:47.000000Z INFO detcore: flock(fd=3, operation=0x2) at <hostaddr 0x1111>";
let addr_only_b = "2022-09-06T14:15:47.000000Z INFO detcore: flock(fd=3, operation=0x2) at <hostaddr 0xaaaa>";
assert!(
!super::log_diff_from_strs(addr_only_a, addr_only_b, &canonical, &mut Vec::new())?,
"an address-only difference alongside an identical syscall arg must compare EQUAL"
);
Ok(())
}
#[test]
fn canonical_virtual_time_difference_compares_unequal() -> std::io::Result<()> {
let run_a = "2022-09-06T14:15:47.000000Z INFO detcore: COMMIT turn 5 at time 100";
let run_b = "2022-09-06T14:15:47.000000Z INFO detcore: COMMIT turn 5 at time 200";
let canonical = super::LogDiffOpts {
comparison: super::LogComparisonMode::FullTrace,
canonicalize_addresses: true,
no_color: true,
..Default::default()
};
assert!(
super::log_diff_from_strs(run_a, run_b, &canonical, &mut Vec::new())?,
"a virtual-time (decimal) difference must compare UNEQUAL under canonicalization"
);
Ok(())
}
#[test]
fn canonical_wall_clock_prefix_difference_compares_equal() -> std::io::Result<()> {
let run_a = "2022-09-06T14:15:47.000000Z INFO detcore: [t] use 0x1111
2022-09-06T14:15:48.000000Z INFO detcore: [t] use 0x1111";
let run_b = "Apr 09 06:08:03.100 INFO detcore: [t] use 0x1111
Jun 09 06:49:17.742 INFO detcore: [t] use 0x1111";
let canonical = super::LogDiffOpts {
comparison: super::LogComparisonMode::FullTrace,
canonicalize_addresses: true,
no_color: true,
..Default::default()
};
assert!(
!super::log_diff_from_strs(run_a, run_b, &canonical, &mut Vec::new())?,
"a wall-clock-prefix-only difference must compare EQUAL"
);
Ok(())
}
#[test]
fn one_log_canonical_info_preserves_values_and_only_rewrites_marked_addresses() {
let log = "2026-08-13T01:02:03.000000Z INFO detcore: COMMIT turn 17 at time 123456 bare=0x2 marked=<hostaddr 0xaaaa>\n\
2026-08-13T01:02:03.000001Z DEBUG detcore: diagnostic=999\n\
2026-08-13T01:02:03.000002Z INFO detcore: DETLOG count=42 bare=0x6 marked=<hostaddr 0xaaaa> other=<hostaddr 0xbbbb>";
assert_eq!(
super::canonical_info_from_str(log).expect("fixture log is fully tagged"),
vec![
"INFO detcore: COMMIT turn 17 at time 123456 bare=0x2 marked=<addr1>",
"INFO detcore: DETLOG count=42 bare=0x6 marked=<addr1> other=<addr2>",
]
);
}
#[test]
fn first_log_divergence_reports_preceding_commit_turn_and_virtual_time() -> std::io::Result<()>
{
let left = "2026-08-13T01:02:03.000000Z INFO detcore::scheduler: COMMIT turn 17, dettid 2, on previously committed 12.345_678_901s\n\
2026-08-13T01:02:03.000001Z INFO detcore: DETLOG count=42";
let right = "2026-08-13T01:02:04.000000Z INFO detcore::scheduler: COMMIT turn 17, dettid 2, on previously committed 12.345_678_901s\n\
2026-08-13T01:02:04.000001Z INFO detcore: DETLOG count=43";
let opts = super::LogDiffOpts {
comparison: super::LogComparisonMode::Info,
canonicalize_addresses: true,
no_color: true,
..Default::default()
};
let diverged = super::log_diff_summary_from_strs(left, right, &opts, &mut Vec::new())?;
assert!(diverged.diff_found);
assert_eq!(diverged.first_divergent_scheduler_turn, Some(17));
assert_eq!(
diverged.first_divergent_virtual_nanoseconds,
Some(12_345_678_901)
);
assert_eq!(
diverged.first_divergent_left_message.as_deref(),
Some("INFO detcore: DETLOG count=42")
);
assert_eq!(
diverged.first_divergent_right_message.as_deref(),
Some("INFO detcore: DETLOG count=43")
);
let matched = super::log_diff_summary_from_strs(left, left, &opts, &mut Vec::new())?;
assert!(matched.matched_with_evidence());
assert_eq!(matched.first_divergent_scheduler_turn, None);
assert_eq!(matched.first_divergent_virtual_nanoseconds, None);
assert_eq!(matched.first_divergent_left_message, None);
assert_eq!(matched.first_divergent_right_message, None);
Ok(())
}
#[test]
fn first_divergent_messages_keep_event_content_not_separate_positions() -> std::io::Result<()> {
let left = "2026-08-13T01:02:03.000000Z INFO detcore::scheduler: COMMIT turn 110, dettid 2 using resources {Device(ContainerStdout): W}, on previously committed 1_767_225_600.031_999_250s";
let right = "2026-08-13T01:02:04.000000Z INFO detcore::scheduler: COMMIT turn 111, dettid 2 using resources {Device(ContainerStdout): W}, on previously committed 1_767_225_600.031_994_250s";
let opts = super::LogDiffOpts {
comparison: super::LogComparisonMode::Info,
canonicalize_addresses: true,
no_color: true,
..Default::default()
};
let same_event = super::log_diff_summary_from_strs(left, right, &opts, &mut Vec::new())?;
assert!(same_event.diff_found);
assert_eq!(
same_event.first_divergent_left_message, same_event.first_divergent_right_message,
"turn and committed-time values are recorded separately, so they must not split one event into two"
);
assert_eq!(
same_event.first_divergent_left_message.as_deref(),
Some(
"INFO detcore::scheduler: COMMIT turn <NUM>, dettid 2 using resources {Device(ContainerStdout): W}, on previously committed <NANOSECONDS>"
)
);
assert_eq!(
super::first_divergent_message(&historical(
0,
"INFO detcore::scheduler: COMMIT turn 110 at time 123\npayload at time 456"
)),
"INFO detcore::scheduler: COMMIT turn <NUM> at time <NANOSECONDS>\npayload at time 456",
"only the structured first line carries the separately recorded position"
);
let after_longer_shared_prefix = super::log_diff_summary_from_strs(
format!("2026-08-13T01:02:02.000000Z INFO detcore: shared event\n{left}"),
format!("2026-08-13T01:02:02.000000Z INFO detcore: shared event\n{right}"),
&opts,
&mut Vec::new(),
)?;
assert_ne!(
same_event.first_divergent_record, after_longer_shared_prefix.first_divergent_record,
"a longer shared trace must move the record observation in this fixture"
);
assert_eq!(
(
same_event.first_divergent_left_message.as_deref(),
same_event.first_divergent_right_message.as_deref(),
),
(
after_longer_shared_prefix
.first_divergent_left_message
.as_deref(),
after_longer_shared_prefix
.first_divergent_right_message
.as_deref(),
),
"the same event after a longer trace must keep the same compared messages"
);
let different_event = super::log_diff_summary_from_strs(
left,
"2026-08-13T01:02:04.000000Z INFO detcore::scheduler: COMMIT turn 111, dettid 2 using resources {Device(ContainerStderr): W}, on previously committed 1_767_225_600.031_994_250s",
&opts,
&mut Vec::new(),
)?;
assert_ne!(
different_event.first_divergent_left_message,
different_event.first_divergent_right_message,
"different event content must remain distinguishable"
);
Ok(())
}
#[test]
fn log_divergence_without_commit_metadata_reports_no_position() -> std::io::Result<()> {
let opts = super::LogDiffOpts {
comparison: super::LogComparisonMode::Info,
canonicalize_addresses: true,
no_color: true,
..Default::default()
};
let summary = super::log_diff_summary_from_strs(
"INFO detcore: DETLOG count=42",
"INFO detcore: DETLOG count=43",
&opts,
&mut Vec::new(),
)?;
assert!(summary.diff_found);
assert_eq!(summary.first_divergent_scheduler_turn, None);
assert_eq!(summary.first_divergent_virtual_nanoseconds, None);
Ok(())
}
#[test]
fn empty_selection_is_a_no_result_not_a_match() -> std::io::Result<()> {
let canonical = super::LogDiffOpts {
comparison: super::LogComparisonMode::FullTrace,
canonicalize_addresses: true,
no_color: true,
..Default::default()
};
let summary = super::log_diff_summary_from_strs("", "", &canonical, &mut Vec::new())?;
assert!(!summary.diff_found, "two empty logs do not differ");
assert_eq!(summary.compared_left, 0);
assert_eq!(summary.compared_right, 0);
assert!(
!summary.matched_with_evidence(),
"zero compared messages must never count as a verified match"
);
Ok(())
}
#[test]
fn nonempty_identical_selection_is_a_match_with_evidence() -> std::io::Result<()> {
let run = "Apr 09 06:08:03.100 INFO detcore: [t] finish syscall: close(2) = Ok(0)
Apr 09 06:08:03.200 INFO detcore: [t] finish syscall: exit_group(0)";
let canonical = super::LogDiffOpts {
comparison: super::LogComparisonMode::FullTrace,
canonicalize_addresses: true,
no_color: true,
..Default::default()
};
let summary = super::log_diff_summary_from_strs(run, run, &canonical, &mut Vec::new())?;
assert!(!summary.diff_found);
assert_eq!(summary.compared_left, 2);
assert_eq!(summary.compared_right, 2);
assert!(
summary.matched_with_evidence(),
"a real, nonempty, identical comparison must count as a match"
);
Ok(())
}
#[test]
fn test_filter_infos() {
let v = super::filter_infos(&[
historical(
0,
"DEBUG detcore::scheduler: [sched-step3] advancing committed_time from 946684799165300000 to 946684799205300000",
),
historical(
1,
"INFO detcore: registers [dtid 3]. user_regs_struct { r15: 140737354129904, ...",
),
]);
assert_eq!(
indexed_text(&v),
vec![(
1,
"INFO detcore: registers [dtid 3]. user_regs_struct { r15: 140737354129904, ..."
)]
);
}
#[test]
fn test_extract_log_messages() {
let s = "
Jan 09 06:08:03.100 INFO detcore: [detcore, dtid 2] finish syscall: close(2) = Ok(0)
Feb 09 06:49:17.742 DEBUG detcore::scheduler: [sched-step3] advancing committed_time from 946684799165300000 to 946684799205300000
Apr 09 06:49:17.742 INFO detcore::scheduler: [scheduler] >>>>>>>
COMMIT turn 5, dettid 2 using resources {Path(\"/proc/2/fd/1\"): W} at time 946684799205300000
Jan 09 06:49:03.100 INFO detcore: registers [dtid 3]. user_regs_struct { r15: 140737354129904, r14: 0, r13: 1, r12: 946684799000118840, rbp: 140737488344736, rbx: 0, r11: 518, r10: 140737488342434, r9: 0, r8: 1, rax: 0, rcx: 0, rdx: 2, rsi: 0, rdi: 140737354052880, orig_rax: 18446744073709551615, rip: 140737351875567, cs: 51, eflags: 66118, rsp: 140737488344064, ss: 43, fs_base: 0, gs_base: 0, ds: 0, es: 0, fs: 0, gs: 0 }
Jun 09 06:49:17.742 TRACE detcore::scheduler: [scheduler] Guest unblocked (<ivar Go>); clear ivars for the next turn on dettid 2
";
let v = super::extract_log_messages(s).expect("fixture log is fully tagged");
eprintln!("Split into {} log messages", v.len());
for x in &v {
eprintln!("{:?}", x);
}
assert_eq!(v.len(), 5);
}
#[test]
fn test_canonicalize_addresses_in_line() {
use std::collections::HashMap;
let mut map = HashMap::new();
let mut next = 1usize;
assert_eq!(
super::canonicalize_addresses_in_line(
"a=<hostaddr 0x1111> b=<hostaddr 0x2222> c=<hostaddr 0x1111> raw=0x4444 n=42",
&mut map,
&mut next
),
"a=<addr1> b=<addr2> c=<addr1> raw=0x4444 n=42"
);
assert_eq!(
super::canonicalize_addresses_in_line(
"use <hostaddr 0x2222> then <hostaddr 0x3333>",
&mut map,
&mut next
),
"use <addr2> then <addr3>"
);
assert_eq!(
super::canonicalize_addresses_in_line("bare 0x1111", &mut map, &mut next),
"bare 0x1111"
);
}
#[test]
fn test_strip_log() {
assert_eq!(super::strip_log_entry("800.709_180s"), "<NANOSECONDS>");
assert_eq!(super::strip_log_entry("98.91618ms"), "<NUM>");
assert_eq!(super::strip_log_entry("98.91619ms"), "<NUM>");
assert_eq!(super::strip_log_entry("x86_64"), "x86_64");
assert_eq!(
super::strip_log_entry(
"COMMIT turn 66, dettid 2 using resources {Path(\"/proc/2/fd/1\"): W} at time 946_684_800.709_180_000s"
),
"COMMIT turn <NUM>, dettid <NUM> using resources {Path(\"/proc/<PID>/fd/<NUM>\"): W} at time <NANOSECONDS>"
);
}
#[test]
fn strip_tmp_path_does_not_swallow_rest_of_line() {
let read = super::strip_log_entry(r#"open path="/tmp/scratch" flags="O_RDONLY""#);
let write = super::strip_log_entry(r#"open path="/tmp/scratch" flags="O_WRONLY""#);
assert_eq!(read, r#"open path="/tmp/<somewhere>" flags="O_RDONLY""#);
assert_eq!(write, r#"open path="/tmp/<somewhere>" flags="O_WRONLY""#);
assert_ne!(
read, write,
"entries differing after a /tmp path must not collapse to equal"
);
}
#[test]
fn strip_tmp_path_still_erases_a_differing_tmp_path() {
assert_eq!(
super::strip_log_entry(r#"open path="/tmp/hermit-aaaa/f" flags="O_RDONLY""#),
super::strip_log_entry(r#"open path="/tmp/hermit-bbbb/f" flags="O_RDONLY""#),
);
}
#[test]
fn strip_tmp_path_erases_each_path_separately() {
assert_eq!(
super::strip_log_entry(r#"rename from="/tmp/a" to="/tmp/b" ok="1""#),
r#"rename from="/tmp/<somewhere>" to="/tmp/<somewhere>" ok="<NUM>""#
);
}
const KICK_LINE_PREFIX: &str = "Logs contain";
const KICK_LINE_SUFFIX: &str = "scheduler empty-run-queue kick messages";
fn kick_opts() -> super::LogDiffOpts {
super::LogDiffOpts {
comparison: super::LogComparisonMode::Info,
canonicalize_addresses: true,
no_color: true,
..Default::default()
}
}
fn log_with_kick() -> &'static str {
"2026-08-13T01:02:03.000000Z INFO detcore::scheduler: COMMIT turn 17, dettid 2, on previously committed 1s\n\
2026-08-13T01:02:03.000001Z INFO detcore::scheduler: scheduler (step2_process_blocked): zero threads left anywhere, fizzling.\n\
2026-08-13T01:02:03.000002Z INFO detcore::scheduler: [scheduler] run queue empty, exiting sched_loop."
}
fn log_without_kick() -> &'static str {
"2026-08-13T01:02:03.000000Z INFO detcore::scheduler: COMMIT turn 17, dettid 2, on previously committed 1s\n\
2026-08-13T01:02:03.000002Z INFO detcore::scheduler: [scheduler] run queue empty, exiting sched_loop."
}
fn run_diff(left: &str, right: &str) -> std::io::Result<(super::LogDiffSummary, String)> {
let mut out = Vec::new();
let summary = super::log_diff_summary_from_strs(left, right, &kick_opts(), &mut out)?;
Ok((
summary,
String::from_utf8(out).expect("diff output is utf-8"),
))
}
#[test]
fn a_matching_pair_records_the_empty_queue_kick_count() -> std::io::Result<()> {
let (kicked, kicked_out) = run_diff(log_with_kick(), log_with_kick())?;
assert!(kicked.matched_with_evidence(), "both-kicked pair must pass");
assert!(
kicked_out.contains(&format!("{KICK_LINE_PREFIX} 1 | 1 {KICK_LINE_SUFFIX}")),
"a passing pair that kicked must retain the count, got:\n{kicked_out}"
);
let (quiet, quiet_out) = run_diff(log_without_kick(), log_without_kick())?;
assert!(
quiet.matched_with_evidence(),
"neither-kicked pair must pass"
);
assert!(
quiet_out.contains(&format!("{KICK_LINE_PREFIX} 0 | 0 {KICK_LINE_SUFFIX}")),
"a passing pair that did not kick must say so explicitly, got:\n{quiet_out}"
);
Ok(())
}
#[test]
fn recording_the_kick_count_does_not_move_any_verdict() -> std::io::Result<()> {
let (diverged, diverged_out) = run_diff(log_with_kick(), log_without_kick())?;
assert!(
diverged.diff_found,
"a pair differing only by the kick must still diverge"
);
assert!(
!diverged_out.contains(KICK_LINE_SUFFIX),
"the count is scoped to passing pairs; a diverging pair already \
reproduces the messages in its diff, got:\n{diverged_out}"
);
let (matched, _) = run_diff(log_with_kick(), log_with_kick())?;
assert!(!matched.diff_found);
assert_eq!(matched.first_divergent_scheduler_turn, None);
assert_eq!(matched.first_divergent_virtual_nanoseconds, None);
assert_eq!(matched.first_divergent_record, None);
assert_eq!(matched.compared_left, matched.compared_right);
Ok(())
}
const MAPS_LINE_SUFFIX: &str = "scheduler COMMIT records reading /proc/self/maps";
fn log_with_maps_read(committed: &str) -> String {
format!(
"2026-08-13T01:02:03.000000Z INFO detcore::scheduler: [sched-step5] >>> COMMIT turn 10, dettid 3 using resources {{Path(\"/proc/self/maps\"): R}}, on previously committed {committed}\n\
2026-08-13T01:02:03.000001Z INFO detcore::scheduler: [scheduler] run queue empty, exiting sched_loop."
)
}
#[test]
fn custom_side_labels_name_the_maps_read_summary() -> std::io::Result<()> {
let scanned = log_with_maps_read("12.345_678_901s");
let options = super::LogDiffOpts {
comparison: super::LogComparisonMode::Info,
canonicalize_addresses: true,
side_labels: super::ComparisonSideLabels::new("the recording", "the replay"),
no_color: true,
..Default::default()
};
let mut output = Vec::new();
let summary = super::log_diff_summary_from_strs(&scanned, &scanned, &options, &mut output)?;
assert!(summary.matched_with_evidence());
let output = String::from_utf8(output).unwrap();
assert!(output.contains(
"(the recording first at turn 10, committed virtual time 12345678901ns, \
the replay first at turn 10, committed virtual time 12345678901ns)"
));
assert!(!output.contains("run 1") && !output.contains("run 2"));
Ok(())
}
#[test]
fn a_matching_pair_records_the_maps_read_commit() -> std::io::Result<()> {
let scanned = log_with_maps_read("12.345_678_901s");
let (summary, out) = run_diff(&scanned, &scanned)?;
assert!(summary.matched_with_evidence(), "the pair must pass");
assert!(
out.contains(&format!("Logs contain 1 | 1 {MAPS_LINE_SUFFIX}")),
"a passing pair that read the map must retain the record, got:\n{out}"
);
assert!(
out.contains(
"(run 1 first at turn 10, committed virtual time 12345678901ns, \
run 2 first at turn 10, committed virtual time 12345678901ns)"
),
"the retained record must carry the turn and the committed virtual \
time, got:\n{out}"
);
let (quiet, quiet_out) = run_diff(log_without_kick(), log_without_kick())?;
assert!(quiet.matched_with_evidence());
assert!(
quiet_out.contains(&format!("Logs contain 0 | 0 {MAPS_LINE_SUFFIX}")),
"a passing pair that never read the map must say so explicitly, \
got:\n{quiet_out}"
);
Ok(())
}
#[test]
fn recording_the_maps_read_commit_does_not_move_any_verdict() -> std::io::Result<()> {
let (diverged, diverged_out) = run_diff(
&log_with_maps_read("12.345_678_901s"),
&log_with_maps_read("12.345_678_902s"),
)?;
assert!(
diverged.diff_found,
"a one-nanosecond difference in the committed time must still diverge"
);
assert_eq!(diverged.first_divergent_scheduler_turn, Some(10));
assert!(
!diverged_out.contains(MAPS_LINE_SUFFIX),
"the record is scoped to passing pairs; a diverging pair already \
prints both times in its diff, got:\n{diverged_out}"
);
Ok(())
}
#[test]
fn both_records_are_retained_under_the_default_comparison_mode() -> std::io::Result<()> {
let default_opts = super::LogDiffOpts {
no_color: true,
..Default::default()
};
assert_eq!(
default_opts.comparison,
super::LogComparisonMode::Deterministic,
"this test exists to cover the default mode; if the default changes \
it must be re-pointed, not deleted"
);
let mut out = Vec::new();
let summary = super::log_diff_summary_from_strs(
log_with_kick(),
log_without_kick(),
&default_opts,
&mut out,
)?;
let out = String::from_utf8(out).expect("diff output is utf-8");
assert!(
summary.matched_with_evidence(),
"a kick asymmetry is not compared under the default mode, so this \
pair must pass; got:\n{out}"
);
assert!(
out.contains(&format!("Logs contain 1 | 0 {KICK_LINE_SUFFIX}")),
"the asymmetry must be visible per side on the default path, \
got:\n{out}"
);
assert!(
out.contains(&format!("Logs contain 0 | 0 {MAPS_LINE_SUFFIX}")),
"the map-read line must also be emitted on the default path, \
got:\n{out}"
);
let scanned = log_with_maps_read("12.345_678_901s");
let mut out = Vec::new();
let summary =
super::log_diff_summary_from_strs(&scanned, &scanned, &default_opts, &mut out)?;
let out = String::from_utf8(out).expect("diff output is utf-8");
assert!(summary.matched_with_evidence());
assert!(
out.contains(
"(run 1 first at turn 10, committed virtual time 12345678901ns, \
run 2 first at turn 10, committed virtual time 12345678901ns)"
),
"both runs' values must be printed under the default mode, \
got:\n{out}"
);
Ok(())
}
#[test]
fn a_stripped_pass_shows_both_runs_diverging_map_read_times() -> std::io::Result<()> {
let opts = super::LogDiffOpts {
strip_lines: true,
no_color: true,
..Default::default()
};
let mut out = Vec::new();
let summary = super::log_diff_summary_from_strs(
log_with_maps_read("12.345_678_901s"),
log_with_maps_read("12.345_678_902s"),
&opts,
&mut out,
)?;
let out = String::from_utf8(out).expect("diff output is utf-8");
assert!(
summary.matched_with_evidence(),
"the stripped comparator normalizes the times, so this pair passes; \
got:\n{out}"
);
assert!(
out.contains(
"(run 1 first at turn 10, committed virtual time 12345678901ns, \
run 2 first at turn 10, committed virtual time 12345678902ns)"
),
"a passing pair whose runs committed at DIFFERENT times must show \
both values; showing one would report agreement on a real drift, \
got:\n{out}"
);
Ok(())
}
#[test]
fn a_run_without_the_maps_read_is_named_not_borrowed() {
assert_eq!(super::describe_maps_commit(None), "no such record");
assert_eq!(
super::describe_maps_commit(Some((10, Some(12_345_678_901)))),
"first at turn 10, committed virtual time 12345678901ns"
);
assert_eq!(
super::describe_maps_commit(Some((10, None))),
"first at turn 10, committed virtual time unrecorded"
);
}
#[test]
fn only_a_maps_read_commit_is_counted() {
assert_eq!(
super::maps_read_commits(&[
historical(
0,
"INFO detcore::scheduler: [sched-step5] >>> COMMIT turn 18, dettid 5 using resources {Path(\"/proc/5/fd/3\"): R}, on previously committed 2s"
),
historical(
1,
"INFO detcore: DETLOG [syscall][detcore, dtid 3] finish syscall #257: openat(-100, \"/proc/self/maps\", 0x0) = Ok(4)"
),
]),
(0, None),
"a COMMIT on another path, and a syscall naming the map, are both \
excluded"
);
assert_eq!(
super::maps_read_commits(&[historical(
0,
"INFO detcore::scheduler: [sched-step5] >>> COMMIT turn 10, dettid 3 using resources {Path(\"/proc/self/maps\"): R}, on previously committed 12.345_678_901s"
)]),
(1, Some((10, Some(12_345_678_901))))
);
}
#[test]
fn only_the_kick_message_is_counted() {
assert_eq!(
super::count_empty_queue_kicks(&[
historical(
0,
"INFO detcore::scheduler: [scheduler] run queue empty, exiting sched_loop."
),
historical(
1,
"INFO detcore::scheduler: COMMIT turn 18, dettid 2, on previously committed 2s"
),
]),
0
);
assert_eq!(
super::count_empty_queue_kicks(&[historical(
0,
"INFO detcore::scheduler: scheduler (step2_process_blocked): zero threads left anywhere, fizzling."
)]),
1
);
}
}