Logging Enhancements (#87)

Cargo.toml

@@ -21,8 +21,7 @@ version = "0.2.1"
 
 [package.metadata.simics]
 package-number = 31337
-
-version = "6.1.0"
+version = "6.1.1"
 
 [lib]
 crate-type = ["cdylib", "rlib"]
@@ -76,6 +75,7 @@ num-derive = "0.4.2"
 tracing-subscriber = "0.3.18"
 tracing = { version = "0.1.40", features = ["log"] }
 yaxpeax-arm = "0.2.5"
+chrono = "0.4.38"
 
 [dev-dependencies]
 simics-test = { path = "simics-rs/simics-test" }

src/fuzzer/feedbacks/mod.rs

@@ -65,11 +65,14 @@ where
                 .ok_or_else(|| {
                     libafl::Error::unknown("Failed to get observer from observers tuple")
                 })?;
+
             let map_state = state
                 .named_metadata_map_mut()
                 .get_mut::<MapFeedbackMetadata<T>>(self.name())
                 .ok_or_else(|| libafl::Error::unknown("Failed to get metadata"))?;
+
             let len = observer.len();
+
             if map_state.history_map.len() < len {
                 map_state.history_map.resize(len, observer.initial());
             }
@@ -106,6 +109,106 @@ where
                 .ok_or_else(|| libafl::Error::unknown("Failed to send report"))?;
         }
 
+        if *exit_kind == ExitKind::Crash {
+            let observer = observers
+                .match_name::<O>(self.observer_name())
+                .ok_or_else(|| {
+                    libafl::Error::unknown("Failed to get observer from observers tuple")
+                })?;
+
+            let map_state = state
+                .named_metadata_map_mut()
+                .get_mut::<MapFeedbackMetadata<T>>(self.name())
+                .ok_or_else(|| libafl::Error::unknown("Failed to get metadata"))?;
+
+            let len = observer.len();
+
+            if map_state.history_map.len() < len {
+                map_state.history_map.resize(len, observer.initial());
+            }
+
+            let history_map = map_state.history_map.as_slice();
+
+            let initial = observer.initial();
+
+            let mut indices = vec![];
+
+            for (i, item) in observer
+                .as_iter()
+                .copied()
+                .enumerate()
+                .filter(|(_, item)| *item != initial)
+            {
+                let existing = unsafe { *history_map.get_unchecked(i) };
+                let reduced = R::reduce(existing, item);
+                if N::is_novel(existing, reduced) {
+                    indices.push(i);
+                }
+            }
+
+            self.sender
+                .get_mut()
+                .and_then(|sender| {
+                    sender
+                        .send(FuzzerMessage::Crash {
+                            indices,
+                            input: input.target_bytes().as_slice().to_vec(),
+                        })
+                        .ok()
+                })
+                .ok_or_else(|| libafl::Error::unknown("Failed to send report"))?;
+        }
+
+        if *exit_kind == ExitKind::Timeout {
+            let observer = observers
+                .match_name::<O>(self.observer_name())
+                .ok_or_else(|| {
+                    libafl::Error::unknown("Failed to get observer from observers tuple")
+                })?;
+
+            let map_state = state
+                .named_metadata_map_mut()
+                .get_mut::<MapFeedbackMetadata<T>>(self.name())
+                .ok_or_else(|| libafl::Error::unknown("Failed to get metadata"))?;
+
+            let len = observer.len();
+
+            if map_state.history_map.len() < len {
+                map_state.history_map.resize(len, observer.initial());
+            }
+
+            let history_map = map_state.history_map.as_slice();
+
+            let initial = observer.initial();
+
+            let mut indices = vec![];
+
+            for (i, item) in observer
+                .as_iter()
+                .copied()
+                .enumerate()
+                .filter(|(_, item)| *item != initial)
+            {
+                let existing = unsafe { *history_map.get_unchecked(i) };
+                let reduced = R::reduce(existing, item);
+                if N::is_novel(existing, reduced) {
+                    indices.push(i);
+                }
+            }
+
+            self.sender
+                .get_mut()
+                .and_then(|sender| {
+                    sender
+                        .send(FuzzerMessage::Timeout {
+                            indices,
+                            input: input.target_bytes().as_slice().to_vec(),
+                        })
+                        .ok()
+                })
+                .ok_or_else(|| libafl::Error::unknown("Failed to send report"))?;
+        }
+
         Ok(is_interesting)
     }
 

src/fuzzer/messages/mod.rs

@@ -7,4 +7,6 @@ use serde::Serialize;
 pub(crate) enum FuzzerMessage {
     String(String),
     Interesting { indices: Vec<usize>, input: Vec<u8> },
+    Crash { indices: Vec<usize>, input: Vec<u8> },
+    Timeout { indices: Vec<usize>, input: Vec<u8> },
 }

src/haps/mod.rs

