From e07964fd128c84d9e17dac571bb7f8d02dfa9121 Mon Sep 17 00:00:00 2001 From: Eloi DEMOLIS Date: Wed, 21 Feb 2024 15:11:46 +0100 Subject: [PATCH] Edit access logs ASCII format, put logs-cache under feature Signed-off-by: Eloi DEMOLIS --- bin/src/command/server.rs | 6 +- command/Cargo.toml | 1 + command/src/logging/access_logs.rs | 88 +++++++++++++++--------------- command/src/logging/display.rs | 16 ++---- command/src/logging/logs.rs | 51 +++++++++++------ command/src/response.rs | 2 +- lib/src/tls.rs | 6 +- 7 files changed, 93 insertions(+), 77 deletions(-) diff --git a/bin/src/command/server.rs b/bin/src/command/server.rs index 818d08f06..a20f70c34 100644 --- a/bin/src/command/server.rs +++ b/bin/src/command/server.rs @@ -1,6 +1,6 @@ use std::{ collections::{HashMap, HashSet}, - fmt::Debug, + fmt::{self, Debug}, io::Error as IoError, ops::{Deref, DerefMut}, os::fd::{AsRawFd, FromRawFd}, @@ -858,8 +858,8 @@ impl Server { } } -impl std::fmt::Debug for Server { - fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { +impl Debug for Server { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { f.debug_struct("Server") .field("config", &self.config) .field("event_subscribers", &self.event_subscribers) diff --git a/command/Cargo.toml b/command/Cargo.toml index b5a63d361..b99edce3c 100644 --- a/command/Cargo.toml +++ b/command/Cargo.toml @@ -53,6 +53,7 @@ x509-parser = "^0.15.1" unstable = [] logs-debug = [] logs-trace = [] +logs-cache = [] [badges] travis-ci = { repository = "sozu-proxy/sozu" } diff --git a/command/src/logging/access_logs.rs b/command/src/logging/access_logs.rs index 68f435d70..989e60302 100644 --- a/command/src/logging/access_logs.rs +++ b/command/src/logging/access_logs.rs @@ -31,7 +31,7 @@ impl DuplicateOwnership for &T { impl<'a, T> DuplicateOwnership for Option<&'a T> where T: ?Sized, - &'a T: DuplicateOwnership + 'a, + &'a T: DuplicateOwnership, { type Target = Option<<&'a T as DuplicateOwnership>::Target>; unsafe fn duplicate(self) -> Self::Target { @@ -133,48 +133,50 @@ impl RequestRecord<'_> { /// 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_binary_access_log(self) -> ManuallyDrop { - let endpoint = match self.endpoint { - EndpointRecord::Http { - method, - authority, - path, - status, - reason, - } => 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 => protobuf_endpoint::Inner::Tcp(TcpEndpoint {}), - }; + pub fn into_binary_access_log(self) -> ManuallyDrop { + unsafe { + let endpoint = match self.endpoint { + EndpointRecord::Http { + method, + authority, + path, + status, + reason, + } => 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 => protobuf_endpoint::Inner::Tcp(TcpEndpoint {}), + }; - 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, - client_rtt: self.client_rtt.map(|t| t.whole_microseconds() as u64), - cluster_id: self.context.cluster_id.duplicate(), - endpoint: ProtobufEndpoint { - inner: Some(endpoint), - }, - message: self.message.duplicate(), - protocol: self.protocol.duplicate(), - request_id: self.context.request_id.into(), - response_time: self.response_time.whole_microseconds() as u64, - server_rtt: self.server_rtt.map(|t| t.whole_microseconds() as u64), - service_time: self.service_time.whole_microseconds() as u64, - session_address: self.session_address.map(Into::into), - tags: self - .tags - .map(|tags| tags.tags.duplicate()) - .unwrap_or_default(), - user_agent: self.user_agent.duplicate(), - tag: self.tag.duplicate(), - time: self.precise_time.into(), - }) + 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, + client_rtt: self.client_rtt.map(|t| t.whole_microseconds() as u64), + cluster_id: self.context.cluster_id.duplicate(), + endpoint: ProtobufEndpoint { + inner: Some(endpoint), + }, + message: self.message.duplicate(), + protocol: self.protocol.duplicate(), + request_id: self.context.request_id.into(), + response_time: self.response_time.whole_microseconds() as u64, + server_rtt: self.server_rtt.map(|t| t.whole_microseconds() as u64), + service_time: self.service_time.whole_microseconds() as u64, + session_address: self.session_address.map(Into::into), + tags: self + .tags + .map(|tags| tags.tags.duplicate()) + .unwrap_or_default(), + user_agent: self.user_agent.duplicate(), + tag: self.tag.duplicate(), + time: self.precise_time.into(), + }) + } } } diff --git a/command/src/logging/display.rs b/command/src/logging/display.rs index a812995af..287df6669 100644 --- a/command/src/logging/display.rs +++ b/command/src/logging/display.rs @@ -47,7 +47,7 @@ impl AsRef for LoggerBackend { } impl fmt::Display for Rfc3339Time { - fn fmt(&self, f: &mut std::fmt::Formatter) -> Result<(), std::fmt::Error> { + fn fmt(&self, f: &mut fmt::Formatter) -> Result<(), fmt::Error> { let t = self.inner; write!( f, @@ -100,7 +100,7 @@ impl fmt::Display for LogDuration { } impl fmt::Display for LogContext<'_> { - fn fmt(&self, f: &mut std::fmt::Formatter) -> std::fmt::Result { + fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { write!( f, "[{} {} {}]", @@ -160,12 +160,8 @@ impl<'a> fmt::Display for FullTags<'a> { } fn prepare_user_agent(user_agent: &str) -> String { - let mut user_agent = user_agent.replace(' ', "_"); - let mut ua_bytes = std::mem::take(&mut user_agent).into_bytes(); - if let Some(last) = ua_bytes.last_mut() { - if *last == b',' { - *last = b'!' - } - } - unsafe { String::from_utf8_unchecked(ua_bytes) } + user_agent + .replace(' ', "_") + .replace('[', "{") + .replace(']', "}") } diff --git a/command/src/logging/logs.rs b/command/src/logging/logs.rs index 80567e846..8f1dd705e 100644 --- a/command/src/logging/logs.rs +++ b/command/src/logging/logs.rs @@ -230,7 +230,7 @@ impl InnerLogger { let io_result = match self.access_format { AccessLogFormat::Protobuf => { - let binary_log = unsafe { log.into_binary_access_log() }; + let binary_log = log.into_binary_access_log(); let log_length = binary_log.encoded_len(); let total_length = log_length + encoded_len_varint(log_length as u64); self.buffer.clear(); @@ -269,11 +269,11 @@ impl InnerLogger { log.tag, ], standard: { - formats: ["{} {}->{} {}/{}/{}/{} {}->{} [{}] {} {}{}\n"], + formats: ["{} {} {} {}/{}/{}/{} {} {} [{}] {} {}{}\n"], args: [ log.context, - log.session_address.as_string_or("X"), - log.backend_address.as_string_or("X"), + log.session_address.as_string_or("-"), + log.backend_address.as_string_or("-"), LogDuration(Some(log.response_time)), LogDuration(Some(log.service_time)), LogDuration(log.client_rtt), @@ -287,7 +287,7 @@ impl InnerLogger { ] }, colored: { - formats: ["\x1b[;1m{}\x1b[m {}->{} {}/{}/{}/{} {}->{} \x1b[2m[{}] \x1b[;1m{} {:#}\x1b[m{}\n"], + formats: ["\x1b[;1m{}\x1b[m {} {} {}/{}/{}/{} {} {} \x1b[2m[{}] \x1b[;1m{} {:#}\x1b[m{}\n"], args: @, } }, @@ -794,16 +794,38 @@ impl LogLineCachedState { } } +#[macro_export] +macro_rules! log_enabled { + ($logger:expr, $lvl:expr) => {{ + let logger = $logger.borrow_mut(); + let enable = if cfg!(feature = "logs-cache") { + static mut LOG_LINE_CACHED_STATE: $crate::logging::LogLineCachedState = + $crate::logging::LogLineCachedState::new(); + logger.cached_enabled( + unsafe { &mut LOG_LINE_CACHED_STATE }, + $crate::logging::Metadata { + level: $lvl, + target: module_path!(), + }, + ) + } else { + logger.enabled($crate::logging::Metadata { + level: $lvl, + target: module_path!(), + }) + }; + if !enable { + return; + } + logger + }}; +} + #[macro_export] macro_rules! log { ($lvl:expr, $format:expr $(, $args:expr)*) => {{ - static mut LOG_LINE_CACHED_STATE: $crate::logging::LogLineCachedState = $crate::logging::LogLineCachedState::new(); $crate::logging::LOGGER.with(|logger| { - let mut logger = logger.borrow_mut(); - if !logger.cached_enabled( - unsafe { &mut LOG_LINE_CACHED_STATE }, - $crate::logging::Metadata { level: $lvl, target: module_path!() } - ) { return; } + let mut logger = $crate::log_enabled!(logger, $lvl); let (pid, tag, inner) = logger.split(); let (now, precise_time) = $crate::logging::now(); @@ -824,13 +846,8 @@ macro_rules! log { #[macro_export] macro_rules! log_access { ($lvl:expr, $($request_record_fields:tt)*) => {{ - static mut LOG_LINE_CACHED_STATE: $crate::logging::LogLineCachedState = $crate::logging::LogLineCachedState::new(); $crate::logging::LOGGER.with(|logger| { - let mut logger = logger.borrow_mut(); - if !logger.cached_enabled( - unsafe { &mut LOG_LINE_CACHED_STATE }, - $crate::logging::Metadata { level: $lvl, target: module_path!() } - ) { return; } + let mut logger = $crate::log_enabled!(logger, $lvl); let (pid, tag, inner) = logger.split(); let (now, precise_time) = $crate::logging::now(); diff --git a/command/src/response.rs b/command/src/response.rs index 04677817c..7efd3eb27 100644 --- a/command/src/response.rs +++ b/command/src/response.rs @@ -130,7 +130,7 @@ pub fn is_default_path_rule(p: &PathRule) -> bool { PathRuleKind::try_from(p.kind) == Ok(PathRuleKind::Prefix) && p.value.is_empty() } -impl std::fmt::Display for PathRule { +impl fmt::Display for PathRule { fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { match PathRuleKind::try_from(self.kind) { Ok(PathRuleKind::Prefix) => write!(f, "prefix '{}'", self.value), diff --git a/lib/src/tls.rs b/lib/src/tls.rs index e061c3d05..15a91a825 100644 --- a/lib/src/tls.rs +++ b/lib/src/tls.rs @@ -7,7 +7,7 @@ use std::{ borrow::ToOwned, collections::{HashMap, HashSet}, convert::From, - fmt::Debug, + fmt, io::BufReader, str::FromStr, sync::{Arc, Mutex}, @@ -468,8 +468,8 @@ impl ResolvesServerCert for MutexWrappedCertificateResolver { } } -impl Debug for MutexWrappedCertificateResolver { - fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { +impl fmt::Debug for MutexWrappedCertificateResolver { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { f.write_str("MutexWrappedCertificateResolver") } }