fix: recover partial session log writes

This commit is contained in:
2026-08-05 18:15:49 +09:00
parent 36df79e561
commit fd391ef705
10 changed files with 488 additions and 104 deletions
+107 -12
View File
@@ -20,17 +20,23 @@ use crate::segment_log::LogEntry;
use crate::store::{Store, StoreError};
use crate::{SegmentId, SessionId};
use std::fs;
use std::io::Write;
use std::io::{Read, Seek, SeekFrom, Write};
use std::path::{Path, PathBuf};
use std::sync::{Arc, Mutex};
use std::time::SystemTime;
/// Filesystem-backed JSONL store.
///
/// Each segment is stored as a single `.jsonl` file with one [`LogEntry`]
/// per line. Writes use append mode for crash safety.
/// per line. A trailing line is committed only once its newline has been
/// written; readers ignore an unterminated tail and the next append removes it.
#[derive(Clone)]
pub struct FsStore {
root: PathBuf,
/// Serialises append repair + write + rollback across clones. A failed
/// `write_all` may have extended the file, so rollback is safe only while
/// no sibling writer can append behind it.
append_lock: Arc<Mutex<()>>,
}
impl FsStore {
@@ -39,7 +45,10 @@ impl FsStore {
pub fn new(root: impl Into<PathBuf>) -> Result<Self, StoreError> {
let root = root.into();
fs::create_dir_all(&root)?;
Ok(Self { root })
Ok(Self {
root,
append_lock: Arc::new(Mutex::new(())),
})
}
/// Return the filesystem root used by this store.
@@ -101,22 +110,62 @@ impl FsStore {
}
fn append_line(&self, path: &Path, line: &str) -> Result<(), StoreError> {
let _guard = self
.append_lock
.lock()
.map_err(|_| std::io::Error::other("session store append lock was poisoned"))?;
if let Some(parent) = path.parent() {
fs::create_dir_all(parent)?;
}
let mut file = fs::OpenOptions::new()
.create(true)
.read(true)
.write(true)
.append(true)
.open(path)?;
file.write_all(line.as_bytes())?;
file.write_all(b"\n")?;
// Append-mode write is the durability boundary; an explicit
// `sync_all` here would multiply latency by ~10× for no gain
// since the kernel already orders concurrent `O_APPEND` writes.
let committed_len = Self::truncate_uncommitted_tail(&mut file)?;
let mut record = Vec::with_capacity(line.len() + 1);
record.extend_from_slice(line.as_bytes());
record.push(b'\n');
if let Err(write_error) = file.write_all(&record) {
return match file.set_len(committed_len) {
Ok(()) => Err(write_error.into()),
Err(rollback_error) => Err(std::io::Error::new(
rollback_error.kind(),
format!(
"session append failed ({write_error}) and partial-write rollback failed: {rollback_error}"
),
)
.into()),
};
}
Ok(())
}
fn parse_jsonl<T: serde::de::DeserializeOwned>(content: &str) -> Result<Vec<T>, StoreError> {
/// Return only newline-terminated records. A process interruption or
/// ENOSPC can leave the final UTF-8 code point / JSON object incomplete;
/// without a newline that record never crossed the commit boundary.
fn complete_jsonl_prefix(content: &[u8]) -> &[u8] {
if content.last() == Some(&b'\n') {
return content;
}
match content.iter().rposition(|byte| *byte == b'\n') {
Some(index) => &content[..=index],
None => &[],
}
}
fn parse_jsonl<T: serde::de::DeserializeOwned>(content: &[u8]) -> Result<Vec<T>, StoreError> {
let complete = Self::complete_jsonl_prefix(content);
let content = std::str::from_utf8(complete).map_err(|error| StoreError::Corrupt {
line: complete[..error.valid_up_to()]
.iter()
.filter(|byte| **byte == b'\n')
.count()
+ 1,
message: error.to_string(),
})?;
let mut entries = Vec::new();
for (i, line) in content.lines().enumerate() {
if line.trim().is_empty() {
@@ -130,6 +179,43 @@ impl FsStore {
}
Ok(entries)
}
/// Remove a prior unterminated record and return the committed file size.
/// Scans backwards in bounded chunks so repairing a large session does not
/// require loading it into memory.
fn truncate_uncommitted_tail(file: &mut fs::File) -> std::io::Result<u64> {
const SCAN_BYTES: usize = 8 * 1024;
let len = file.metadata()?.len();
if len == 0 {
return Ok(0);
}
file.seek(SeekFrom::End(-1))?;
let mut last = [0_u8; 1];
file.read_exact(&mut last)?;
if last[0] == b'\n' {
return Ok(len);
}
let mut end = len;
let mut buffer = [0_u8; SCAN_BYTES];
while end > 0 {
let start = end.saturating_sub(SCAN_BYTES as u64);
let chunk_len = (end - start) as usize;
file.seek(SeekFrom::Start(start))?;
file.read_exact(&mut buffer[..chunk_len])?;
if let Some(index) = buffer[..chunk_len].iter().rposition(|byte| *byte == b'\n') {
let committed_len = start + index as u64 + 1;
file.set_len(committed_len)?;
return Ok(committed_len);
}
end = start;
}
file.set_len(0)?;
Ok(0)
}
}
impl Store for FsStore {
@@ -152,7 +238,7 @@ impl Store for FsStore {
if !path.exists() {
return Err(StoreError::NotFound(segment_id));
}
let content = fs::read_to_string(&path)?;
let content = fs::read(&path)?;
Self::parse_jsonl(&content)
}
@@ -251,8 +337,17 @@ impl Store for FsStore {
if !path.exists() {
return Err(StoreError::NotFound(segment_id));
}
let content = fs::read_to_string(&path)?;
Ok(content.lines().filter(|l| !l.trim().is_empty()).count())
let content = fs::read(&path)?;
let complete = Self::complete_jsonl_prefix(&content);
let complete = std::str::from_utf8(complete).map_err(|error| StoreError::Corrupt {
line: complete[..error.valid_up_to()]
.iter()
.filter(|byte| **byte == b'\n')
.count()
+ 1,
message: error.to_string(),
})?;
Ok(complete.lines().filter(|l| !l.trim().is_empty()).count())
}
fn append_trace(
+38 -5
View File
@@ -69,7 +69,10 @@ pub enum LogEntry {
/// Field name is `trigger` (not `kind`) because the LogEntry
/// serde tag already occupies `"kind"`.
///
/// Marker only — replay does not mutate `RestoredState`.
/// Replay marks the run interrupted until a terminal `RunCompleted`,
/// `RunErrored`, or `PausedTurnAbandoned` entry proves how it ended. This
/// makes a process/disk failure between Invoke and its terminal record
/// restore conservatively instead of re-running a dangling tool call.
Invoke { ts: u64, trigger: InvokeKind },
/// User input accepted at submit time. Carries the original typed
@@ -236,9 +239,9 @@ pub fn collect_state(entries: &[LogEntry]) -> RestoredState {
state.history = history.iter().cloned().map(Item::from).collect();
}
LogEntry::Invoke { .. } => {
// Marker only; no state mutation. The trailing
// UserInput / SystemItem / TurnEnd entries carry all
// replay-relevant data.
// A terminal run record below clears or refines this. If the
// log ends first, restore must treat the turn as interrupted.
state.last_run_interrupted = true;
}
LogEntry::UserInput { segments, .. } => {
let text = Segment::flatten_to_text(segments);
@@ -368,6 +371,35 @@ mod tests {
assert!(!state.last_run_interrupted);
}
#[test]
fn replay_incomplete_invoke_is_interrupted() {
let state = collect_state(&[
LogEntry::SegmentStart {
ts: 1000,
session_id: uuid::Uuid::nil(),
system_prompt: None,
config: RequestConfig::default(),
history: vec![],
forked_from: None,
compacted_from: None,
},
LogEntry::Invoke {
ts: 2000,
trigger: InvokeKind::UserSend,
},
LogEntry::UserInput {
ts: 2001,
segments: vec![Segment::text("run a tool")],
},
LogEntry::AssistantItem {
ts: 3000,
item: Item::tool_call("call_1", "side_effect", "{}").into(),
},
]);
assert!(state.last_run_interrupted);
}
#[test]
fn replay_with_tool_calls() {
let state = collect_state(&[
@@ -546,7 +578,7 @@ mod tests {
}
#[test]
fn replay_invoke_marker_does_not_mutate_state() {
fn replay_invoke_marker_only_mutates_interrupted_state() {
let state = collect_state(&[
LogEntry::SegmentStart {
ts: 0,
@@ -576,6 +608,7 @@ mod tests {
]);
assert_eq!(state.history.len(), 1);
assert_eq!(state.turn_count, 1);
assert!(state.last_run_interrupted);
}
#[test]
+2 -2
View File
@@ -40,8 +40,8 @@ pub enum StoreError {
pub trait Store: Send + Sync {
/// Append a single log entry to the segment log.
///
/// One line per call. The kernel orders concurrent `O_APPEND` writes
/// for lines < `PIPE_BUF`, so user-space serialization is unnecessary.
/// One committed line per successful call. Implementations must not expose
/// a failed call's partial record as committed data on later reads.
fn append(
&self,
session_id: SessionId,
@@ -3,6 +3,7 @@ use llm_engine::llm_client::types::{Item, RequestConfig};
use session_store::{
FsStore, LogEntry, Store, TraceEntry, collect_state, new_segment_id, new_session_id,
};
use std::io::Write;
fn nil_session_start(ts: u64, session_id: uuid::Uuid) -> LogEntry {
LogEntry::SegmentStart {
@@ -224,6 +225,71 @@ fn read_entry_count_matches_append_tally() {
assert_eq!(store.read_entry_count(sid, segid).unwrap(), entries.len());
}
#[test]
fn unterminated_utf8_tail_is_ignored_and_replaced_on_append() {
let dir = tempfile::tempdir().unwrap();
let store = FsStore::new(dir.path()).unwrap();
let sid = new_session_id();
let segid = new_segment_id();
let path = dir
.path()
.join(sid.to_string())
.join(format!("{segid}.jsonl"));
store
.append(sid, segid, &nil_session_start(1, sid))
.unwrap();
std::fs::OpenOptions::new()
.append(true)
.open(&path)
.unwrap()
// First byte of a three-byte UTF-8 code point, matching an ENOSPC
// partial write observed in a real session log.
.write_all(&[0xe3])
.unwrap();
assert_eq!(store.read_all(sid, segid).unwrap().len(), 1);
assert_eq!(store.read_entry_count(sid, segid).unwrap(), 1);
let next = LogEntry::UserInput {
ts: 2,
segments: vec![protocol::Segment::text("recovered")],
};
store.append(sid, segid, &next).unwrap();
let bytes = std::fs::read(&path).unwrap();
assert!(std::str::from_utf8(&bytes).is_ok());
assert_eq!(store.read_all(sid, segid).unwrap().len(), 2);
assert_eq!(store.read_entry_count(sid, segid).unwrap(), 2);
}
#[test]
fn newline_terminated_invalid_utf8_is_reported_as_corruption() {
let dir = tempfile::tempdir().unwrap();
let store = FsStore::new(dir.path()).unwrap();
let sid = new_session_id();
let segid = new_segment_id();
let path = dir
.path()
.join(sid.to_string())
.join(format!("{segid}.jsonl"));
store
.append(sid, segid, &nil_session_start(1, sid))
.unwrap();
std::fs::OpenOptions::new()
.append(true)
.open(path)
.unwrap()
.write_all(&[0xe3, b'\n'])
.unwrap();
assert!(matches!(
store.read_all(sid, segid),
Err(session_store::StoreError::Corrupt { line: 2, .. })
));
}
#[test]
fn lookup_session_of_finds_owning_session() {
let dir = tempfile::tempdir().unwrap();