Add --verbose cmdline flag (#216)

src/caller/src/main.rs

@@ -5,7 +5,7 @@ extern crate cwe_checker_lib; // Needed for the docstring-link to work
 
 use cwe_checker_lib::analysis::graph;
 use cwe_checker_lib::utils::binary::{BareMetalConfig, RuntimeMemoryImage};
-use cwe_checker_lib::utils::log::print_all_messages;
+use cwe_checker_lib::utils::log::{print_all_messages, LogLevel};
 use cwe_checker_lib::utils::{get_ghidra_plugin_path, read_config_file};
 use cwe_checker_lib::AnalysisResults;
 use cwe_checker_lib::{intermediate_representation::Project, utils::log::LogMessage};
@@ -46,7 +46,11 @@ struct CmdlineArgs {
     #[structopt(long, short)]
     quiet: bool,
 
-    /// Include various statistics in the debug log messages.
+    /// Print additional debug log messages.
+    #[structopt(long, short, conflicts_with("quiet"))]
+    verbose: bool,
+
+    /// Include various statistics in the log messages.
     /// This can be helpful for assessing the analysis quality for the input binary.
     #[structopt(long, conflicts_with("quiet"))]
     statistics: bool,
@@ -210,6 +214,13 @@ fn run_with_ghidra(args: &CmdlineArgs) {
     // Print the results of the modules.
     if args.quiet {
         all_logs = Vec::new(); // Suppress all log messages since the `--quiet` flag is set.
+    } else {
+        if args.statistics {
+            cwe_checker_lib::utils::log::add_debug_log_statistics(&mut all_logs);
+        }
+        if !args.verbose {
+            all_logs.retain(|log_msg| log_msg.level != LogLevel::Debug);
+        }
     }
     print_all_messages(all_logs, all_cwes, args.out.as_deref(), args.json);
 }

src/cwe_checker_lib/src/analysis/pointer_inference/mod.rs

@@ -151,10 +151,13 @@ impl<'a> PointerInference<'a> {
         let mut fixpoint_computation =
             super::forward_interprocedural_fixpoint::create_computation_with_alternate_worklist_order(context, None);
         if print_stats {
-            let _ = log_sender.send(LogThreadMsg::Log(LogMessage::new_debug(format!(
-                "Pointer Inference: Adding {} entry points",
-                entry_sub_to_entry_node_map.len()
-            ))));
+            let _ = log_sender.send(LogThreadMsg::Log(
+                LogMessage::new_info(format!(
+                    "Adding {} entry points",
+                    entry_sub_to_entry_node_map.len()
+                ))
+                .source("Pointer Inference"),
+            ));
         }
         for (sub_tid, start_node_index) in entry_sub_to_entry_node_map.into_iter() {
             let mut fn_entry_state = State::new(&project.stack_pointer_register, sub_tid.clone());
@@ -284,8 +287,8 @@ impl<'a> PointerInference<'a> {
             }
         }
         if print_stats {
-            self.log_debug(format!(
-                "Pointer Inference: Adding {} speculative entry points",
+            self.log_info(format!(
+                "Adding {} speculative entry points",
                 new_entry_points.len()
             ));
         }
@@ -320,14 +323,14 @@ impl<'a> PointerInference<'a> {
                 }
             }
         }
-        self.log_debug(format!(
-            "Pointer Inference: Blocks with state: {} / {}",
+        self.log_info(format!(
+            "Blocks with state: {} / {}",
             stateful_blocks, all_blocks
         ));
     }
 
-    fn log_debug(&self, msg: impl Into<String>) {
-        let log_msg = LogMessage::new_debug(msg.into());
+    fn log_info(&self, msg: impl Into<String>) {
+        let log_msg = LogMessage::new_info(msg.into()).source("Pointer Inference");
         let _ = self.log_collector.send(LogThreadMsg::Log(log_msg));
     }
 
@@ -354,9 +357,9 @@ impl<'a> PointerInference<'a> {
 
         if !self.computation.has_stabilized() {
             let worklist_size = self.computation.get_worklist().len();
-            let _ = self.log_debug(format!(
-                "Pointer Inference: Fixpoint did not stabilize. Remaining worklist size: {}",
-                worklist_size
+            let _ = self.log_info(format!(
+                "Fixpoint did not stabilize. Remaining worklist size: {}",
+                worklist_size,
             ));
         }
         if print_stats {

src/cwe_checker_lib/src/analysis/pointer_inference/statistics.rs

@@ -33,7 +33,7 @@ impl MemAccessStats {
     fn print_general_stats(&self, log_collector: Sender<LogThreadMsg>) {
         let all_mem_ops = self.all_mem_ops as f64;
         let msg = format!(
-            "Pointer Inference: {} memory operations.\n\
+            "{} memory operations.\n\
             \t{:.2}% tracked,\n\
             \t{:.2}% partially tracked,\n\
             \t{:.2}% untracked,\n\
@@ -44,14 +44,14 @@ impl MemAccessStats {
             self.is_only_top as f64 / all_mem_ops * 100.,
             self.empty_errors as f64 / all_mem_ops * 100.,
         );
-        let log_msg = LogMessage::new_debug(msg);
+        let log_msg = LogMessage::new_info(msg).source("Pointer Inference");
         let _ = log_collector.send(LogThreadMsg::Log(log_msg));
     }
 
     fn print_tracked_mem_ops_stats(&self, log_collector: Sender<LogThreadMsg>) {
         let all_mem_ops = self.all_mem_ops as f64;
         let msg = format!(
-            "Pointer Inference: {} ({:.2}%) memory operations with exactly known target. Of these are\n\
+            "{} ({:.2}%) memory operations with exactly known target. Of these are\n\
             \t{:.2}% global memory access,\n\
             \t{:.2}% current stack access,\n\
             \t{:.2}% other (heap or stack) access,\n\
@@ -62,10 +62,12 @@ impl MemAccessStats {
             self.global_mem_access as f64 / self.ops_with_exact_target_known() as f64 * 100.,
             self.current_stack_access as f64 / self.ops_with_exact_target_known() as f64 * 100.,
             self.non_current_stack_access as f64 / self.ops_with_exact_target_known() as f64 * 100.,
-            self.exact_target_with_exact_offset as f64 / self.ops_with_exact_target_known() as f64 * 100.,
-            self.exact_target_with_top_offset as f64 / self.ops_with_exact_target_known() as f64 * 100.,
+            self.exact_target_with_exact_offset as f64 / self.ops_with_exact_target_known() as f64
+                * 100.,
+            self.exact_target_with_top_offset as f64 / self.ops_with_exact_target_known() as f64
+                * 100.,
         );
-        let log_msg = LogMessage::new_debug(msg);
+        let log_msg = LogMessage::new_info(msg).source("Pointer Inference");
         let _ = log_collector.send(LogThreadMsg::Log(log_msg));
     }
 

src/cwe_checker_lib/src/utils/log.rs

 //! Structs and functions for generating log messages and CWE warnings.
 
 use crate::prelude::*;
-use std::thread::JoinHandle;
+use std::{collections::BTreeMap, thread::JoinHandle};
 
 /// A CWE warning message.
 #[derive(Serialize, Deserialize, Debug, PartialEq, Eq, Hash, Clone, PartialOrd, Ord, Default)]
@@ -197,6 +197,43 @@ pub fn print_all_messages(
     }
 }
 
+/// For each analysis count the number of debug log messages in `all_logs`
+/// and add a (INFO level) log message with the resulting number to `all_logs`.
+/// Also count and log the number of general debug log messages.
+pub fn add_debug_log_statistics(all_logs: &mut Vec<LogMessage>) {
+    let mut analysis_debug_log_count = BTreeMap::new();
+    let mut general_debug_log_count = 0u64;
+    for log in all_logs.iter().filter(|log| log.level == LogLevel::Debug) {
+        if let Some(analysis) = &log.source {
+            analysis_debug_log_count
+                .entry(analysis.clone())
+                .and_modify(|count| *count += 1)
+                .or_insert(1u64);
+        } else {
+            general_debug_log_count += 1;
+        }
+    }
+    for (analysis, count) in analysis_debug_log_count {
+        all_logs.push(LogMessage {
+            text: format!("Logged {} debug log messages.", count),
+            level: LogLevel::Info,
+            location: None,
+            source: Some(analysis),
+        });
+    }
+    if general_debug_log_count > 0 {
+        all_logs.push(LogMessage {
+            text: format!(
+                "Logged {} general debug log messages.",
+                general_debug_log_count
+            ),
+            level: LogLevel::Info,
+            location: None,
+            source: None,
+        });
+    }
+}
+
 /// The message types a logging thread can receive.
 /// See the [`LogThread`] type for more information.
 #[derive(Serialize, Deserialize, Debug, PartialEq, Eq, Hash, Clone, PartialOrd, Ord)]