Fixing indentation (#23)

* Fixing indentation, color, newlines etc in exceptions

* Fixing timing test

* Fixing timing test

* Fixing timing test

opencollector.yaml

@@ -27,7 +27,7 @@ exporters:
       stream-name: default
   # Writes all opentelemetry logs, traces, metrics to a file, useful for testing:
   file/debug_file_writing:
-    path: /home/runner/work/bitbazaar/bitbazaar/logs/otlp_telemetry_out.log
+    path: /Users/zak/z/code/bitbazaar/logs/otlp_telemetry_out.log
     rotation:
       max_megabytes: 10
       max_days: 3

rust/bitbazaar/log/global_log/event_formatter.rs

@@ -1,3 +1,4 @@
+use colored::Colorize;
 use tracing_core::Subscriber;
 use tracing_subscriber::{
     fmt::{format::Writer, FmtContext, FormatEvent, FormatFields},
@@ -57,40 +58,75 @@ where
         if is_exception {
             let mut visitor = ExceptionEventVisitor::default();
             event.record(&mut visitor);
-            if let Some(stacktrace) = visitor.stacktrace.as_ref() {
-                writeln!(writer, "{}", clean_string(stacktrace))?;
-            }
-            if let Some(typ) = visitor.typ.as_ref() {
-                if let Some(message) = visitor.message.as_ref() {
-                    writeln!(writer, "{}: {}", clean_string(typ), clean_string(message))?;
-                } else {
-                    writeln!(writer, "{}", clean_string(typ))?;
-                }
-            } else if let Some(message) = visitor.message.as_ref() {
-                writeln!(writer, "{}", clean_string(message))?;
+
+            let indent = 6;
+            writeln!(writer, "{}", "ERROR: ".red())?;
+
+            let msg = visitor.into_msg();
+            // Write each line and indent it by 7 to match the ERROR: prefix
+            for line in msg.lines() {
+                writeln!(writer, "{:indent$}{}", "", line.red())?;
             }
+
             Ok(())
         } else {
             self.inner.format_event(ctx, writer, event)
         }
     }
 }
 
-#[inline]
-/// Weirdly they seem to come in with quotes around them, this simple removes them.
-/// In a sep func to allow extending if needed.
-fn clean_string(s: &str) -> &str {
-    s.trim_matches('"')
-}
-
 #[derive(Default)]
 struct ExceptionEventVisitor {
     message: Option<String>,
     typ: Option<String>,
     stacktrace: Option<String>,
 }
 
+impl ExceptionEventVisitor {
+    fn into_msg(self) -> String {
+        let mut msg = String::new();
+        if let Some(stacktrace) = self.stacktrace {
+            msg.push_str(clean_string(&stacktrace));
+            msg.push('\n');
+        }
+        if let Some(typ) = self.typ {
+            if let Some(message) = self.message {
+                msg.push_str(&format!(
+                    "{}: {}\n",
+                    clean_string(&typ),
+                    clean_string(&message)
+                ));
+            } else {
+                msg.push_str(clean_string(&typ));
+                msg.push('\n');
+            }
+        } else if let Some(message) = self.message {
+            msg.push_str(clean_string(&message));
+            msg.push('\n');
+        }
+        msg
+    }
+}
+
+#[inline]
+/// Weirdly they seem to come in with quotes around them, this simple removes them.
+/// In a sep func to allow extending if needed.
+fn clean_string(s: &str) -> &str {
+    s.trim_matches('"')
+}
+
 impl tracing::field::Visit for ExceptionEventVisitor {
+    fn record_str(&mut self, field: &tracing_core::Field, value: &str) {
+        match field.name() {
+            "exception.message" => self.message = Some(value.to_string()),
+            "exception.type" => self.typ = Some(value.to_string()),
+            "exception.stacktrace" => self.stacktrace = Some(value.to_string()),
+            _ => {}
+        }
+    }
+
+    /// NOTE: record_str() is the one that's actually used, this would escape newlines etc.
+    /// But keeping as the trait requires it and just in case for some reason one of these isn't a string.
     fn record_debug(&mut self, field: &tracing_core::Field, value: &dyn std::fmt::Debug) {
         match field.name() {
             "exception.message" => self.message = Some(format!("{:?}", value)),

rust/bitbazaar/log/mod.rs

@@ -221,7 +221,7 @@ mod tests {
         let line_preceding_panic = AtomicU32::new(0);
         log.with_tmp_global(|| {
             // Manual record:
-            record_exception("test_exc", "test_stack");
+            record_exception("test_exc", "test_stack\nfoodle\nwoodle");
 
             // Panics should be auto recorded:
             let _ = std::panic::catch_unwind(|| {
@@ -239,14 +239,13 @@ mod tests {
                 line_preceding_panic.load(std::sync::atomic::Ordering::Relaxed) + 1
             ),
         ]
-        .join(if cfg!(windows) { "\\\\" } else { "/" });
-        assert_eq!(
-            out,
-            vec![
-                "test_stack\nErr: test_exc".to_string(),
-                format!("{}\nPanic: test_panic", exp_panic_loc)
-            ]
-        );
+        .join(if cfg!(windows) { "\\" } else { "/" });
+
+        assert_eq!(out.len(), 2, "{:?}", out);
+        assert!(out[0].contains("test_stack"), "{:?}", out[0]);
+        assert!(out[0].contains("Err: test_exc"), "{:?}", out[0]);
+        assert!(out[1].contains(&exp_panic_loc), "{:?}", out[1]);
+        assert!(out[1].contains("Panic: test_panic"), "{:?}", out[1]);
 
         Ok(())
     }

rust/bitbazaar/timing/mod.rs

@@ -62,12 +62,7 @@ mod tests {
 
         let elapsed = recorder.total_elapsed().unwrap();
         assert!(
-            elapsed.as_millis() >= 1,
-            "elapsed: {:?}",
-            elapsed.as_millis()
-        );
-        assert!(
-            elapsed.as_millis() < 2,
+            elapsed.as_millis() == 1 || elapsed.as_millis() == 2,
             "elapsed: {:?}",
             elapsed.as_millis()
         );
@@ -83,12 +78,7 @@ mod tests {
         });
         let elapsed = GLOBAL_TIME_RECORDER.total_elapsed().unwrap();
         assert!(
-            elapsed.as_millis() >= 1,
-            "elapsed: {:?}",
-            elapsed.as_millis()
-        );
-        assert!(
-            elapsed.as_millis() < 2,
+            elapsed.as_millis() == 1 || elapsed.as_millis() == 2,
             "elapsed: {:?}",
             elapsed.as_millis()
         );