fix: removed choosing options time from elapsed time #1291

src/debug/checkpoint_process_timer.rs

@@ -3,7 +3,6 @@ use std::sync::Mutex;
 use crate::detections::utils::output_duration;
 use chrono::{DateTime, Local};
 use lazy_static::lazy_static;
-use nested::Nested;
 
 lazy_static! {
     pub static ref CHECKPOINT: Mutex<CheckPointProcessTimer> =
@@ -12,15 +11,21 @@ lazy_static! {
 
 pub struct CheckPointProcessTimer {
     prev_checkpoint: Option<DateTime<Local>>,
-    stocked_results: Nested<String>,
+    stocked_results: Vec<CheckPointTimeStore>,
+}
+
+pub struct CheckPointTimeStore {
+    pub output_str: String,
+    pub sec: i64,
+    pub msec: i64,
 }
 
 impl CheckPointProcessTimer {
     /// static変数に最初に投入するための構造体情報を作成する関数
     pub fn create_checkpoint_timer() -> Self {
         CheckPointProcessTimer {
             prev_checkpoint: None,
-            stocked_results: Nested::<String>::new(),
+            stocked_results: Vec::new(),
         }
     }
 
@@ -30,31 +35,61 @@ impl CheckPointProcessTimer {
     }
 
     /// ラップタイムを取得して、出力用の配列に格納する関数
-    pub fn rap_check_point(&mut self, output_str: &str) {
+    pub fn rap_checkpoint(&mut self, output_str: &str) {
         if self.prev_checkpoint.is_none() {
             return;
         }
         let new_checkpoint = Local::now();
-        self.stocked_results.push(format!(
-            "{}: {} ",
-            output_str,
-            output_duration(new_checkpoint - self.prev_checkpoint.unwrap())
-        ));
-        self.prev_checkpoint = Some(new_checkpoint);
+
+        let duration = new_checkpoint - self.prev_checkpoint.unwrap();
+        let s = duration.num_seconds();
+        let ms = duration.num_milliseconds() - 1000 * s;
+        if !self.stocked_results.is_empty()
+            && self.stocked_results[self.stocked_results.len() - 1].output_str == output_str
+        {
+            let stocked_last_idx = self.stocked_results.len() - 1;
+            self.stocked_results[stocked_last_idx].sec += s;
+            self.stocked_results[stocked_last_idx].msec += ms;
+        } else {
+            self.stocked_results.push(CheckPointTimeStore {
+                output_str: output_str.into(),
+                sec: s,
+                msec: ms,
+            });
+        }
+        self.prev_checkpoint = None;
     }
 
     /// ストックした結果を出力する関数
     pub fn output_stocked_result(&self) {
         for output in self.stocked_results.iter() {
-            println!("{output}");
+            println!(
+                "{}: {}",
+                output.output_str,
+                output_duration((output.sec, output.msec))
+            );
+        }
+    }
+
+    pub fn calculate_all_stocked_results(&self) -> String {
+        let mut s = 0;
+        let mut ms = 0;
+        for output in self.stocked_results.iter() {
+            s += output.sec;
+            ms += output.msec;
+        }
+        if let Some(prev_check) = self.prev_checkpoint {
+            let duration = Local::now() - prev_check;
+            s += duration.num_seconds();
+            ms += duration.num_milliseconds() - 1000 * duration.num_seconds();
         }
+        output_duration((s, ms))
     }
 }
 
 #[cfg(test)]
 mod tests {
-    use chrono::{DateTime, Local};
-    use nested::Nested;
+    use chrono::{DateTime, Local, TimeDelta};
 
     use crate::debug::checkpoint_process_timer::CheckPointProcessTimer;
 
@@ -67,21 +102,40 @@ mod tests {
     }
 
     #[test]
-    fn test_rap_check_point() {
+    fn test_rap_checkpoint() {
         let mut actual = CheckPointProcessTimer {
             prev_checkpoint: None,
-            stocked_results: Nested::<String>::new(),
+            stocked_results: Vec::new(),
         };
-        actual.rap_check_point("Test");
+        actual.rap_checkpoint("Test");
         let now: DateTime<Local> = Local::now();
         actual.set_checkpoint(now);
-        actual.rap_check_point("Test2");
-
+        actual.rap_checkpoint("Test2");
+        actual.set_checkpoint(Local::now());
         assert!(actual.prev_checkpoint.is_some());
         assert_eq!(actual.stocked_results.len(), 1);
-        assert!(actual.stocked_results[0].starts_with("Test2:"));
+        assert!(actual.stocked_results[0].output_str == "Test2");
         assert_ne!(actual.prev_checkpoint.unwrap(), now);
 
         actual.output_stocked_result();
     }
+
+    #[test]
+    fn test_calculate_all_stocked_results() {
+        let now = Local::now();
+        let mut actual = CheckPointProcessTimer {
+            prev_checkpoint: Some(now),
+            stocked_results: Vec::new(),
+        };
+        actual.rap_checkpoint("Test");
+        actual.set_checkpoint(now.checked_add_signed(TimeDelta::seconds(1)).unwrap());
+        actual.rap_checkpoint("Test2");
+        actual.set_checkpoint(now.checked_add_signed(TimeDelta::seconds(1)).unwrap());
+        assert!(actual.prev_checkpoint.is_some());
+        assert_eq!(actual.stocked_results.len(), 2);
+        assert!(actual.stocked_results[0].output_str == "Test");
+        assert_ne!(actual.prev_checkpoint.unwrap(), now);
+
+        actual.calculate_all_stocked_results();
+    }
 }

src/detections/utils.rs

@@ -12,7 +12,7 @@ use nested::Nested;
 use std::path::{Path, PathBuf};
 use std::thread::available_parallelism;
 
-use chrono::{Duration, Local};
+use chrono::Local;
 use termcolor::{Color, ColorChoice};
 
 use tokio::runtime::{Builder, Runtime};
@@ -694,10 +694,8 @@ pub fn is_filtered_by_computer_name(
     false
 }
 
-///Durationから出力文字列を作成する関数。絶対値での秒数から算出してhh:mm:ss.fffの形式で出力する。
-pub fn output_duration(d: Duration) -> String {
-    let mut s = d.num_seconds();
-    let mut ms = d.num_milliseconds() - 1000 * s;
+///指定された秒数とミリ秒数から出力文字列を作成する関数。絶対値での秒数から算出してhh:mm:ss.fffの形式で出力する。
+pub fn output_duration((mut s, mut ms): (i64, i64)) -> String {
     if s < 0 {
         s = -s;
         ms = -ms;
@@ -1164,7 +1162,15 @@ mod tests {
             .unwrap()
             .and_hms_milli_opt(1, 23, 45, 678)
             .unwrap();
-        assert_eq!(output_duration(time1 - time2), "25:11:03.322".to_string());
-        assert_eq!(output_duration(time2 - time1), "25:11:03.322".to_string());
+        let duration = time1 - time2;
+        let s = duration.num_seconds();
+        let ms = duration.num_milliseconds() - 1000 * s;
+
+        assert_eq!(output_duration((s, ms)), "25:11:03.322".to_string());
+
+        let duration = time2 - time1;
+        let s = duration.num_seconds();
+        let ms = duration.num_milliseconds() - 1000 * s;
+        assert_eq!(output_duration((s, ms)), "25:11:03.322".to_string());
     }
 }

src/main.rs

@@ -24,8 +24,7 @@ use hayabusa::detections::message::{AlertMessage, DetectInfo, ERROR_LOG_STACK};
 use hayabusa::detections::rule::{get_detection_keys, RuleNode};
 use hayabusa::detections::utils;
 use hayabusa::detections::utils::{
-    check_setting_path, get_writable_color, output_and_data_stack_for_html, output_duration,
-    output_profile_name,
+    check_setting_path, get_writable_color, output_and_data_stack_for_html, output_profile_name,
 };
 use hayabusa::options::htmlreport::{self, HTML_REPORTER};
 use hayabusa::options::pivot::create_output;
@@ -721,9 +720,14 @@ impl App {
         }
 
         // 処理時間の出力
-        let analysis_end_time: DateTime<Local> = Local::now();
-        let analysis_duration = analysis_end_time.signed_duration_since(analysis_start_time);
-        let elapsed_output_str = format!("Elapsed time: {}", output_duration(analysis_duration));
+        let elapsed_output_str = format!(
+            "Elapsed time: {}",
+            CHECKPOINT
+                .lock()
+                .as_mut()
+                .unwrap()
+                .calculate_all_stocked_results()
+        );
         output_and_data_stack_for_html(
             &elapsed_output_str,
             "General Overview {#general_overview}",
@@ -1023,6 +1027,11 @@ impl App {
             || stored_static.computer_metrics_flag
             || stored_static.output_option.as_ref().unwrap().no_wizard)
         {
+            CHECKPOINT
+                .lock()
+                .as_mut()
+                .unwrap()
+                .rap_checkpoint("Rule Parse Processing Time");
             let mut rule_counter_wizard_map = HashMap::new();
             yaml::count_rules(
                 &stored_static.output_option.as_ref().unwrap().rules,
@@ -1268,6 +1277,12 @@ impl App {
                 }
             }
 
+            CHECKPOINT
+                .lock()
+                .as_mut()
+                .unwrap()
+                .set_checkpoint(Local::now());
+
             if let Some(noisy_cnt) = exclude_noisy_cnt.get("noisy") {
                 // noisy rules load prompt
                 let prompt_fmt = format!("Include noisy rules? ({} rules)", noisy_cnt);
@@ -1375,7 +1390,12 @@ impl App {
                 .lock()
                 .as_mut()
                 .unwrap()
-                .rap_check_point("Rule Parse Processing Time");
+                .rap_checkpoint("Rule Parse Processing Time");
+            CHECKPOINT
+                .lock()
+                .as_mut()
+                .unwrap()
+                .set_checkpoint(Local::now());
             let unused_rules_option = stored_static.logon_summary_flag
                 || stored_static.search_flag
                 || stored_static.computer_metrics_flag
@@ -1461,7 +1481,13 @@ impl App {
             .lock()
             .as_mut()
             .unwrap()
-            .rap_check_point("Analysis Processing Time");
+            .rap_checkpoint("Analysis Processing Time");
+        CHECKPOINT
+            .lock()
+            .as_mut()
+            .unwrap()
+            .set_checkpoint(Local::now());
+
         if stored_static.metrics_flag {
             tl.tm_stats_dsp_msg(event_timeline_config, stored_static);
         } else if stored_static.logon_summary_flag {
@@ -1514,7 +1540,12 @@ impl App {
             .lock()
             .as_mut()
             .unwrap()
-            .rap_check_point("Output Processing Time");
+            .rap_checkpoint("Output Processing Time");
+        CHECKPOINT
+            .lock()
+            .as_mut()
+            .unwrap()
+            .set_checkpoint(Local::now());
     }
 
     // Windowsイベントログファイルを1ファイル分解析する。

src/timeline/computer_metrics.rs

@@ -207,7 +207,7 @@ mod tests {
 
         let header = ["\"Computer\"", "\"Events\""];
 
-        let expect = vec![vec!["\"FALCON\"", "1"], vec!["\"HAYABUSA-DESKTOP\"", "1"]];
+        let expect = [vec!["\"FALCON\"", "1"], vec!["\"HAYABUSA-DESKTOP\"", "1"]];
         let expect_str =
             header.join(",") + "\n" + &expect.join(&"\n").join(",").replace(",\n,", "\n") + "\n";
         match read_to_string("./test_computer_metrics.csv") {

src/timeline/timelines.rs

@@ -785,7 +785,7 @@ mod tests {
             &dummy_stored_static,
         );
         // Event column is defined in rules/config/channel_eid_info.txt
-        let expect_records = vec![vec!["1", "100.0%", "Sec", "4625", "Logon failure"]];
+        let expect_records = [["1", "100.0%", "Sec", "4625", "Logon failure"]];
         let expect = "Total,%,Channel,ID,Event\n".to_owned()
             + &expect_records.join(&"\n").join(",").replace(",\n,", "\n")
             + "\n";
@@ -909,7 +909,7 @@ mod tests {
         ];
 
         // Login Successful csv output test
-        let expect_success_records = vec![vec![
+        let expect_success_records = [[
             "1",
             "testuser",
             "HAYABUSA-DESKTOP",
@@ -933,7 +933,7 @@ mod tests {
 
         // Login Failed csv output test
         header[0] = "Failed";
-        let expect_failed_records = vec![vec![
+        let expect_failed_records = [[
             "1",
             "testuser",
             "HAYABUSA-DESKTOP",