sozu_command_lib/logging/
logs.rs

1use std::{
2    cell::RefCell,
3    cmp, env,
4    fmt::Arguments,
5    fs::{File, OpenOptions},
6    io::{Error as IoError, ErrorKind as IoErrorKind, Stdout, Write, stdout},
7    net::{SocketAddr, TcpStream, UdpSocket},
8    ops::{Deref, DerefMut},
9    path::Path,
10    str::FromStr,
11};
12
13use mio::net::UnixDatagram;
14use prost::{Message, encoding::encoded_len_varint};
15
16use crate::{
17    AsString,
18    config::{Config, DEFAULT_LOG_TARGET},
19    logging::{LogDuration, LogError, LogMessage, RequestRecord},
20    proto::command::ProtobufAccessLogFormat,
21    writer::MultiLineWriter,
22};
23
24thread_local! {
25  pub static LOGGER: RefCell<Logger> = RefCell::new(Logger::new());
26}
27
28// TODO: check if this error is critical:
29//     could not register compat logger: SetLoggerError(())
30// The CompatLogger may need a variable that tells wether it has been initiated already
31pub static COMPAT_LOGGER: CompatLogger = CompatLogger;
32
33#[derive(Debug, Clone, PartialEq, Eq, Hash, Serialize, Deserialize)]
34#[serde(deny_unknown_fields, rename_all = "lowercase")]
35pub enum AccessLogFormat {
36    Ascii,
37    Protobuf,
38}
39
40impl From<&ProtobufAccessLogFormat> for AccessLogFormat {
41    fn from(value: &ProtobufAccessLogFormat) -> Self {
42        match value {
43            ProtobufAccessLogFormat::Ascii => Self::Ascii,
44            ProtobufAccessLogFormat::Protobuf => Self::Protobuf,
45        }
46    }
47}
48
49impl From<&Option<AccessLogFormat>> for ProtobufAccessLogFormat {
50    fn from(value: &Option<AccessLogFormat>) -> Self {
51        match value {
52            Some(AccessLogFormat::Ascii) | None => Self::Ascii,
53            Some(AccessLogFormat::Protobuf) => Self::Protobuf,
54        }
55    }
56}
57
58pub struct InnerLogger {
59    directives: Vec<LogDirective>,
60    backend: LoggerBackend,
61    /// inherited from the config's `log_target`, used to revive the backend
62    log_target: String,
63    pub colored: bool,
64    /// target of the access logs
65    access_backend: Option<LoggerBackend>,
66    /// used to revive the backend for access logs
67    access_logs_target: Option<String>,
68    /// how to format the access logs
69    access_format: AccessLogFormat,
70    access_colored: bool,
71    buffer: LoggerBuffer,
72}
73
74pub struct Logger {
75    inner: InnerLogger,
76    /// is displayed in each log, for instance "MAIN" or worker_id
77    tag: String,
78    /// the pid of the current process (main or worker)
79    pid: i32,
80    initialized: bool,
81}
82
83impl std::ops::Deref for Logger {
84    type Target = InnerLogger;
85    fn deref(&self) -> &Self::Target {
86        &self.inner
87    }
88}
89impl std::ops::DerefMut for Logger {
90    fn deref_mut(&mut self) -> &mut Self::Target {
91        &mut self.inner
92    }
93}
94
95impl Default for Logger {
96    fn default() -> Self {
97        Self {
98            inner: InnerLogger {
99                directives: vec![LogDirective {
100                    name: None,
101                    level: LogLevelFilter::Error,
102                }],
103                backend: LoggerBackend::Stdout(stdout()),
104                log_target: DEFAULT_LOG_TARGET.to_string(),
105                colored: false,
106                access_backend: None,
107                access_logs_target: None,
108                access_format: AccessLogFormat::Ascii,
109                access_colored: false,
110                buffer: LoggerBuffer(Vec::with_capacity(4096)),
111            },
112            tag: "UNINITIALIZED".to_string(),
113            pid: 0,
114            initialized: false,
115        }
116    }
117}
118
119impl Logger {
120    pub fn new() -> Self {
121        Self::default()
122    }
123
124    pub fn init(
125        tag: String,
126        spec: &str,
127        log_target: &str,
128        colored: bool,
129        access_logs_target: Option<&str>,
130        access_format: Option<AccessLogFormat>,
131        access_colored: Option<bool>,
132    ) -> Result<(), LogError> {
133        println!("Logs will be sent to {log_target}");
134        let backend = target_or_default(log_target);
135
136        println!("Access logs will be sent to {access_logs_target:?}");
137        let access_backend = access_logs_target.map(target_to_backend).transpose()?;
138
139        let (directives, _errors) = parse_logging_spec(spec);
140        LOGGER.with(|logger| {
141            let mut logger = logger.borrow_mut();
142            if !logger.initialized {
143                logger.set_directives(directives);
144                logger.colored = match backend {
145                    LoggerBackend::Stdout(_) => colored,
146                    _ => false,
147                };
148                logger.access_colored = match (&access_backend, &backend) {
149                    (Some(LoggerBackend::Stdout(_)), _) | (None, LoggerBackend::Stdout(_)) => {
150                        access_colored.unwrap_or(colored)
151                    }
152                    _ => false,
153                };
154                logger.backend = backend;
155                logger.log_target = log_target.to_owned();
156                logger.access_backend = access_backend;
157                logger.access_logs_target = access_logs_target.map(ToOwned::to_owned);
158                logger.access_format = access_format.unwrap_or(AccessLogFormat::Ascii);
159                logger.tag = tag;
160                logger.pid = unsafe { libc::getpid() };
161                logger.initialized = true;
162
163                let _ = log::set_logger(&COMPAT_LOGGER)
164                    .map_err(|e| println!("could not register compat logger: {e:?}"));
165
166                log::set_max_level(log::LevelFilter::Info);
167            }
168        });
169        Ok(())
170    }
171
172    pub fn set_directives(&mut self, directives: Vec<LogDirective>) {
173        self.directives = directives;
174    }
175
176    pub fn split(&mut self) -> (i32, &str, &mut InnerLogger) {
177        (self.pid, &self.tag, &mut self.inner)
178    }
179}
180
181struct LoggerBuffer(Vec<u8>);
182
183impl Deref for LoggerBuffer {
184    type Target = Vec<u8>;
185    fn deref(&self) -> &Self::Target {
186        &self.0
187    }
188}
189impl DerefMut for LoggerBuffer {
190    fn deref_mut(&mut self) -> &mut Self::Target {
191        &mut self.0
192    }
193}
194
195impl LoggerBuffer {
196    fn fmt<F: FnOnce(&[u8]) -> Result<usize, IoError>>(
197        &mut self,
198        args: Arguments,
199        flush: F,
200    ) -> Result<(), IoError> {
201        self.clear();
202        self.write_fmt(args)?;
203        flush(self.as_slice())?;
204        Ok(())
205    }
206}
207
208fn log_arguments(
209    args: Arguments,
210    backend: &mut LoggerBackend,
211    buffer: &mut LoggerBuffer,
212) -> Result<(), IoError> {
213    match backend {
214        LoggerBackend::Stdout(stdout) => {
215            let _ = stdout.write_fmt(args);
216            Ok(())
217        }
218        LoggerBackend::Tcp(socket) => socket.write_fmt(args),
219        LoggerBackend::File(file) => file.write_fmt(args),
220        LoggerBackend::Unix(socket) => buffer.fmt(args, |bytes| socket.send(bytes)),
221        LoggerBackend::Udp(sock, addr) => buffer.fmt(args, |b| sock.send_to(b, *addr)),
222    }
223}
224
225impl InnerLogger {
226    pub fn log(&mut self, args: Arguments) {
227        if let Err(e) = log_arguments(args, &mut self.backend, &mut self.buffer) {
228            println!("Could not write log to {}: {e:?}", self.backend.as_ref());
229        }
230    }
231
232    /// write an access log to the proper logging target
233    ///
234    /// Protobuf access logs are written with a prost length delimiter before, and 2 empty bytes after
235    pub fn log_access(&mut self, log: RequestRecord) -> bool {
236        let backend = self.access_backend.as_mut().unwrap_or(&mut self.backend);
237
238        let io_result = match self.access_format {
239            AccessLogFormat::Protobuf => {
240                let binary_log = log.into_binary_access_log();
241                let log_length = binary_log.encoded_len();
242                let total_length = log_length + encoded_len_varint(log_length as u64);
243                self.buffer.clear();
244                let current_capacity = self.buffer.capacity();
245                if current_capacity < total_length {
246                    self.buffer.reserve(total_length - current_capacity);
247                }
248
249                if let Err(e) = binary_log.encode_length_delimited(&mut self.buffer.0) {
250                    Err(IoError::new(IoErrorKind::InvalidData, e))
251                } else {
252                    self.buffer.extend_from_slice(&[0, 0]); // add two empty bytes after each protobuf access log
253                    let bytes = &self.buffer;
254                    match backend {
255                        LoggerBackend::Stdout(stdout) => {
256                            let _ = stdout.write(bytes);
257                            return true;
258                        }
259                        LoggerBackend::Tcp(socket) => socket.write(bytes),
260                        LoggerBackend::File(file) => file.write(bytes),
261                        LoggerBackend::Unix(socket) => socket.send(bytes),
262                        LoggerBackend::Udp(socket, address) => socket.send_to(bytes, *address),
263                    }
264                    .map(|_| ())
265                }
266            }
267            AccessLogFormat::Ascii => crate::_prompt_log! {
268                logger: |args| log_arguments(args, backend, &mut self.buffer),
269                is_access: true,
270                condition: self.access_colored,
271                prompt: [
272                    log.now,
273                    log.precise_time,
274                    log.pid,
275                    log.level,
276                    log.tag,
277                ],
278                standard: {
279                    formats: ["{} {} {} {}/{}/{}/{}/{} {} {} [{}] {:?} {} {}{}\n"],
280                    args: [
281                        log.context,
282                        log.session_address.as_string_or("-"),
283                        log.backend_address.as_string_or("-"),
284                        LogDuration(Some(log.request_time)),
285                        LogDuration(Some(log.service_time)),
286                        LogDuration(log.response_time),
287                        LogDuration(log.client_rtt),
288                        LogDuration(log.server_rtt),
289                        log.bytes_in,
290                        log.bytes_out,
291                        log.full_tags(),
292                        log.otel,
293                        log.protocol,
294                        log.endpoint,
295                        LogMessage(log.message),
296                    ]
297                },
298                colored: {
299                    formats: ["\x1b[;1m{}\x1b[m {} {} {}/{}/{}/{}/{} {} {} \x1b[2m[{}] {:?} \x1b[;1m{} {:#}\x1b[m{}\n"],
300                    args: @,
301                }
302            },
303        };
304
305        if let Err(e) = io_result {
306            println!("Could not write access log to {}: {e:?}", backend.as_ref());
307            println!(
308                "Trying to revive the backend of access logs to {:?}, or defaulting to {}",
309                self.access_logs_target, self.log_target
310            );
311            let log_target = self.access_logs_target.as_ref().unwrap_or(&self.log_target);
312            if let Err(err) = backend.revive(log_target) {
313                eprintln!("could not revive logger backend: {err}");
314            }
315            false
316        } else {
317            true
318        }
319    }
320
321    pub fn enabled(&self, meta: Metadata) -> bool {
322        // Search for the longest match, the vector is assumed to be pre-sorted.
323        for directive in self.directives.iter().rev() {
324            match &directive.name {
325                Some(name) if !meta.target.starts_with(name) => {}
326                Some(_) | None => return meta.level <= directive.level,
327            }
328        }
329        false
330    }
331
332    fn compat_enabled(&self, meta: &log::Metadata) -> bool {
333        // Search for the longest match, the vector is assumed to be pre-sorted.
334        for directive in self.directives.iter().rev() {
335            match &directive.name {
336                Some(name) if !meta.target().starts_with(name) => {}
337                Some(_) | None => return LogLevel::from(meta.level()) <= directive.level,
338            }
339        }
340        false
341    }
342}
343
344pub enum LoggerBackend {
345    Stdout(Stdout),
346    Unix(UnixDatagram),
347    Udp(UdpSocket, SocketAddr),
348    Tcp(TcpStream),
349    File(crate::writer::MultiLineWriter<File>),
350}
351
352impl LoggerBackend {
353    fn revive(&mut self, log_target: &str) -> Result<(), LogError> {
354        *self = target_to_backend(log_target)?;
355        Ok(())
356    }
357}
358
359#[repr(usize)]
360#[derive(Clone, Copy, Eq, Debug)]
361pub enum LogLevel {
362    /// The "error" level.
363    ///
364    /// Designates very serious errors.
365    Error = 1, // This way these line up with the discriminants for LogLevelFilter below
366    /// The "warn" level.
367    ///
368    /// Designates hazardous situations.
369    Warn,
370    /// The "info" level.
371    ///
372    /// Designates useful information.
373    Info,
374    /// The "debug" level.
375    ///
376    /// Designates lower priority information.
377    Debug,
378    /// The "trace" level.
379    ///
380    /// Designates very low priority, often extremely verbose, information.
381    Trace,
382}
383
384static LOG_LEVEL_NAMES: [&str; 6] = ["OFF", "ERROR", "WARN", "INFO", "DEBUG", "TRACE"];
385
386impl PartialEq for LogLevel {
387    #[inline]
388    fn eq(&self, other: &LogLevel) -> bool {
389        *self as usize == *other as usize
390    }
391}
392
393impl PartialEq<LogLevelFilter> for LogLevel {
394    #[inline]
395    fn eq(&self, other: &LogLevelFilter) -> bool {
396        *self as usize == *other as usize
397    }
398}
399
400impl PartialOrd for LogLevel {
401    #[inline]
402    fn partial_cmp(&self, other: &LogLevel) -> Option<cmp::Ordering> {
403        Some(self.cmp(other))
404    }
405}
406
407impl PartialOrd<LogLevelFilter> for LogLevel {
408    #[inline]
409    fn partial_cmp(&self, other: &LogLevelFilter) -> Option<cmp::Ordering> {
410        Some((*self as usize).cmp(&(*other as usize)))
411    }
412}
413
414impl Ord for LogLevel {
415    #[inline]
416    fn cmp(&self, other: &LogLevel) -> cmp::Ordering {
417        (*self as usize).cmp(&(*other as usize))
418    }
419}
420
421impl LogLevel {
422    fn from_usize(u: usize) -> Option<LogLevel> {
423        match u {
424            1 => Some(LogLevel::Error),
425            2 => Some(LogLevel::Warn),
426            3 => Some(LogLevel::Info),
427            4 => Some(LogLevel::Debug),
428            5 => Some(LogLevel::Trace),
429            _ => None,
430        }
431    }
432
433    /// Returns the most verbose logging level.
434    #[inline]
435    pub fn max() -> LogLevel {
436        LogLevel::Trace
437    }
438
439    /// Converts the `LogLevel` to the equivalent `LogLevelFilter`.
440    #[inline]
441    pub fn to_log_level_filter(self) -> LogLevelFilter {
442        LogLevelFilter::from_usize(self as usize).unwrap()
443    }
444}
445
446#[repr(usize)]
447#[derive(Clone, Copy, Eq, Debug)]
448pub enum LogLevelFilter {
449    Off,
450    Error,
451    Warn,
452    Info,
453    Debug,
454    Trace,
455}
456
457impl PartialEq for LogLevelFilter {
458    #[inline]
459    fn eq(&self, other: &LogLevelFilter) -> bool {
460        *self as usize == *other as usize
461    }
462}
463
464impl PartialEq<LogLevel> for LogLevelFilter {
465    #[inline]
466    fn eq(&self, other: &LogLevel) -> bool {
467        other.eq(self)
468    }
469}
470
471impl PartialOrd for LogLevelFilter {
472    #[inline]
473    fn partial_cmp(&self, other: &LogLevelFilter) -> Option<cmp::Ordering> {
474        Some(self.cmp(other))
475    }
476}
477
478impl PartialOrd<LogLevel> for LogLevelFilter {
479    #[inline]
480    fn partial_cmp(&self, other: &LogLevel) -> Option<cmp::Ordering> {
481        other.partial_cmp(self).map(|x| x.reverse())
482    }
483}
484
485impl Ord for LogLevelFilter {
486    #[inline]
487    fn cmp(&self, other: &LogLevelFilter) -> cmp::Ordering {
488        (*self as usize).cmp(&(*other as usize))
489    }
490}
491
492impl FromStr for LogLevelFilter {
493    type Err = ();
494    fn from_str(level: &str) -> Result<LogLevelFilter, ()> {
495        LOG_LEVEL_NAMES
496            .iter()
497            .position(|&name| name.eq_ignore_ascii_case(level))
498            .map(|p| LogLevelFilter::from_usize(p).unwrap())
499            .ok_or(())
500    }
501}
502
503impl LogLevelFilter {
504    fn from_usize(u: usize) -> Option<LogLevelFilter> {
505        match u {
506            0 => Some(LogLevelFilter::Off),
507            1 => Some(LogLevelFilter::Error),
508            2 => Some(LogLevelFilter::Warn),
509            3 => Some(LogLevelFilter::Info),
510            4 => Some(LogLevelFilter::Debug),
511            5 => Some(LogLevelFilter::Trace),
512            _ => None,
513        }
514    }
515    /// Returns the most verbose logging level filter.
516    #[inline]
517    pub fn max() -> LogLevelFilter {
518        LogLevelFilter::Trace
519    }
520
521    /// Converts `self` to the equivalent `LogLevel`.
522    ///
523    /// Returns `None` if `self` is `LogLevelFilter::Off`.
524    #[inline]
525    pub fn to_log_level(self) -> Option<LogLevel> {
526        LogLevel::from_usize(self as usize)
527    }
528}
529
530/// Metadata about a log message.
531#[derive(Debug)]
532pub struct Metadata {
533    pub level: LogLevel,
534    pub target: &'static str,
535}
536
537#[derive(Debug)]
538pub struct LogDirective {
539    name: Option<String>,
540    level: LogLevelFilter,
541}
542
543#[derive(thiserror::Error, Debug)]
544pub enum LogSpecParseError {
545    #[error("Too many '/'s: {0}")]
546    TooManySlashes(String),
547    #[error("Too many '='s: {0}")]
548    TooManyEquals(String),
549    #[error("Invalid log level: {0}")]
550    InvalidLogLevel(String),
551}
552
553pub fn parse_logging_spec(spec: &str) -> (Vec<LogDirective>, Vec<LogSpecParseError>) {
554    let mut dirs = Vec::new();
555    let mut errors = Vec::new();
556
557    let mut parts = spec.split('/');
558    let mods = parts.next();
559    let _ = parts.next();
560    if parts.next().is_some() {
561        errors.push(LogSpecParseError::TooManySlashes(spec.to_string()));
562    }
563    if let Some(m) = mods {
564        for s in m.split(',') {
565            if s.is_empty() {
566                continue;
567            }
568            let mut parts = s.split('=');
569            let (log_level, name) =
570                match (parts.next(), parts.next().map(|s| s.trim()), parts.next()) {
571                    (Some(part0), None, None) => {
572                        // if the single argument is a log-level string or number,
573                        // treat that as a global fallback
574                        match part0.parse() {
575                            Ok(num) => (num, None),
576                            Err(_) => {
577                                errors.push(LogSpecParseError::InvalidLogLevel(s.to_string()));
578                                (LogLevelFilter::max(), None)
579                            }
580                        }
581                    }
582                    (Some(part0), Some(""), None) => (LogLevelFilter::max(), Some(part0)),
583                    (Some(part0), Some(part1), None) => match part1.parse() {
584                        Ok(num) => (num, Some(part0)),
585                        Err(_) => {
586                            errors.push(LogSpecParseError::InvalidLogLevel(s.to_string()));
587                            continue;
588                        }
589                    },
590                    _ => {
591                        errors.push(LogSpecParseError::TooManyEquals(s.to_string()));
592                        continue;
593                    }
594                };
595            dirs.push(LogDirective {
596                name: name.map(|s| s.to_string()),
597                level: log_level,
598            });
599        }
600    }
601
602    for error in &errors {
603        println!("{error:?}");
604    }
605    (dirs, errors)
606}
607
608/// start the logger with all logs and access logs on stdout
609pub fn setup_default_logging(
610    log_colored: bool,
611    log_level: &str,
612    tag: &str,
613) -> Result<(), LogError> {
614    setup_logging("stdout", log_colored, None, None, None, log_level, tag)
615}
616
617/// start the logger from config (takes RUST_LOG into account)
618pub fn setup_logging_with_config(config: &Config, tag: &str) -> Result<(), LogError> {
619    setup_logging(
620        &config.log_target,
621        config.log_colored,
622        config.access_logs_target.as_deref(),
623        config.access_logs_format.clone(),
624        config.access_logs_colored,
625        &config.log_level,
626        tag,
627    )
628}
629
630/// start the logger, after:
631///
632/// - determining logging backends
633/// - taking RUST_LOG into account
634pub fn setup_logging(
635    log_target: &str,
636    log_colored: bool,
637    access_logs_target: Option<&str>,
638    access_logs_format: Option<AccessLogFormat>,
639    access_logs_colored: Option<bool>,
640    log_level: &str,
641    tag: &str,
642) -> Result<(), LogError> {
643    Logger::init(
644        tag.to_string(),
645        env::var("RUST_LOG").as_deref().unwrap_or(log_level),
646        log_target,
647        log_colored,
648        access_logs_target,
649        access_logs_format,
650        access_logs_colored,
651    )
652}
653
654/// defaults to stdout if the log target is unparseable
655fn target_or_default(target: &str) -> LoggerBackend {
656    match target_to_backend(target) {
657        Ok(backend) => backend,
658        Err(target_error) => {
659            eprintln!("{target_error}, defaulting to stdout");
660            LoggerBackend::Stdout(stdout())
661        }
662    }
663}
664
665pub fn target_to_backend(target: &str) -> Result<LoggerBackend, LogError> {
666    if target == "stdout" {
667        return Ok(LoggerBackend::Stdout(stdout()));
668    }
669
670    if let Some(addr) = target.strip_prefix("udp://") {
671        let address = addr
672            .parse::<SocketAddr>()
673            .map_err(|e| LogError::InvalidSocketAddress(target.to_owned(), e))?;
674
675        let socket = UdpSocket::bind(("0.0.0.0", 0)).map_err(LogError::UdpBind)?;
676
677        return Ok(LoggerBackend::Udp(socket, address));
678    }
679
680    if let Some(addr) = target.strip_prefix("tcp://") {
681        let tcp_stream =
682            TcpStream::connect(addr).map_err(|e| LogError::TcpConnect(target.to_owned(), e))?;
683
684        return Ok(LoggerBackend::Tcp(tcp_stream));
685    }
686
687    if let Some(addr) = target.strip_prefix("unix://") {
688        let socket = UnixDatagram::unbound().map_err(LogError::CreateUnixSocket)?;
689
690        socket
691            .connect(addr)
692            .map_err(|e| LogError::ConnectToUnixSocket(target.to_owned(), e))?;
693
694        return Ok(LoggerBackend::Unix(socket));
695    }
696
697    if let Some(addr) = target.strip_prefix("file://") {
698        let path = Path::new(addr);
699        let file = OpenOptions::new()
700            .create(true)
701            .append(true)
702            .open(path)
703            .map_err(|e| LogError::OpenFile(target.to_owned(), e))?;
704
705        return Ok(LoggerBackend::File(MultiLineWriter::new(file)));
706    }
707
708    Err(LogError::InvalidLogTarget(
709        target.to_owned(),
710        "Log target is not parseable",
711    ))
712}
713
714#[macro_export]
715macro_rules! _prompt_log {
716    {
717        logger: $logger:expr,
718        is_access: $access:expr,
719        condition: $cond:expr,
720        prompt: [$($p:tt)*],
721        standard: {$($std:tt)*}$(,)?
722    } => {
723        $crate::_prompt_log!{
724            logger: $logger,
725            is_access: $access,
726            condition: $cond,
727            prompt: [$($p)*],
728            standard: {$($std)*},
729            colored: {$($std)*},
730        }
731    };
732    {
733        logger: $logger:expr,
734        is_access: $access:expr,
735        condition: $cond:expr,
736        prompt: [$($p:tt)*],
737        standard: {
738            formats: [$($std_fmt:tt)*],
739            args: [$($std_args:expr),*$(,)?]$(,)?
740        },
741        colored: {
742            formats: [$($col_fmt:tt)*],
743            args: @$(,)?
744        }$(,)?
745    } => {
746        $crate::_prompt_log!{
747            logger: $logger,
748            is_access: $access,
749            condition: $cond,
750            prompt: [$($p)*],
751            standard: {
752                formats: [$($std_fmt)*],
753                args: [$($std_args),*],
754            },
755            colored: {
756                formats: [$($col_fmt)*],
757                args: [$($std_args),*],
758            },
759        }
760    };
761    {
762        logger: $logger:expr,
763        is_access: $access:expr,
764        condition: $cond:expr,
765        prompt: [$now:expr, $precise_time:expr, $pid:expr, $lvl:expr, $tag:expr$(,)?],
766        standard: {
767            formats: [$($std_fmt:tt)*],
768            args: [$($std_args:expr),*$(,)?]$(,)?
769        },
770        colored: {
771            formats: [$($col_fmt:tt)*],
772            args: [$($col_args:expr),*$(,)?]$(,)?
773        }$(,)?
774    } => {
775        if $cond {
776            $crate::_prompt_log!(@bind [$logger, concat!("{} \x1b[2m{} \x1b[;2;1m{} {} \x1b[0;1m{}\x1b[m\t", $($col_fmt)*)] [$now, $precise_time, $pid, $lvl.as_str($access, true), $tag] $($col_args),*)
777        } else {
778            $crate::_prompt_log!(@bind [$logger, concat!("{} {} {} {} {}\t", $($std_fmt)*)] [$now, $precise_time, $pid, $lvl.as_str($access, false), $tag] $($std_args),*)
779        }
780    };
781    (@bind [$logger:expr, $fmt:expr] [$($bindings:expr),*] $arg:expr $(, $args:expr)*) => {{
782        let binding = &$arg;
783        $crate::_prompt_log!(@bind [$logger, $fmt] [$($bindings),* , binding] $($args),*)
784    }};
785    (@bind [$logger:expr, $fmt:expr] [$($bindings:expr),*]) => {
786        $logger(format_args!($fmt, $($bindings),*))
787    };
788}
789
790#[derive(Clone, Copy, Debug)]
791pub struct LogLineCachedState(u8);
792const LOG_LINE_ENABLED: u8 = 1 << 7;
793
794impl Default for LogLineCachedState {
795    fn default() -> Self {
796        Self::new()
797    }
798}
799
800impl LogLineCachedState {
801    pub const fn new() -> Self {
802        Self(0)
803    }
804    #[inline(always)]
805    pub fn version(&self) -> u8 {
806        self.0 & !LOG_LINE_ENABLED
807    }
808    #[inline(always)]
809    pub fn enabled(&self) -> bool {
810        self.0 & LOG_LINE_ENABLED != 0
811    }
812    #[inline(always)]
813    pub fn set(&mut self, version: u8, enabled: bool) {
814        self.0 = version;
815        if enabled {
816            self.0 |= LOG_LINE_ENABLED
817        }
818    }
819}
820
821#[macro_export]
822macro_rules! _log_enabled {
823    ($logger:expr, $lvl:expr) => {{
824        let logger = $logger.borrow_mut();
825        if !logger.enabled($crate::logging::Metadata {
826            level: $lvl,
827            target: module_path!(),
828        }) {
829            return;
830        }
831        logger
832    }};
833}
834
835#[macro_export]
836macro_rules! _log {
837    ($lvl:expr, $format:expr $(, $args:expr)*) => {{
838        $crate::logging::LOGGER.with(|logger| {
839            let mut logger = $crate::_log_enabled!(logger, $lvl);
840            let (pid, tag, inner) = logger.split();
841            let (now, precise_time) = $crate::logging::now();
842
843            $crate::_prompt_log!{
844                logger: |args| inner.log(args),
845                is_access: false,
846                condition: inner.colored,
847                prompt: [now, precise_time, pid, $lvl, tag],
848                standard: {
849                    formats: [$format, '\n'],
850                    args: [$($args),*]
851                }
852            };
853        })
854    }};
855}
856
857#[macro_export]
858macro_rules! _log_access {
859    ($lvl:expr, $on_failure:block, $($request_record_fields:tt)*) => {{
860         $crate::logging::LOGGER.with(|logger| {
861            let success = {
862                let mut logger = $crate::_log_enabled!(logger, $lvl);
863                let (pid, tag, inner) = logger.split();
864                let (now, precise_time) = $crate::logging::now();
865
866                inner.log_access(
867                    $crate::_structured_access_log!(
868                        [$crate::logging::RequestRecord]
869                        pid, tag, now, precise_time, level: $lvl, $($request_record_fields)*
870                    )
871                )
872            }; // logger dropped here
873
874            if !success {
875                // recording this metric may borrow the logger, so we have
876                // to perform this action after the block above
877                $on_failure
878            }
879        });
880    }};
881}
882
883#[macro_export]
884macro_rules! _structured_access_log {
885    ([$($struct_name:tt)+] $($fields:tt)*) => {{
886        $($struct_name)+ {$(
887            $fields
888        )*}
889    }};
890}
891
892#[macro_export]
893/// dynamically chose between info_access and error_access
894macro_rules! log_access {
895    ($error:expr, on_failure: $on_failure:block, $($request_record_fields:tt)*) => {
896        let lvl = if $error {
897            $crate::logging::LogLevel::Error
898        } else {
899            $crate::logging::LogLevel::Info
900        };
901        _log_access!(lvl, $on_failure, $($request_record_fields)*);
902    };
903}
904
905/// log a failure concerning an HTTP or TCP request
906#[macro_export]
907macro_rules! error_access {
908    (on_failure: $on_failure:block, $($request_record_fields:tt)*) => {
909        $crate::_log_access!($crate::logging::LogLevel::Error, $on_failure, $($request_record_fields)*);
910    };
911}
912
913/// log the success of an HTTP or TCP request
914#[macro_export]
915macro_rules! info_access {
916    (on_failure: $on_failure:block, $($request_record_fields:tt)*) => {
917        $crate::_log_access!($crate::logging::LogLevel::Info, $on_failure, $($request_record_fields)*);
918    };
919}
920
921/// log an error with Sōzu's custom log stack
922#[macro_export]
923macro_rules! error {
924    ($format:expr $(, $args:expr)* $(,)?) => {
925        $crate::_log!($crate::logging::LogLevel::Error, $format $(, $args)*)
926    };
927}
928
929/// log a warning with Sōzu’s custom log stack
930#[macro_export]
931macro_rules! warn {
932    ($format:expr $(, $args:expr)* $(,)?) => {
933        $crate::_log!($crate::logging::LogLevel::Warn, $format $(, $args)*)
934    };
935}
936
937/// log an info with Sōzu’s custom log stack
938#[macro_export]
939macro_rules! info {
940    ($format:expr $(, $args:expr)* $(,)?) => {
941        $crate::_log!($crate::logging::LogLevel::Info, $format $(, $args)*)
942    };
943}
944
945/// log a debug with Sōzu’s custom log stack
946#[macro_export]
947macro_rules! debug {
948    ($format:expr $(, $args:expr)* $(,)?) => {{
949        #[cfg(any(debug_assertions, feature = "logs-debug", feature = "logs-trace"))]
950        $crate::_log!($crate::logging::LogLevel::Debug, concat!("{}\t", $format), module_path!() $(, $args)*);
951        #[cfg(not(any(debug_assertions, feature = "logs-trace")))]
952        if false {$( let _ = $args; )*}
953    }};
954}
955
956/// log a trace with Sōzu’s custom log stack
957#[macro_export]
958macro_rules! trace {
959    ($format:expr $(, $args:expr)* $(,)?) => {{
960        #[cfg(any(debug_assertions, feature = "logs-trace"))]
961        $crate::_log!($crate::logging::LogLevel::Trace, concat!("{}\t", $format), module_path!() $(, $args)*);
962        #[cfg(not(any(debug_assertions, feature = "logs-trace")))]
963        if false {$( let _ = $args; )*}
964    }};
965}
966
967/// write a log with a "FIXME" prefix on an info level
968#[macro_export]
969macro_rules! fixme {
970    ($(, $args:expr)* $(,)?) => {
971        $crate::_log!($crate::logging::LogLevel::Info, "FIXME: {}:{} in {}: {}", file!(), line!(), module_path!() $(, $args)*)
972    };
973}
974
975pub struct CompatLogger;
976
977impl From<log::Level> for LogLevel {
978    fn from(lvl: log::Level) -> Self {
979        match lvl {
980            log::Level::Error => LogLevel::Error,
981            log::Level::Warn => LogLevel::Warn,
982            log::Level::Info => LogLevel::Info,
983            log::Level::Debug => LogLevel::Debug,
984            log::Level::Trace => LogLevel::Trace,
985        }
986    }
987}
988
989impl log::Log for CompatLogger {
990    fn enabled(&self, _: &log::Metadata) -> bool {
991        true
992    }
993
994    fn log(&self, record: &log::Record) {
995        LOGGER.with(|logger| {
996            let mut logger = logger.borrow_mut();
997            if !logger.compat_enabled(record.metadata()) {
998                return;
999            }
1000            let (pid, tag, inner) = logger.split();
1001            let (now, precise_time) = now();
1002            crate::_prompt_log! {
1003                logger: |args| inner.log(args),
1004                is_access: false,
1005                condition: inner.colored,
1006                prompt: [
1007                    now, precise_time, pid, LogLevel::from(record.level()), tag
1008                ],
1009                standard: {
1010                    formats: ["{}\n"],
1011                    args: [record.args()]
1012                }
1013            };
1014        })
1015    }
1016
1017    fn flush(&self) {}
1018}
1019
1020/// start a logger used in test environment
1021#[macro_export]
1022macro_rules! setup_test_logger {
1023    () => {
1024        let _ = $crate::logging::Logger::init(
1025            module_path!().to_string(),
1026            "error",
1027            sozu_command_lib::config::DEFAULT_LOG_TARGET,
1028            false,
1029            None,
1030            None,
1031            None,
1032        );
1033    };
1034}
1035
1036pub struct Rfc3339Time {
1037    pub inner: ::time::OffsetDateTime,
1038}
1039
1040/// yields (Rfc3339Time, unix_epoch)
1041pub fn now() -> (Rfc3339Time, i128) {
1042    let t = time::OffsetDateTime::now_utc();
1043    (
1044        Rfc3339Time { inner: t },
1045        (t - time::OffsetDateTime::UNIX_EPOCH).whole_nanoseconds(),
1046    )
1047}
sozu_command_lib/logging/logs.rs

sozu_command_lib/logging/
logs.rs
