diff --git a/apps/figcraft-server/src/disk.rs b/apps/figcraft-server/src/disk.rs index f58f25b2..af6e0f99 100644 --- a/apps/figcraft-server/src/disk.rs +++ b/apps/figcraft-server/src/disk.rs @@ -8,8 +8,10 @@ //! length (u32 LE), CRC-32 (u32 LE), one [`Journal`] entry in the wire encoding. //! //! Compaction writes the next generation's snapshot, then an empty log of that generation. A log -//! whose generation isn't the snapshot's is from before a compaction that was cut short: what it -//! holds is in the snapshot already. A log ends at its first damaged record (a write cut short). +//! whose generation isn't the snapshot's is usually from before a compaction that was cut short +//! (what it holds is in the snapshot already), but no checksum covers either generation, so the +//! store replays such a log anyway and reports any change the snapshot lacked. A log ends at its +//! first damaged record (a write cut short). use std::fs::{self, File}; use std::io::{self, Read, Write}; diff --git a/apps/figcraft-server/src/store.rs b/apps/figcraft-server/src/store.rs index 538adeff..ea9bc626 100644 --- a/apps/figcraft-server/src/store.rs +++ b/apps/figcraft-server/src/store.rs @@ -440,7 +440,7 @@ impl Store { && let Ok(log) = disk::read_log(&bytes) && log.generation != generation { - log::info!("file at {}: its log predates the last compaction; it is ignored", path.display()); + log::info!("file at {}: its log isn't of its snapshot's generation; it is replayed over it when the file opens", path.display()); } let bytes = [SNAPSHOT, LOG].iter().filter_map(|n| fs::metadata(path.join(n)).ok()).map(|m| m.len()).sum(); Ok(Entry { meta, links, log: None, bytes, forced: 0 }) @@ -1126,8 +1126,32 @@ impl Store { fresh_log = true; } } - // From before a compaction that was cut short: the snapshot has it all. - Ok(_) => {} + // From before a compaction that was cut short, the snapshot has it all; or a generation + // field damaged, which no checksum covers. Replaying tells them apart without trusting + // it: entries the snapshot holds are skipped, so only edits it lacks change anything. + Ok(log) => { + let before = server.seq(); + let mut stopped = None; + for entry in log.entries { + if let Err(e) = server.replay(entry) { + stopped = Some(e); + break; + } + } + let (snap, found, recovered) = (generation, log.generation, server.seq().saturating_sub(before)); + if recovered > 0 { + issues.push(format!( + "file {file}: its log's generation ({found}) doesn't match its snapshot's ({snap}), but it held \ + {recovered} changes the snapshot didn't; they were recovered" + )); + } + if let Some(e) = stopped { + issues.push(format!( + "file {file}: its log's generation ({found}) doesn't match its snapshot's ({snap}) and it stops \ + making sense after {recovered} newer changes ({e}); the rest was dropped" + )); + } + } Err(why) => issues.push(format!("file {file}: {why}; starting a new log")), } for i in issues { diff --git a/apps/figcraft-server/tests/header_recovery.rs b/apps/figcraft-server/tests/header_recovery.rs new file mode 100644 index 00000000..d728908d --- /dev/null +++ b/apps/figcraft-server/tests/header_recovery.rs @@ -0,0 +1,139 @@ +//! A generation field damaged after an abrupt stop must not make the server drop a log that still +//! holds confirmed edits (#408): the log is replayed over the snapshot, which only the changes the +//! snapshot lacks survive, and the damage is reported. A genuine leftover of a compaction cut short +//! still restores silently. +#![allow(clippy::unwrap_used, clippy::expect_used, clippy::panic)] + +use figcraft_collab::message::{Access, ClientMsg}; +use figcraft_collab::{Client, Outgoing, Replica, Server}; +use figcraft_collab_net::hub::Backend; +use figcraft_doc::Document; +use figcraft_server::config::Config; +use figcraft_server::disk::{self, LOG, SNAPSHOT}; +use figcraft_server::store::{FILES, Store}; +use std::fs; +use std::path::{Path, PathBuf}; + +struct Fixture(PathBuf); + +impl Fixture { + fn new() -> Self { + let path = std::env::temp_dir().join(format!("figcraft-header-recovery-{}", figcraft_collab_net::token::file_id().unwrap())); + fs::create_dir(&path).unwrap(); + Self(path) + } +} + +impl Drop for Fixture { + fn drop(&mut self) { + let _ = fs::remove_dir_all(&self.0); + } +} + +fn page_name(server: &Server) -> String { + let doc = server.document(); + doc.node(doc.first_page().unwrap()).unwrap().name.clone() +} + +/// A published file whose first page was renamed "Kept", flushed to its log (not compacted), then +/// the store dropped without stopping (an abrupt stop). Returns the file id and the final state. +fn renamed_and_stopped(data: &Path) -> (String, Server) { + let mut store = Store::open(data, Config::default().store()).unwrap(); + let snapshot = Replica::new(Document::new("Fixture")).snapshot().unwrap(); + let (info, _, _) = store.publish("Fixture", &snapshot).unwrap(); + let id = info.id; + let mut server = store.open(&id).unwrap(); + let ClientMsg::Hello(hello) = Client::hello("f", "", "Editor", "#FF8800") else { panic!("not a hello") }; + let (_, messages) = server.join_as(hello, Access::Edit).unwrap(); + let Some(Outgoing::To(_, welcome)) = messages.into_iter().next() else { panic!("no welcome") }; + let mut client = Client::join(welcome).unwrap(); + store.changed(&id, &mut server); + let mut edited = client.document().clone(); + let page = edited.first_page().unwrap(); + edited.node_mut(page).unwrap().name = "Kept".into(); + let change = client.edit(&edited).unwrap().unwrap(); + assert!(!server.receive(client.id(), change).is_empty()); + store.changed(&id, &mut server); + assert!(store.flush().is_empty(), "the edit must reach disk"); + assert_eq!(page_name(&server), "Kept"); + let dir = data.join(FILES).join(&id); + assert!(!disk::read_log(&fs::read(dir.join(LOG)).unwrap()).unwrap().entries.is_empty()); + assert_eq!(disk::decode_snapshot(&fs::read(dir.join(SNAPSHOT)).unwrap()).unwrap().1.seq, 0, "the rename is only in the log"); + drop(store); + (id, server) +} + +/// Reopen the data directory: the file's first page name and the problems reported. +fn reopen(data: &Path, id: &str) -> (String, Vec) { + let mut store = Store::open(data, Config::default().store()).unwrap(); + let server = store.open(id).unwrap(); + (page_name(&server), store.problems().to_vec()) +} + +fn flip(path: &Path, at: usize) { + let mut bytes = fs::read(path).unwrap(); + bytes[at] ^= 1; + fs::write(path, bytes).unwrap(); +} + +/// The generation field's first byte in both headers (after the magic and the format byte). +const GENERATION_AT: usize = 5; + +#[test] +fn an_intact_log_restores_its_edits_without_a_report() { + let fixture = Fixture::new(); + let (id, _) = renamed_and_stopped(&fixture.0); + let (name, problems) = reopen(&fixture.0, &id); + assert_eq!(name, "Kept"); + assert!(problems.is_empty(), "{problems:?}"); +} + +#[test] +fn a_damaged_log_generation_keeps_the_edits_and_is_reported() { + let fixture = Fixture::new(); + let (id, _) = renamed_and_stopped(&fixture.0); + let log = fixture.0.join(FILES).join(&id).join(LOG); + flip(&log, GENERATION_AT); + // The records themselves still read: only the header's generation changed. + let read = disk::read_log(&fs::read(&log).unwrap()).unwrap(); + assert!(read.damaged.is_none() && !read.entries.is_empty()); + let (name, problems) = reopen(&fixture.0, &id); + assert_eq!(name, "Kept", "the flushed rename must survive"); + assert!(problems.iter().any(|p| p.contains(&id) && p.contains("generation")), "{problems:?}"); + // And it stays: the recovered edit is now in the file's snapshot. + assert_eq!(reopen(&fixture.0, &id).0, "Kept"); +} + +#[test] +fn a_damaged_snapshot_generation_keeps_the_edits_and_is_reported() { + let fixture = Fixture::new(); + let (id, _) = renamed_and_stopped(&fixture.0); + let snapshot = fixture.0.join(FILES).join(&id).join(SNAPSHOT); + flip(&snapshot, GENERATION_AT); + assert!(disk::check_snapshot(&fs::read(&snapshot).unwrap()).is_ok(), "the generation is outside the checksum"); + let (name, problems) = reopen(&fixture.0, &id); + assert_eq!(name, "Kept", "the flushed rename must survive"); + assert!(problems.iter().any(|p| p.contains(&id) && p.contains("generation")), "{problems:?}"); + assert_eq!(reopen(&fixture.0, &id).0, "Kept"); +} + +#[test] +fn a_damaged_log_format_is_still_reported() { + let fixture = Fixture::new(); + let (id, _) = renamed_and_stopped(&fixture.0); + flip(&fixture.0.join(FILES).join(&id).join(LOG), 4); + let (_, problems) = reopen(&fixture.0, &id); + assert!(problems.iter().any(|p| p.contains(&id) && p.contains("format")), "{problems:?}"); +} + +#[test] +fn a_log_left_by_a_compaction_cut_short_restores_without_a_report() { + let fixture = Fixture::new(); + let (id, server) = renamed_and_stopped(&fixture.0); + // The next snapshot was written (it holds the rename); the old log wasn't replaced yet. + let bytes = disk::encode_snapshot(2, &server.state().unwrap()).unwrap(); + fs::write(fixture.0.join(FILES).join(&id).join(SNAPSHOT), bytes).unwrap(); + let (name, problems) = reopen(&fixture.0, &id); + assert_eq!(name, "Kept"); + assert!(problems.is_empty(), "a leftover log is expected, not damage: {problems:?}"); +} diff --git a/docs/server.md b/docs/server.md index f2e4820c..021d0e3f 100644 --- a/docs/server.md +++ b/docs/server.md @@ -337,8 +337,9 @@ the address it came from and when it was last opened (for expiry). before the server tells anyone about the change. - **Compaction** writes the file's state as the next snapshot and starts an empty log, after `compact_after` entries or `compact_mb` of log, when the last person leaves, and when the server - stops. A log left over from a compaction cut short is recognised and ignored (the snapshot holds - it all). + stops. A log left over from a compaction cut short is replayed over the snapshot, which already + holds it all, so nothing changes. If a damaged generation field made a current log look like such + a leftover, its edits the snapshot lacks are recovered the same way and the damage is reported. - **Damage is skipped and reported, never deleted.** At startup a folder whose description, links or snapshot can't be read is left out and logged; a log that ends in a cut-short or damaged record loses only that end (logged when the file opens). Leftover temporary files are removed.