storage: Add more tests for journal recovery

server/src/engine/storage/v2/raw/journal/raw/mod.rs

@@ -177,6 +177,7 @@ pub enum JournalReaderTraceEvent {
     ClosedAndReachedEof,
     ReopenSuccess,
     // event
+    LookingForEvent,
     AttemptingEvent(u64),
     DetectedServerEvent,
     ServerEventMetadataParsed,
@@ -734,6 +735,7 @@ impl<J: RawJournalAdapter> RawJournalReader<J> {
     }
     fn _scroll(&mut self, gs: &J::GlobalState) -> RuntimeResult<JournalInitializer> {
         loop {
+            jtrace_reader!(LookingForEvent);
             match self._apply_next_event_and_stop(gs) {
                 Ok(true) => {
                     jtrace_reader!(Completed);

server/src/engine/storage/v2/raw/journal/raw/tests/journal_ops.rs

@@ -72,6 +72,7 @@ fn journal_open_close() {
             intovec![
                 // init reader and read close event
                 JournalReaderTraceEvent::Initialized,
+                JournalReaderTraceEvent::LookingForEvent,
                 JournalReaderTraceEvent::AttemptingEvent(0),
                 JournalReaderTraceEvent::DriverEventExpectingClose,
                 JournalReaderTraceEvent::DriverEventCompletedBlockRead,
@@ -116,6 +117,7 @@ fn journal_open_close() {
             intovec![
                 // init reader and read reopen event
                 JournalReaderTraceEvent::Initialized,
+                JournalReaderTraceEvent::LookingForEvent,
                 JournalReaderTraceEvent::AttemptingEvent(0),
                 JournalReaderTraceEvent::DriverEventExpectingClose,
                 JournalReaderTraceEvent::DriverEventCompletedBlockRead,
@@ -125,6 +127,7 @@ fn journal_open_close() {
                 JournalReaderTraceEvent::DriverEventExpectingReopenGotReopen,
                 JournalReaderTraceEvent::ReopenSuccess,
                 // now read close event
+                JournalReaderTraceEvent::LookingForEvent,
                 JournalReaderTraceEvent::AttemptingEvent(2),
                 JournalReaderTraceEvent::DriverEventExpectingClose,
                 JournalReaderTraceEvent::DriverEventCompletedBlockRead,
@@ -198,11 +201,13 @@ fn journal_with_server_single_event() {
             intovec![
                 // init reader and read server event
                 JournalReaderTraceEvent::Initialized,
+                JournalReaderTraceEvent::LookingForEvent,
                 JournalReaderTraceEvent::AttemptingEvent(0),
                 JournalReaderTraceEvent::DetectedServerEvent,
                 JournalReaderTraceEvent::ServerEventMetadataParsed,
                 JournalReaderTraceEvent::ServerEventAppliedSuccess,
                 // now read close event
+                JournalReaderTraceEvent::LookingForEvent,
                 JournalReaderTraceEvent::AttemptingEvent(1),
                 JournalReaderTraceEvent::DriverEventExpectingClose,
                 JournalReaderTraceEvent::DriverEventCompletedBlockRead,
@@ -246,11 +251,13 @@ fn journal_with_server_single_event() {
             intovec![
                 // init reader and read server event
                 JournalReaderTraceEvent::Initialized,
+                JournalReaderTraceEvent::LookingForEvent,
                 JournalReaderTraceEvent::AttemptingEvent(0),
                 JournalReaderTraceEvent::DetectedServerEvent,
                 JournalReaderTraceEvent::ServerEventMetadataParsed,
                 JournalReaderTraceEvent::ServerEventAppliedSuccess,
                 // now read close event
+                JournalReaderTraceEvent::LookingForEvent,
                 JournalReaderTraceEvent::AttemptingEvent(1),
                 JournalReaderTraceEvent::DriverEventExpectingClose,
                 JournalReaderTraceEvent::DriverEventCompletedBlockRead,
@@ -261,6 +268,7 @@ fn journal_with_server_single_event() {
                 JournalReaderTraceEvent::DriverEventExpectingReopenGotReopen,
                 JournalReaderTraceEvent::ReopenSuccess,
                 // now read close event
+                JournalReaderTraceEvent::LookingForEvent,
                 JournalReaderTraceEvent::AttemptingEvent(3),
                 JournalReaderTraceEvent::DriverEventExpectingClose,
                 JournalReaderTraceEvent::DriverEventCompletedBlockRead,

server/src/engine/storage/v2/raw/journal/raw/tests/recovery.rs

@@ -26,94 +26,148 @@
 
 use {
     super::{SimpleDB, SimpleDBJournal},
-    crate::engine::{
+    crate::{
-        error::ErrorKind,
+        engine::{
-        storage::{
+            error::ErrorKind,
-            common::interface::fs::{File, FileExt, FileSystem, FileWriteExt},
+            storage::{
-            v2::raw::journal::{
+                common::interface::fs::{File, FileExt, FileSystem, FileWriteExt},
-                create_journal, open_journal,
+                v2::raw::journal::{
-                raw::{obtain_trace, DriverEvent, JournalReaderTraceEvent, RawJournalWriter},
+                    create_journal, open_journal,
-                repair_journal, JournalRepairMode, JournalSettings, RepairResult,
+                    raw::{obtain_trace, DriverEvent, JournalReaderTraceEvent, RawJournalWriter},
+                    repair_journal, JournalRepairMode, JournalSettings, RepairResult,
+                },
             },
+            RuntimeResult,
         },
+        IoResult,
     },
     std::io::ErrorKind as IoErrorKind,
 };
 
+fn create_trimmed_file(from: &str, to: &str, trim_to: u64) -> IoResult<()> {
+    FileSystem::copy(from, to)?;
+    let mut f = File::open(to)?;
+    f.f_truncate(trim_to)
+}
+
 #[test]
-fn close_event_corruption() {
+fn corruption_at_close() {
-    let full_file_size;
+    let initializers: Vec<fn() -> RuntimeResult<(&'static str, u64)>> = vec![
-    {
+        || {
-        // open and close a journal (and clear traces)
+            let jrnl_id = "close_event_corruption_empty.db";
-        let mut jrnl = create_journal::<SimpleDBJournal>("close_event_corruption.db").unwrap();
+            let mut jrnl = create_journal::<SimpleDBJournal>(jrnl_id)?;
-        RawJournalWriter::close_driver(&mut jrnl).unwrap();
+            RawJournalWriter::close_driver(&mut jrnl)?;
+            Ok((jrnl_id, 0))
+        },
+        || {
+            let mut operation_count = 0;
+            let jrnl_id = "close_event_corruption.db";
+            let mut sdb = SimpleDB::new();
+            let mut jrnl = create_journal::<SimpleDBJournal>(jrnl_id)?;
+            for num in 1..=100 {
+                operation_count += 1;
+                sdb.push(&mut jrnl, format!("key-{num}"))?;
+                if num % 10 == 0 {
+                    operation_count += 1;
+                    sdb.pop(&mut jrnl)?;
+                }
+            }
+            RawJournalWriter::close_driver(&mut jrnl)?;
+            Ok((jrnl_id, operation_count))
+        },
+    ];
+    for initializer in initializers {
+        // initialize journal, get size and clear traces
+        let (journal_id, next_id) = initializer().unwrap();
+        let journal_size = File::open(journal_id).unwrap().f_len().unwrap();
         let _ = obtain_trace();
-        full_file_size = {
+        // now trim and repeat
-            let f = File::open("close_event_corruption.db").unwrap();
+        for (trim_size, new_size) in (1..=DriverEvent::FULL_EVENT_SIZE)
-            f.f_len().unwrap()
+            .rev()
-        };
+            .map(|trim_size| (trim_size, journal_size - trim_size as u64))
-    }
+        {
-    for (trim_size, new_size) in (1..=DriverEvent::FULL_EVENT_SIZE)
+            // create a copy of the "good" journal and trim to simulate data loss
-        .rev()
+            let trimmed_journal_path = format!("{journal_id}-trimmed-{trim_size}.db");
-        .map(|trim_size| (trim_size, full_file_size - trim_size as u64))
+            create_trimmed_file(journal_id, &trimmed_journal_path, new_size).unwrap();
-    {
+            // init misc
-        // create a copy of the "good" journal
+            let simple_db = SimpleDB::new();
-        let trimmed_journal_path = format!("close_event_corruption-trimmed-{trim_size}.db");
+            let open_journal_fn = || {
-        FileSystem::copy("close_event_corruption.db", &trimmed_journal_path).unwrap();
+                open_journal::<SimpleDBJournal>(
-        let simple_db = SimpleDB::new();
+                    &trimmed_journal_path,
-        let open_journal_fn = || {
+                    &simple_db,
-            open_journal::<SimpleDBJournal>(
+                    JournalSettings::default(),
-                &trimmed_journal_path,
+                )
-                &simple_db,
+            };
-                JournalSettings::default(),
+            // open the journal and validate failure
-            )
+            let open_err = open_journal_fn().unwrap_err();
-        };
+            let trace = obtain_trace();
-        // trim this journal to simulate loss of data
+            if trim_size > (DriverEvent::FULL_EVENT_SIZE - (sizeof!(u128) + sizeof!(u64))) {
-        let mut f = File::open(&trimmed_journal_path).unwrap();
+                // the amount of trim from the end of the file causes us to lose valuable metadata
-        f.f_truncate(new_size).unwrap();
+                if next_id == 0 {
-        // open the journal and validate failure
+                    // empty log
-        let open_err = open_journal_fn().unwrap_err();
+                    assert_eq!(
-        let trace = obtain_trace();
+                        trace,
-        if trim_size > (DriverEvent::FULL_EVENT_SIZE - (sizeof!(u128) + sizeof!(u64))) {
+                        intovec![
-            // the amount of trim from the end of the file causes us to lose valuable metadata
+                            JournalReaderTraceEvent::Initialized,
+                            JournalReaderTraceEvent::LookingForEvent
+                        ],
+                        "failed at trim_size {trim_size} for journal {journal_id}"
+                    )
+                } else {
+                    assert_eq!(
+                        *trace.last().unwrap(),
+                        JournalReaderTraceEvent::LookingForEvent.into(),
+                        "failed at trim_size {trim_size} for journal {journal_id}"
+                    );
+                }
+            } else {
+                // the amount of trim still allows us to read some metadata
+                if next_id == 0 {
+                    // empty log
+                    assert_eq!(
+                        trace,
+                        intovec![
+                            JournalReaderTraceEvent::Initialized,
+                            JournalReaderTraceEvent::LookingForEvent,
+                            JournalReaderTraceEvent::AttemptingEvent(next_id),
+                            JournalReaderTraceEvent::DriverEventExpectingClose,
+                        ],
+                        "failed at trim_size {trim_size} for journal {journal_id}"
+                    )
+                } else {
+                    assert_eq!(
+                        &trace[trace.len() - 3..],
+                        &into_array![
+                            JournalReaderTraceEvent::LookingForEvent,
+                            JournalReaderTraceEvent::AttemptingEvent(next_id),
+                            JournalReaderTraceEvent::DriverEventExpectingClose
+                        ],
+                        "failed at trim_size {trim_size} for journal {journal_id}"
+                    );
+                }
+            }
             assert_eq!(
-                trace,
+                open_err.kind(),
-                intovec![JournalReaderTraceEvent::Initialized],
+                &ErrorKind::IoError(IoErrorKind::UnexpectedEof.into()),
-                "failed at trim_size {trim_size}"
+                "failed at trim_size {trim_size} for journal {journal_id}"
             );
-        } else {
+            // now repair this log
-            // the amount of trim still allows us to read some metadata
             assert_eq!(
-                trace,
+                repair_journal::<SimpleDBJournal>(
-                intovec![
+                    &trimmed_journal_path,
-                    JournalReaderTraceEvent::Initialized,
+                    &simple_db,
-                    JournalReaderTraceEvent::AttemptingEvent(0),
+                    JournalSettings::default(),
-                    JournalReaderTraceEvent::DriverEventExpectingClose
+                    JournalRepairMode::Simple,
-                ],
+                )
-                "failed at trim_size {trim_size}"
+                .unwrap(),
+                RepairResult::UnspecifiedLoss((DriverEvent::FULL_EVENT_SIZE - trim_size) as _),
+                "failed at trim_size {trim_size} for journal {journal_id}"
             );
+            // now reopen log and ensure it's repaired
+            let mut jrnl = open_journal_fn().unwrap();
+            RawJournalWriter::close_driver(&mut jrnl).unwrap();
+            // clear trace
+            let _ = obtain_trace();
         }
-        assert_eq!(
-            open_err.kind(),
-            &ErrorKind::IoError(IoErrorKind::UnexpectedEof.into()),
-            "failed at trim_size {trim_size}"
-        );
-        // now repair this log
-        assert_eq!(
-            repair_journal::<SimpleDBJournal>(
-                &trimmed_journal_path,
-                &simple_db,
-                JournalSettings::default(),
-                JournalRepairMode::Simple,
-            )
-            .unwrap(),
-            RepairResult::UnspecifiedLoss((DriverEvent::FULL_EVENT_SIZE - trim_size) as _),
-            "failed at trim_size {trim_size}"
-        );
-        // now reopen log and ensure it's repaired
-        let mut jrnl = open_journal_fn().unwrap();
-        RawJournalWriter::close_driver(&mut jrnl).unwrap();
-        // clear trace
-        let _ = obtain_trace();
     }
 }