1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
//! The replay summary line — split from `replay.rs` (500-LOC house rule)
//! and grown one behavior: the informational branches can be silenced.
//!
//! For a long-lived server the summary is a boot banner, one line per
//! lifetime. For an embedded short-lived process it prints on every open
//! — a CLI that opens the store per command pays it per command, into
//! terminals, CI logs, and AI-session transcripts. A caller that has
//! registered a metric sink already receives the same numbers as data,
//! so the open paths pass `quiet_info` there. The corrupt-frame WARN is
//! an incident signal and never silenced — it does not share the switch.
// `write!` into an in-memory buffer returns a `Result` because
// `fmt::Write` / `io::Write` must, not because it can fail: the
// `String` and `Vec` impls are infallible. Said once here.
#![expect(clippy::let_underscore_must_use, reason = "writing to an in-memory buffer cannot fail")]
use crate::replay_walk::ReplayStop;
use std::path::Path;
/// Emit the one-line replay summary. Goes to stderr because kevy-persist
/// has no log-crate dependency (pure-Rust + 0 deps charter); production
/// deployments route stderr to their existing log sink. Quiet-mode
/// suppression of the informational branches happens at the call sites
/// (the corrupt-frame WARN is always emitted there).
pub(crate) fn log_replay_summary(
path: &Path,
total: usize,
pos: usize,
replayed: u64,
remainder: &[u8],
stop: ReplayStop,
elapsed_ms: u128,
) {
let display = path.display();
// Saturating like replay.rs's other two consumers of this pair
// (`pos.min(total)` / `saturating_sub`): `total` is a snapshot of the
// file length at open, and a writer appending during replay walks
// `pos` past it. 6.2.1 panicked here in debug and printed a wrapped
// "trailing 18446744073709551607 bytes" in release (downstream report).
let dropped = total.saturating_sub(pos);
match stop {
ReplayStop::Clean => {
eprintln!(
"kevy: AOF {display} replayed {replayed} commands from {total} bytes \
in {elapsed_ms} ms (clean)"
);
}
ReplayStop::TruncatedTail => {
eprintln!(
"kevy: AOF {display} replayed {replayed} commands from {total} bytes \
in {elapsed_ms} ms; trailing {dropped} bytes \
were a partial frame (crash mid-append, recoverable)"
);
}
ReplayStop::LengthOutranFile { claimed, available } => {
outran_warn(&display, replayed, elapsed_ms, pos, claimed, available, dropped);
}
ReplayStop::CorruptFrame(err) => {
let preview = preview_bytes(remainder);
eprintln!(
"kevy WARN: AOF {display} replayed {replayed} commands in {elapsed_ms} ms \
then hit a corrupt \
frame at byte {pos}; dropping the trailing {dropped} bytes \
(quarantined before truncation). \
Preview: {preview}. Parser error: {err}. \
Most common cause: the process was killed mid-append (a torn \
frame); less commonly, non-kevy bytes got written into this \
file path (e.g. a deploy pipeline redirecting stderr here)."
);
}
}
}
/// Hex + ASCII preview of up to 16 bytes, for diagnostic eprintlns.
fn preview_bytes(b: &[u8]) -> String {
use std::fmt::Write;
let n = b.len().min(16);
let mut hex = String::with_capacity(n * 3);
let mut ascii = String::with_capacity(n);
for &x in &b[..n] {
if !hex.is_empty() {
hex.push(' ');
}
let _ = write!(hex, "{x:02x}");
ascii.push(if (0x20..0x7f).contains(&x) { x as char } else { '.' });
}
format!("hex=[{hex}] ascii=[{ascii}]")
}
/// The message a length field the file could not honour deserves.
///
/// It used to share `TruncatedTail`'s line, which calls the drop "a partial
/// frame (crash mid-append, recoverable)" — CI printed exactly that for
/// 27,485,178 bytes. A torn append leaves at most one incomplete record.
#[allow(clippy::too_many_arguments)]
fn outran_warn(
display: &std::path::Display<'_>,
replayed: u64,
elapsed_ms: u128,
pos: usize,
claimed: u64,
available: u64,
dropped: usize,
) {
eprintln!(
"kevy WARN: AOF {display} replayed {replayed} commands in {elapsed_ms} ms \
then hit a record at byte {pos} whose length field claimed {claimed} \
bytes with only {available} left in the file; the trailing {dropped} \
bytes were dropped. This is not a partial frame from a crash \
mid-append — a torn append leaves at most one incomplete record. \
Turn on `replay_resync` to recover the good records behind it."
);
}
/// The log ended inside a transaction that never committed: replay dropped
/// its records, and the open that follows cuts them off the log.
pub(crate) fn log_open_transaction(path: &Path, bytes: u64) {
eprintln!(
"kevy: AOF {} ended inside a transaction that never committed; its {bytes} bytes \
were not replayed and are cut from the log before new writes.",
path.display()
);
}
#[cfg(test)]
mod tests {
use super::*;
use crate::replay_walk::ReplayStop;
/// `pos > total` is a real state, not a bug in the caller: `stream_v2`
/// snapshots `total = metadata().len()` and then reads through a
/// `BufReader` — a writer appending to the same file during replay
/// hands the walker records past the snapshot. Both other consumers
/// of the pair already guard (`pos.min(total)`, `saturating_sub`);
/// this line panicked in debug and wrapped to ~1.8e19 in release
/// (reported downstream against 6.2.1).
#[test]
fn summary_survives_pos_past_total_on_every_stop() {
let p = std::path::Path::new("/nonexistent/grew-during-replay.aof");
let stops = [
ReplayStop::Clean,
ReplayStop::TruncatedTail,
ReplayStop::LengthOutranFile { claimed: 4, available: 1 },
ReplayStop::CorruptFrame("test".into()),
];
for stop in stops {
log_replay_summary(p, 9, 27, 1, b"", stop, 0);
}
}
}