add logging functionality for aligning key value pairs after message (#461)

* add logging functionality for aligning key value pairs after the main messages

* move to own crate, change default message width to 40

* use FullFormat in validator_client (CompactFormat is not compatible with aligning)

* move logging to eth2/utils/logging

Cargo.toml

@@ -10,6 +10,7 @@ members = [
 	"eth2/utils/compare_fields_derive",
 	"eth2/utils/eth2_config",
 	"eth2/utils/hashing",
+	"eth2/utils/logging",
 	"eth2/utils/merkle_proof",
 	"eth2/utils/int_to_bytes",
 	"eth2/utils/serde_hex",

beacon_node/Cargo.toml

@@ -21,3 +21,4 @@ futures = "0.1.25"
 exit-future = "0.1.3"
 env_logger = "0.6.1"
 dirs = "2.0.1"
+logging = { path = "../eth2/utils/logging" }

beacon_node/src/main.rs

@@ -173,6 +173,7 @@ fn main() {
 
     // build the initial logger
     let decorator = slog_term::TermDecorator::new().build();
+    let decorator = logging::AlignedTermDecorator::new(decorator, logging::MAX_MESSAGE_WIDTH);
     let drain = slog_term::FullFormat::new(decorator).build().fuse();
     let drain = slog_async::Async::new(drain).build();
 

eth2/utils/logging/Cargo.toml

@@ -0,0 +1,9 @@
+[package]
+name = "logging"
+version = "0.1.0"
+authors = ["blacktemplar <blacktemplar@a1.net>"]
+edition = "2018"
+
+[dependencies]
+slog = { version = "^2.2.3" }
+slog-term = "^2.4.0"

eth2/utils/logging/src/lib.rs

@@ -0,0 +1,122 @@
+use std::io::{Write, Result};
+
+pub const MAX_MESSAGE_WIDTH: usize = 40;
+
+pub struct AlignedTermDecorator {
+    wrapped: slog_term::TermDecorator,
+    message_width: usize,
+}
+
+impl AlignedTermDecorator {
+    pub fn new(decorator: slog_term::TermDecorator, message_width: usize) -> AlignedTermDecorator {
+        AlignedTermDecorator {
+            wrapped: decorator,
+            message_width,
+        }
+    }
+}
+
+impl slog_term::Decorator for AlignedTermDecorator {
+    fn with_record<F>(&self, _record: &slog::Record, _logger_values: &slog::OwnedKVList, f: F)
+                      -> Result<()> where
+        F: FnOnce(&mut dyn slog_term::RecordDecorator) -> std::io::Result<()> {
+        self.wrapped.with_record(_record, _logger_values, |deco| {
+            f(&mut AlignedRecordDecorator::new(deco, self.message_width))
+        })
+    }
+}
+
+struct AlignedRecordDecorator<'a> {
+    wrapped: &'a mut dyn slog_term::RecordDecorator,
+    message_count: usize,
+    message_active: bool,
+    ignore_comma: bool,
+    message_width: usize,
+}
+
+impl<'a> AlignedRecordDecorator<'a> {
+    fn new(decorator: &'a mut dyn slog_term::RecordDecorator, message_width: usize) ->
+    AlignedRecordDecorator<'a> {
+        AlignedRecordDecorator {
+            wrapped: decorator,
+            message_count: 0,
+            ignore_comma: false,
+            message_active: false,
+            message_width,
+        }
+    }
+}
+
+impl<'a> Write for AlignedRecordDecorator<'a> {
+    fn write(&mut self, buf: &[u8]) -> Result<usize> {
+        if self.ignore_comma {
+            //don't write comma
+            self.ignore_comma = false;
+            Ok(buf.len())
+        } else if self.message_active {
+            self.wrapped.write(buf).map(|n| {
+                self.message_count += n;
+                n
+            })
+        } else {
+            self.wrapped.write(buf)
+        }
+    }
+
+    fn flush(&mut self) -> Result<()> {
+        self.wrapped.flush()
+    }
+}
+
+impl<'a> slog_term::RecordDecorator for AlignedRecordDecorator<'a> {
+    fn reset(&mut self) -> Result<()> {
+        self.message_active = false;
+        self.message_count = 0;
+        self.ignore_comma = false;
+        self.wrapped.reset()
+    }
+
+    fn start_whitespace(&mut self) -> Result<()> {
+        self.wrapped.start_whitespace()
+    }
+
+    fn start_msg(&mut self) -> Result<()> {
+        self.message_active = true;
+        self.ignore_comma = false;
+        self.wrapped.start_msg()
+    }
+
+    fn start_timestamp(&mut self) -> Result<()> {
+        self.wrapped.start_timestamp()
+    }
+
+    fn start_level(&mut self) -> Result<()> {
+        self.wrapped.start_level()
+    }
+
+    fn start_comma(&mut self) -> Result<()> {
+        if self.message_active && self.message_count + 1 < self.message_width {
+            self.ignore_comma = true;
+        }
+        self.wrapped.start_comma()
+    }
+
+    fn start_key(&mut self) -> Result<()> {
+        if self.message_active && self.message_count + 1 < self.message_width {
+            write!(self, "{}", std::iter::repeat(' ').take(self.message_width - self.message_count)
+                .collect::<String>())?;
+            self.message_active = false;
+            self.message_count = 0;
+            self.ignore_comma = false;
+        }
+        self.wrapped.start_key()
+    }
+
+    fn start_value(&mut self) -> Result<()> {
+        self.wrapped.start_value()
+    }
+
+    fn start_separator(&mut self) -> Result<()> {
+        self.wrapped.start_separator()
+    }
+}

validator_client/Cargo.toml

@@ -34,3 +34,4 @@ error-chain = "0.12.0"
 bincode = "^1.1.2"
 futures = "0.1.25"
 dirs = "2.0.1"
+logging = { path = "../eth2/utils/logging" }

validator_client/src/main.rs

@@ -24,7 +24,8 @@ pub const ETH2_CONFIG_FILENAME: &str = "eth2-spec.toml";
 fn main() {
     // Logging
     let decorator = slog_term::TermDecorator::new().build();
-    let drain = slog_term::CompactFormat::new(decorator).build().fuse();
+    let decorator = logging::AlignedTermDecorator::new(decorator, logging::MAX_MESSAGE_WIDTH);
+    let drain = slog_term::FullFormat::new(decorator).build().fuse();
     let drain = slog_async::Async::new(drain).build().fuse();
 
     // CLI