Logger refactor: better structured logs and colored logs

- Refactor the Logger with the new more powerful macro prompt_log
- Explicitely take ownership of RequestRecord fields in access log
  macros, the user can decide the best  way to pass them
- Add logger specific fields in the RequestRecord
- Add basic colors to logs and access logs, configurable in the condig,
  checked at runtime
- Cache the Logger::enabled result at call site

Signed-off-by: Eloi DEMOLIS <eloi.demolis@clever-cloud.com>

bin/src/command/server.rs

@@ -295,7 +295,7 @@ impl CommandHub {
     /// - manage timeouts of tasks
     pub fn run(&mut self) {
         let mut events = Events::with_capacity(100);
-        debug!("running the command hub: {:?}", self);
+        debug!("running the command hub: {:#?}", self);
 
         loop {
             let run_state = self.run_state;
@@ -511,7 +511,6 @@ pub enum ServerState {
 /// - scatter to workers
 /// - gather worker responses
 /// - trigger a finishing function when all responses are gathered
-#[derive(Debug)]
 pub struct Server {
     pub config: Config,
     /// Sōzu clients that subscribed to events
@@ -857,3 +856,23 @@ impl Server {
         }
     }
 }
+
+impl std::fmt::Debug for Server {
+    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
+        f.debug_struct("Server")
+            .field("config", &self.config)
+            .field("event_subscribers", &self.event_subscribers)
+            .field("executable_path", &self.executable_path)
+            .field("in_flight", &self.in_flight)
+            .field("next_client_id", &self.next_client_id)
+            .field("next_session_id", &self.next_session_id)
+            .field("next_task_id", &self.next_task_id)
+            .field("next_worker_id", &self.next_worker_id)
+            .field("poll", &self.poll)
+            .field("queued_tasks", &self.queued_tasks)
+            .field("run_state", &self.run_state)
+            .field("unix_listener", &self.unix_listener)
+            .field("workers", &self.workers)
+            .finish()
+    }
+}

bin/src/worker.rs

@@ -115,8 +115,10 @@ pub fn begin_worker_process(
     // do not try to log anything before this, or the logger will panic
     setup_logging(
         &worker_config.log_target,
+        worker_config.log_colored,
         worker_config.log_access_target.as_deref(),
         Some(access_log_format),
+        Some(worker_config.log_colored),
         &worker_config.log_level,
         &worker_id,
     );

command/src/access_logs.rs

@@ -3,7 +3,12 @@ use std::{collections::BTreeMap, mem::ManuallyDrop, net::SocketAddr};
 use rusty_ulid::Ulid;
 use time::Duration;
 
-use crate::proto::command::{ProtobufAccessLog, ProtobufEndpoint, TcpEndpoint, Uint128};
+use crate::{
+    logging::{LogLevel, Rfc3339Time},
+    proto::command::{
+        protobuf_endpoint, HttpEndpoint, ProtobufAccessLog, ProtobufEndpoint, TcpEndpoint, Uint128,
+    },
+};
 
 /// This uses unsafe to creates a "fake" owner of the underlying data.
 /// Beware that for the compiler it is as legitimate as the original owner.
@@ -97,37 +102,52 @@ impl CachedTags {
     }
 }
 
+#[derive(Debug)]
+pub struct FullTags<'a> {
+    pub concatenated: Option<&'a str>,
+    pub user_agent: Option<&'a str>,
+}
+
 /// Intermediate representation of an access log agnostic of the final format.
 /// Every field is a reference to avoid capturing ownership (as a logger should).
 pub struct RequestRecord<'a> {
-    pub error: &'a Option<&'a str>,
-    pub context: &'a LogContext<'a>,
-    pub session_address: &'a Option<SocketAddr>,
-    pub backend_address: &'a Option<SocketAddr>,
+    pub error: Option<&'a str>,
+    pub context: LogContext<'a>,
+    pub session_address: Option<SocketAddr>,
+    pub backend_address: Option<SocketAddr>,
     pub protocol: &'a str,
-    pub endpoint: &'a EndpointRecord<'a>,
-    pub tags: &'a Option<&'a CachedTags>,
-    pub client_rtt: &'a Option<Duration>,
-    pub server_rtt: &'a Option<Duration>,
-    pub user_agent: &'a Option<String>,
-    pub service_time: &'a Duration,
-    pub response_time: &'a Duration,
-    pub bytes_in: &'a usize,
-    pub bytes_out: &'a usize,
+    pub endpoint: EndpointRecord<'a>,
+    pub tags: Option<&'a CachedTags>,
+    pub client_rtt: Option<Duration>,
+    pub server_rtt: Option<Duration>,
+    pub user_agent: Option<&'a str>,
+    pub service_time: Duration,
+    pub response_time: Duration,
+    pub bytes_in: usize,
+    pub bytes_out: usize,
+
+    // added by the logger itself
+    pub pid: i32,
+    pub tag: &'a str,
+    pub level: LogLevel,
+    pub now: Rfc3339Time,
+    pub precise_time: i128,
 }
 
 impl RequestRecord<'_> {
