Logging via the HTTP API (#4074)

This PR adds the ability to read the Lighthouse logs from the HTTP API for both the BN and the VC. 

This is done in such a way to as minimize any kind of performance hit by adding this feature.

The current design creates a tokio broadcast channel and mixes is into a form of slog drain that combines with our main global logger drain, only if the http api is enabled. 

The drain gets the logs, checks the log level and drops them if they are below INFO. If they are INFO or higher, it sends them via a broadcast channel only if there are users subscribed to the HTTP API channel. If not, it drops the logs. 

If there are more than one subscriber, the channel clones the log records and converts them to json in their independent HTTP API tasks. 

Co-authored-by: Michael Sproul <micsproul@gmail.com>

common/logging/Cargo.toml

@@ -10,6 +10,13 @@ test_logger = [] # Print log output to stderr when running tests instead of drop
 [dependencies]
 slog = "2.5.2"
 slog-term = "2.6.0"
+tokio = { version = "1.26.0", features = ["sync"] }
 lighthouse_metrics = { path = "../lighthouse_metrics" }
 lazy_static = "1.4.0"
 sloggers = { version = "2.1.1", features = ["json"] }
+slog-async = "2.7.0"
+take_mut = "0.2.2"
+parking_lot = "0.12.1"
+serde = "1.0.153" 
+serde_json = "1.0.94"
+chrono = "0.4.23"

common/logging/src/async_record.rs

@@ -0,0 +1,309 @@
+//! An object that can be used to pass through a channel and be cloned. It can therefore be used
+//! via the broadcast channel.
+
+use parking_lot::Mutex;
+use serde::ser::SerializeMap;
+use serde::serde_if_integer128;
+use serde::Serialize;
+use slog::{BorrowedKV, Key, Level, OwnedKVList, Record, RecordStatic, Serializer, SingleKV, KV};
+use std::cell::RefCell;
+use std::fmt;
+use std::fmt::Write;
+use std::sync::Arc;
+use take_mut::take;
+
+thread_local! {
+    static TL_BUF: RefCell<String> = RefCell::new(String::with_capacity(128))
+}
+
+/// Serialized record.
+#[derive(Clone)]
+pub struct AsyncRecord {
+    msg: String,
+    level: Level,
+    location: Box<slog::RecordLocation>,
+    tag: String,
+    logger_values: OwnedKVList,
+    kv: Arc<Mutex<dyn KV + Send>>,
+}
+
+impl AsyncRecord {
+    /// Serializes a `Record` and an `OwnedKVList`.
+    pub fn from(record: &Record, logger_values: &OwnedKVList) -> Self {
+        let mut ser = ToSendSerializer::new();
+        record
+            .kv()
+            .serialize(record, &mut ser)
+            .expect("`ToSendSerializer` can't fail");
+
+        AsyncRecord {
+            msg: fmt::format(*record.msg()),
+            level: record.level(),
+            location: Box::new(*record.location()),
+            tag: String::from(record.tag()),
+            logger_values: logger_values.clone(),
+            kv: Arc::new(Mutex::new(ser.finish())),
+        }
+    }
+
+    pub fn to_json_string(&self) -> Result<String, String> {
+        serde_json::to_string(&self).map_err(|e| format!("{:?}", e))
+    }
+}
+
+pub struct ToSendSerializer {
+    kv: Box<dyn KV + Send>,
+}
+
+impl ToSendSerializer {
+    fn new() -> Self {
+        ToSendSerializer { kv: Box::new(()) }
+    }
+
+    fn finish(self) -> Box<dyn KV + Send> {
+        self.kv
+    }
+}
+
+impl Serializer for ToSendSerializer {
+    fn emit_bool(&mut self, key: Key, val: bool) -> slog::Result {
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    fn emit_unit(&mut self, key: Key) -> slog::Result {
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, ()))));
+        Ok(())
+    }
+    fn emit_none(&mut self, key: Key) -> slog::Result {
+        let val: Option<()> = None;
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    fn emit_char(&mut self, key: Key, val: char) -> slog::Result {
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    fn emit_u8(&mut self, key: Key, val: u8) -> slog::Result {
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    fn emit_i8(&mut self, key: Key, val: i8) -> slog::Result {
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    fn emit_u16(&mut self, key: Key, val: u16) -> slog::Result {
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    fn emit_i16(&mut self, key: Key, val: i16) -> slog::Result {
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    fn emit_u32(&mut self, key: Key, val: u32) -> slog::Result {
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    fn emit_i32(&mut self, key: Key, val: i32) -> slog::Result {
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    fn emit_f32(&mut self, key: Key, val: f32) -> slog::Result {
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    fn emit_u64(&mut self, key: Key, val: u64) -> slog::Result {
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    fn emit_i64(&mut self, key: Key, val: i64) -> slog::Result {
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    fn emit_f64(&mut self, key: Key, val: f64) -> slog::Result {
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    #[cfg(integer128)]
+    fn emit_u128(&mut self, key: Key, val: u128) -> slog::Result {
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    #[cfg(integer128)]
+    fn emit_i128(&mut self, key: Key, val: i128) -> slog::Result {
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    fn emit_usize(&mut self, key: Key, val: usize) -> slog::Result {
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    fn emit_isize(&mut self, key: Key, val: isize) -> slog::Result {
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    fn emit_str(&mut self, key: Key, val: &str) -> slog::Result {
+        let val = val.to_owned();
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+    fn emit_arguments(&mut self, key: Key, val: &fmt::Arguments) -> slog::Result {
+        let val = fmt::format(*val);
+        take(&mut self.kv, |kv| Box::new((kv, SingleKV(key, val))));
+        Ok(())
+    }
+}
+
+impl Serialize for AsyncRecord {
+    fn serialize<S>(&self, serializer: S) -> Result<S::Ok, S::Error>
+    where
+        S: serde::Serializer,
+    {
+        // Get the current time
+        let dt = chrono::Local::now().format("%b %e %T").to_string();
+
+        let rs = RecordStatic {
+            location: &self.location,
+            level: self.level,
+            tag: &self.tag,
+        };
+        let mut map_serializer = SerdeSerializer::new(serializer)?;
+
+        // Serialize the time and log level first
+        map_serializer.serialize_entry("time", &dt)?;
+        map_serializer.serialize_entry("level", self.level.as_short_str())?;
+
+        let kv = self.kv.lock();
+
+        // Convoluted pattern to avoid binding `format_args!` to a temporary.
+        // See: https://stackoverflow.com/questions/56304313/cannot-use-format-args-due-to-temporary-value-is-freed-at-the-end-of-this-state
+        let mut f = |msg: std::fmt::Arguments| {
+            map_serializer.serialize_entry("msg", &msg.to_string())?;
+
+            let record = Record::new(&rs, &msg, BorrowedKV(&(*kv)));
+            self.logger_values
+                .serialize(&record, &mut map_serializer)
+                .map_err(serde::ser::Error::custom)?;
+            record
+                .kv()
+                .serialize(&record, &mut map_serializer)
+                .map_err(serde::ser::Error::custom)
+        };
+        f(format_args!("{}", self.msg))?;
+        map_serializer.end()
+    }
+}
+
+struct SerdeSerializer<S: serde::Serializer> {
+    /// Current state of map serializing: `serde::Serializer::MapState`
+    ser_map: S::SerializeMap,
+}
+
+impl<S: serde::Serializer> SerdeSerializer<S> {
+    fn new(ser: S) -> Result<Self, S::Error> {
+        let ser_map = ser.serialize_map(None)?;
+        Ok(SerdeSerializer { ser_map })
+    }
+
+    fn serialize_entry<K, V>(&mut self, key: K, value: V) -> Result<(), S::Error>
+    where
+        K: serde::Serialize,
+        V: serde::Serialize,
+    {
+        self.ser_map.serialize_entry(&key, &value)
+    }
+
+    /// Finish serialization, and return the serializer
+    fn end(self) -> Result<S::Ok, S::Error> {
+        self.ser_map.end()
+    }
+}
+
+// NOTE: This is borrowed from slog_json
+macro_rules! impl_m(
+    ($s:expr, $key:expr, $val:expr) => ({
+        let k_s:  &str = $key.as_ref();
+        $s.ser_map.serialize_entry(k_s, $val)
+             .map_err(|e| std::io::Error::new(std::io::ErrorKind::Other, format!("serde serialization error: {}", e)))?;
+        Ok(())
+    });
+);
+
+impl<S> slog::Serializer for SerdeSerializer<S>
+where
+    S: serde::Serializer,
+{
+    fn emit_bool(&mut self, key: Key, val: bool) -> slog::Result {
+        impl_m!(self, key, &val)
+    }
+
+    fn emit_unit(&mut self, key: Key) -> slog::Result {
+        impl_m!(self, key, &())
+    }
+
+    fn emit_char(&mut self, key: Key, val: char) -> slog::Result {
+        impl_m!(self, key, &val)
+    }
+
+    fn emit_none(&mut self, key: Key) -> slog::Result {
+        let val: Option<()> = None;
+        impl_m!(self, key, &val)
+    }
+    fn emit_u8(&mut self, key: Key, val: u8) -> slog::Result {
+        impl_m!(self, key, &val)
+    }
+    fn emit_i8(&mut self, key: Key, val: i8) -> slog::Result {
+        impl_m!(self, key, &val)
+    }
+    fn emit_u16(&mut self, key: Key, val: u16) -> slog::Result {
+        impl_m!(self, key, &val)
+    }
+    fn emit_i16(&mut self, key: Key, val: i16) -> slog::Result {
+        impl_m!(self, key, &val)
+    }
+    fn emit_usize(&mut self, key: Key, val: usize) -> slog::Result {
+        impl_m!(self, key, &val)
+    }
+    fn emit_isize(&mut self, key: Key, val: isize) -> slog::Result {
+        impl_m!(self, key, &val)
+    }
+    fn emit_u32(&mut self, key: Key, val: u32) -> slog::Result {
+        impl_m!(self, key, &val)
+    }
+    fn emit_i32(&mut self, key: Key, val: i32) -> slog::Result {
+        impl_m!(self, key, &val)
+    }
+    fn emit_f32(&mut self, key: Key, val: f32) -> slog::Result {
+        impl_m!(self, key, &val)
+    }
+    fn emit_u64(&mut self, key: Key, val: u64) -> slog::Result {
+        impl_m!(self, key, &val)
+    }
+    fn emit_i64(&mut self, key: Key, val: i64) -> slog::Result {
+        impl_m!(self, key, &val)
+    }
+    fn emit_f64(&mut self, key: Key, val: f64) -> slog::Result {
+        impl_m!(self, key, &val)
+    }
+    serde_if_integer128! {
+        fn emit_u128(&mut self, key: Key, val: u128) -> slog::Result {
+            impl_m!(self, key, &val)
+        }
+        fn emit_i128(&mut self, key: Key, val: i128) -> slog::Result {
+            impl_m!(self, key, &val)
+        }
+    }
+    fn emit_str(&mut self, key: Key, val: &str) -> slog::Result {
+        impl_m!(self, key, &val)
+    }
+    fn emit_arguments(&mut self, key: Key, val: &fmt::Arguments) -> slog::Result {
+        TL_BUF.with(|buf| {
+            let mut buf = buf.borrow_mut();
+
+            buf.write_fmt(*val).unwrap();
+
+            let res = { || impl_m!(self, key, &*buf) }();
+            buf.clear();
+            res
+        })
+    }
+}

common/logging/src/lib.rs

@@ -11,6 +11,10 @@ use std::time::{Duration, Instant};
 
 pub const MAX_MESSAGE_WIDTH: usize = 40;
 
+pub mod async_record;
+mod sse_logging_components;
+pub use sse_logging_components::SSELoggingComponents;
+
 /// The minimum interval between log messages indicating that a queue is full.
 const LOG_DEBOUNCE_INTERVAL: Duration = Duration::from_secs(30);
 

common/logging/src/sse_logging_components.rs

@@ -0,0 +1,46 @@
+//! This module provides an implementation of `slog::Drain` that optionally writes to a channel if
+//! there are subscribers to a HTTP SSE stream.
+
+use crate::async_record::AsyncRecord;
+use slog::{Drain, OwnedKVList, Record};
+use std::panic::AssertUnwindSafe;
+use std::sync::Arc;
+use tokio::sync::broadcast::Sender;
+
+/// Default log level for SSE Events.
+// NOTE: Made this a constant. Debug level seems to be pretty intense. Can make this
+// configurable later if needed.
+const LOG_LEVEL: slog::Level = slog::Level::Info;
+
+/// The components required in the HTTP API task to receive logged events.
+#[derive(Clone)]
+pub struct SSELoggingComponents {
+    /// The channel to receive events from.
+    pub sender: Arc<AssertUnwindSafe<Sender<AsyncRecord>>>,
+}
+
+impl SSELoggingComponents {
+    /// Create a new SSE drain.
+    pub fn new(channel_size: usize) -> Self {
+        let (sender, _receiver) = tokio::sync::broadcast::channel(channel_size);
+
+        let sender = Arc::new(AssertUnwindSafe(sender));
+        SSELoggingComponents { sender }
+    }
+}
+
+impl Drain for SSELoggingComponents {
+    type Ok = ();
+    type Err = &'static str;
+
+    fn log(&self, record: &Record, logger_values: &OwnedKVList) -> Result<Self::Ok, Self::Err> {
+        if record.level().is_at_least(LOG_LEVEL) {
+            // Attempt to send the logs
+            match self.sender.send(AsyncRecord::from(record, logger_values)) {
+                Ok(_num_sent) => {} // Everything got sent
+                Err(_err) => {}     // There are no subscribers, do nothing
+            }
+        }
+        Ok(())
+    }
+}