@@ -406,8 +406,12 @@ impl Tsffs {
                 .ok_or_else(|| anyhow!("No fuzzer tx channel"))?;
 
             match kind {
-                SolutionKind::Timeout => fuzzer_tx.send(ExitKind::Timeout)?,
+                SolutionKind::Timeout => {
+                    self.timeouts += 1;
+                    fuzzer_tx.send(ExitKind::Timeout)?
+                }
                 SolutionKind::Exception | SolutionKind::Breakpoint | SolutionKind::Manual => {
+                    self.solutions += 1;
                     fuzzer_tx.send(ExitKind::Crash)?
                 }
             }
@@ -427,7 +431,7 @@ impl Tsffs {
             self.post_timeout_event()?;
         }
 
-        if self.save_all_execution_traces || self.save_solution_execution_traces {
+        if self.save_all_execution_traces {
             self.save_execution_trace()?;
         }
 

src/lib.rs

@@ -39,14 +39,15 @@ use indoc::indoc;
 use libafl::{inputs::HasBytesVec, prelude::ExitKind};
 use libafl_bolts::prelude::OwnedMutSlice;
 use libafl_targets::AFLppCmpLogMap;
+use log::LogMessage;
 use magic::MagicNumber;
 use num_traits::FromPrimitive as _;
 use serde::{Deserialize, Serialize};
 use serde_json::to_writer;
 use simics::{
     break_simulation, class, debug, error, free_attribute, get_class, get_interface,
-    get_processor_number, info, lookup_file, object_clock, run_command, run_python, simics_init,
-    trace, version_base, AsConfObject, BreakpointId, ClassCreate, ClassObjectsFinalize, ConfObject,
+    get_processor_number, lookup_file, object_clock, run_command, run_python, simics_init, trace,
+    version_base, AsConfObject, BreakpointId, ClassCreate, ClassObjectsFinalize, ConfObject,
     CoreBreakpointMemopHap, CoreExceptionHap, CoreMagicInstructionHap, CoreSimulationStoppedHap,
     CpuInstrumentationSubscribeInterface, Event, EventClassFlag, FromConfObject, HapHandle,
     Interface, IntoAttrValueDict,
@@ -381,6 +382,9 @@ pub(crate) struct Tsffs {
     /// Whether to quit on iteration limit
     pub quit_on_iteration_limit: bool,
     #[class(attribute(optional, default = false))]
+    /// Whether to save execution traces of test cases which result in a timeout
+    pub save_timeout_execution_traces: bool,
+    #[class(attribute(optional, default = false))]
     /// Whether to save execution traces of test cases which result in a solution
     pub save_solution_execution_traces: bool,
     #[class(attribute(optional, default = false))]
@@ -399,6 +403,12 @@ pub(crate) struct Tsffs {
     #[class(attribute(optional, default = false))]
     /// Whether execution traces should include just PC (vs instruction text and bytes)
     pub execution_trace_pc_only: bool,
+    #[class(attribute(optional, default = true))]
+    /// Whether a heartbeat message should be emitted every `heartbeat_interval` seconds
+    pub heartbeat: bool,
+    #[class(attribute(optional, default = 60))]
+    /// The interval in seconds between heartbeat messages
+    pub heartbeat_interval: u64,
 
     #[attr_value(skip)]
     /// Handle for the core simulation stopped hap
@@ -489,6 +499,10 @@ pub(crate) struct Tsffs {
     // #[builder(default = SystemTime::now())]
     /// The time the fuzzer was started at
     start_time: OnceCell<SystemTime>,
+    #[attr_value(skip)]
+    // #[builder(default = SystemTime::now())]
+    /// The time the fuzzer was started at
+    last_heartbeat_time: Option<SystemTime>,
 
     #[attr_value(skip)]
     log: OnceCell<File>,
@@ -521,6 +535,12 @@ pub(crate) struct Tsffs {
     #[attr_value(skip)]
     /// Whether snapshots are used. Snapshots are used on Simics 7.0.0 and later.
     use_snapshots: bool,
+    #[attr_value(skip)]
+    /// The number of timeouts so far
+    timeouts: usize,
+    #[attr_value(skip)]
+    /// The number of solutions so far
+    solutions: usize,
 }
 
 impl ClassObjectsFinalize for Tsffs {
@@ -705,6 +725,8 @@ impl Tsffs {
             return Ok(());
         }
 
+        self.log(LogMessage::startup())?;
+
         #[cfg(simics_version_7)]
         {
             if self.checkpoint_path.exists() {
@@ -845,9 +867,8 @@ impl Tsffs {
                 start_processor_cpu,
                 start_processor_clock,
                 self.timeout,
-                move |obj| {
+                move |_obj| {
                     let tsffs: &'static mut Tsffs = tsffs_ptr.into();
-                    info!(tsffs.as_conf_object_mut(), "timeout({:#x})", obj as usize);
                     tsffs
                         .stop_simulation(StopReason::Solution {
                             kind: SolutionKind::Timeout,