+    pub fn full_tags(&self) -> FullTags {
+        FullTags {
+            concatenated: self.tags.as_ref().map(|t| t.concatenated.as_str()),
+            user_agent: self.user_agent,
+        }
+    }
+
     /// Converts the RequestRecord in its protobuf representation.
     /// Prost needs ownership over all the fields but we don't want to take it from the user
     /// or clone them, so we use the unsafe DuplicateOwnership.
-    pub unsafe fn into_protobuf_access_log(
-        self,
-        time: i128,
-        tag: &str,
-    ) -> ManuallyDrop<ProtobufAccessLog> {
+    pub unsafe fn into_binary_access_log(self) -> ManuallyDrop<ProtobufAccessLog> {
         let (low, high) = self.context.request_id.into();
         let request_id = Uint128 { low, high };
-        let time: Uint128 = time.into();
 
         let endpoint = match self.endpoint {
             EndpointRecord::Http {
@@ -136,33 +156,29 @@ impl RequestRecord<'_> {
                 path,
                 status,
                 reason,
-            } => crate::proto::command::protobuf_endpoint::Inner::Http(
-                crate::proto::command::HttpEndpoint {
-                    method: method.duplicate().duplicate(),
-                    authority: authority.duplicate().duplicate(),
-                    path: path.duplicate().duplicate(),
-                    status: status.map(|s| s as u32),
-                    reason: reason.duplicate().duplicate(),
-                },
-            ),
-            EndpointRecord::Tcp { context } => {
-                crate::proto::command::protobuf_endpoint::Inner::Tcp(TcpEndpoint {
-                    context: context.duplicate().duplicate(),
-                })
-            }
+            } => protobuf_endpoint::Inner::Http(HttpEndpoint {
+                method: method.duplicate(),
+                authority: authority.duplicate(),
+                path: path.duplicate(),
+                status: status.map(|s| s as u32),
+                reason: reason.duplicate(),
+            }),
+            EndpointRecord::Tcp { context } => protobuf_endpoint::Inner::Tcp(TcpEndpoint {
+                context: context.duplicate(),
+            }),
         };
 
         ManuallyDrop::new(ProtobufAccessLog {
             backend_address: self.backend_address.map(Into::into),
             backend_id: self.context.backend_id.duplicate(),
-            bytes_in: *self.bytes_in as u64,
-            bytes_out: *self.bytes_out as u64,
+            bytes_in: self.bytes_in as u64,
+            bytes_out: self.bytes_out as u64,
             client_rtt: self.client_rtt.map(|t| t.whole_microseconds() as u64),
             cluster_id: self.context.cluster_id.duplicate(),
             endpoint: ProtobufEndpoint {
                 inner: Some(endpoint),
             },
-            error: self.error.duplicate().duplicate(),
+            error: self.error.duplicate(),
             protocol: self.protocol.duplicate(),
             request_id,
             response_time: self.response_time.whole_microseconds() as u64,
@@ -174,8 +190,8 @@ impl RequestRecord<'_> {
                 .map(|tags| tags.tags.duplicate())
                 .unwrap_or_default(),
             user_agent: self.user_agent.duplicate(),
-            tag: tag.duplicate(),
-            time: time.duplicate(),
+            tag: self.tag.duplicate(),
+            time: self.precise_time.into(),
         })
     }
 }

command/src/command.proto

@@ -151,7 +151,7 @@ message HttpsListenerConfig {
     required uint32 request_timeout = 10 [default = 10];
     // wether the listener is actively listening on its socket
     required bool active = 11 [default = false];
-    // TLS versions
+    // TLS versions
     repeated TlsVersion versions = 12;
     repeated string cipher_list = 13;
     repeated string cipher_suites = 14;
@@ -306,7 +306,7 @@ message CertificateAndKey {
 message QueryCertificatesFilters {
     // a domain name to filter certificate results
     optional string domain = 1;
-    // a hex-encoded fingerprint of the TLS certificate to find
+    // a hex-encoded fingerprint of the TLS certificate to find
     optional string fingerprint = 2;
 }
 
@@ -612,7 +612,7 @@ message RequestCounts {
 }
 
 // matches std::net::SocketAddr in the Rust library
-// beware that the ports are expressed with uint32 here,
+// beware that the ports are expressed with uint32 here,
 // but they should NOT exceed uint16 value
 message SocketAddress {
     required IpAddress ip = 1;
@@ -675,6 +675,7 @@ message ServerConfig {
     required uint64 max_command_buffer_size = 14 [default = 2000000];
     optional ServerMetricsConfig metrics = 15;
     required ProtobufAccessLogFormat access_log_format = 16;
+    required bool log_colored = 17;
 }
 
 enum ProtobufAccessLogFormat {

command/src/config.rs

@@ -1091,8 +1091,13 @@ pub struct FileConfig {
     pub log_level: Option<String>,
     pub log_target: Option<String>,
     #[serde(default)]
+    pub log_colored: bool,
+    #[serde(default)]
     pub log_access_target: Option<String>,
+    #[serde(default)]
     pub log_access_format: Option<AccessLogFormat>,
+    #[serde(default)]
+    pub log_access_colored: Option<bool>,
     pub worker_count: Option<u16>,
     pub worker_automatic_restart: Option<bool>,
     pub metrics: Option<MetricsConfig>,
@@ -1205,6 +1210,7 @@ impl ConfigBuilder {
             handle_process_affinity: file_config.handle_process_affinity.unwrap_or(false),
             log_access_target: file_config.log_access_target.clone(),
             log_access_format: file_config.log_access_format.clone(),
+            log_access_colored: file_config.log_access_colored,
             log_level: file_config
                 .log_level
                 .clone()
@@ -1213,6 +1219,7 @@ impl ConfigBuilder {
                 .log_target
                 .clone()
                 .unwrap_or_else(|| String::from("stdout")),
+            log_colored: file_config.log_colored,
             max_buffers: file_config.max_buffers.unwrap_or(DEFAULT_MAX_BUFFERS),
             max_command_buffer_size: file_config
                 .max_command_buffer_size
@@ -1434,7 +1441,7 @@ impl ConfigBuilder {
 /// Sōzu configuration, populated with clusters and listeners.
 ///
 /// This struct is used on startup to generate `WorkerRequest`s
-#[derive(Debug, Clone, PartialEq, Eq, Serialize, Default, Deserialize)]
+#[derive(Clone, PartialEq, Eq, Serialize, Default, Deserialize)]
 pub struct Config {
     pub config_path: String,
     pub command_socket: String,
@@ -1449,9 +1456,11 @@ pub struct Config {
     pub automatic_state_save: bool,
     pub log_level: String,
     pub log_target: String,
+    pub log_colored: bool,
     #[serde(default)]
     pub log_access_target: Option<String>,
     pub log_access_format: Option<AccessLogFormat>,
+    pub log_access_colored: Option<bool>,
     pub worker_count: u16,
     pub worker_automatic_restart: bool,
     pub metrics: Option<MetricsConfig>,
@@ -1783,7 +1792,7 @@ impl From<&Config> for ServerConfig {
             max_command_buffer_size: config.max_command_buffer_size,
             metrics,
             access_log_format: ProtobufAccessLogFormat::from(&config.log_access_format) as i32,
-            // log_colored: config.log_colored,
+            log_colored: config.log_colored,
         }
     }
 }