sozu_command_lib/logging/
logs.rs

1use std::{
2    cell::RefCell,
3    cmp, env,
4    fmt::Arguments,
5    fs::{File, OpenOptions},
6    io::{stdout, Error as IoError, ErrorKind as IoErrorKind, Stdout, Write},
7    net::{SocketAddr, TcpStream, UdpSocket},
8    ops::{Deref, DerefMut},
9    path::Path,
10    str::FromStr,
11};
12
13use mio::net::UnixDatagram;
14use prost::{encoding::encoded_len_varint, Message};
15
16use crate::{
17    config::{Config, DEFAULT_LOG_TARGET},
18    logging::{LogDuration, LogError, LogMessage, RequestRecord},
19    proto::command::ProtobufAccessLogFormat,
20    writer::MultiLineWriter,
21    AsString,
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.protocol,
293                        log.endpoint,
294                        LogMessage(log.message),
295                    ]
296                },
297                colored: {
298                    formats: ["\x1b[;1m{}\x1b[m {} {} {}/{}/{}/{}/{} {} {} \x1b[2m[{}] \x1b[;1m{} {:#}\x1b[m{}\n"],
299                    args: @,
300                }
301            },
302        };
303
304        if let Err(e) = io_result {
305            println!("Could not write access log to {}: {e:?}", backend.as_ref());
306            println!(
307                "Trying to revive the backend of access logs to {:?}, or defaulting to {}",
308                self.access_logs_target, self.log_target
309            );
310            let log_target = self.access_logs_target.as_ref().unwrap_or(&self.log_target);
311            if let Err(err) = backend.revive(log_target) {
312                eprintln!("could not revive logger backend: {err}");
313            }
314            false
315        } else {
316            true
317        }
318    }
319
320    pub fn enabled(&self, meta: Metadata) -> bool {
321        // Search for the longest match, the vector is assumed to be pre-sorted.
322        for directive in self.directives.iter().rev() {
323            match &directive.name {
324                Some(name) if !meta.target.starts_with(name) => {}
325                Some(_) | None => return meta.level <= directive.level,
326            }
327        }
328        false
329    }
330
331    fn compat_enabled(&self, meta: &log::Metadata) -> bool {
332        // Search for the longest match, the vector is assumed to be pre-sorted.
333        for directive in self.directives.iter().rev() {
334            match &directive.name {
335                Some(name) if !meta.target().starts_with(name) => {}
336                Some(_) | None => return LogLevel::from(meta.level()) <= directive.level,
337            }
338        }
339        false
340    }
341}
342
343pub enum LoggerBackend {
344    Stdout(Stdout),
345    Unix(UnixDatagram),
346    Udp(UdpSocket, SocketAddr),
347    Tcp(TcpStream),
348    File(crate::writer::MultiLineWriter<File>),
349}
350
351impl LoggerBackend {
352    fn revive(&mut self, log_target: &str) -> Result<(), LogError> {
353        *self = target_to_backend(log_target)?;
354        Ok(())
355    }
356}
357
358#[repr(usize)]
359#[derive(Clone, Copy, Eq, Debug)]
360pub enum LogLevel {
361    /// The "error" level.
362    ///
363    /// Designates very serious errors.
364    Error = 1, // This way these line up with the discriminants for LogLevelFilter below
365    /// The "warn" level.
366    ///
367    /// Designates hazardous situations.
368    Warn,
369    /// The "info" level.
370    ///
371    /// Designates useful information.
372    Info,
373    /// The "debug" level.
374    ///
375    /// Designates lower priority information.
376    Debug,
377    /// The "trace" level.
378    ///
379    /// Designates very low priority, often extremely verbose, information.
380    Trace,
381}
382
383static LOG_LEVEL_NAMES: [&str; 6] = ["OFF", "ERROR", "WARN", "INFO", "DEBUG", "TRACE"];
384
385impl PartialEq for LogLevel {
386    #[inline]
387    fn eq(&self, other: &LogLevel) -> bool {
388        *self as usize == *other as usize
389    }
390}
391
392impl PartialEq<LogLevelFilter> for LogLevel {
393    #[inline]
394    fn eq(&self, other: &LogLevelFilter) -> bool {
395        *self as usize == *other as usize
396    }
397}
398
399impl PartialOrd for LogLevel {
400    #[inline]
401    fn partial_cmp(&self, other: &LogLevel) -> Option<cmp::Ordering> {
402        Some(self.cmp(other))
403    }
404}
405
406impl PartialOrd<LogLevelFilter> for LogLevel {
407    #[inline]
408    fn partial_cmp(&self, other: &LogLevelFilter) -> Option<cmp::Ordering> {
409        Some((*self as usize).cmp(&(*other as usize)))
410    }
411}
412
413impl Ord for LogLevel {
414    #[inline]
415    fn cmp(&self, other: &LogLevel) -> cmp::Ordering {
416        (*self as usize).cmp(&(*other as usize))
417    }
418}
419
420impl LogLevel {
421    fn from_usize(u: usize) -> Option<LogLevel> {
422        match u {
423            1 => Some(LogLevel::Error),
424            2 => Some(LogLevel::Warn),
425            3 => Some(LogLevel::Info),
426            4 => Some(LogLevel::Debug),
427            5 => Some(LogLevel::Trace),
428            _ => None,
429        }
430    }
431
432    /// Returns the most verbose logging level.
433    #[inline]
434    pub fn max() -> LogLevel {
435        LogLevel::Trace
436    }
437
438    /// Converts the `LogLevel` to the equivalent `LogLevelFilter`.
439    #[inline]
440    pub fn to_log_level_filter(self) -> LogLevelFilter {
441        LogLevelFilter::from_usize(self as usize).unwrap()
442    }
443}
444
445#[repr(usize)]
446#[derive(Clone, Copy, Eq, Debug)]
447pub enum LogLevelFilter {
448    Off,
449    Error,
450    Warn,
451    Info,
452    Debug,
453    Trace,
454}
455
456impl PartialEq for LogLevelFilter {
457    #[inline]
458    fn eq(&self, other: &LogLevelFilter) -> bool {
459        *self as usize == *other as usize
460    }
461}
462
463impl PartialEq<LogLevel> for LogLevelFilter {
464    #[inline]
465    fn eq(&self, other: &LogLevel) -> bool {
466        other.eq(self)
467    }
468}
469
470impl PartialOrd for LogLevelFilter {
471    #[inline]
472    fn partial_cmp(&self, other: &LogLevelFilter) -> Option<cmp::Ordering> {
473        Some(self.cmp(other))
474    }
475}
476
477impl PartialOrd<LogLevel> for LogLevelFilter {
478    #[inline]
479    fn partial_cmp(&self, other: &LogLevel) -> Option<cmp::Ordering> {
480        other.partial_cmp(self).map(|x| x.reverse())
481    }
482}
483
484impl Ord for LogLevelFilter {
485    #[inline]
486    fn cmp(&self, other: &LogLevelFilter) -> cmp::Ordering {
487        (*self as usize).cmp(&(*other as usize))
488    }
489}
490
491impl FromStr for LogLevelFilter {
492    type Err = ();
493    fn from_str(level: &str) -> Result<LogLevelFilter, ()> {
494        LOG_LEVEL_NAMES
495            .iter()
496            .position(|&name| name.eq_ignore_ascii_case(level))
497            .map(|p| LogLevelFilter::from_usize(p).unwrap())
498            .ok_or(())
499    }
500}
501
502impl LogLevelFilter {
503    fn from_usize(u: usize) -> Option<LogLevelFilter> {
504        match u {
505            0 => Some(LogLevelFilter::Off),
506            1 => Some(LogLevelFilter::Error),
507            2 => Some(LogLevelFilter::Warn),
508            3 => Some(LogLevelFilter::Info),
509            4 => Some(LogLevelFilter::Debug),
510            5 => Some(LogLevelFilter::Trace),
511            _ => None,
512        }
513    }
514    /// Returns the most verbose logging level filter.
515    #[inline]
516    pub fn max() -> LogLevelFilter {
517        LogLevelFilter::Trace
518    }
519
520    /// Converts `self` to the equivalent `LogLevel`.
521    ///
522    /// Returns `None` if `self` is `LogLevelFilter::Off`.
523    #[inline]
524    pub fn to_log_level(self) -> Option<LogLevel> {
525        LogLevel::from_usize(self as usize)
526    }
527}
528
529/// Metadata about a log message.
530#[derive(Debug)]
531pub struct Metadata {
532    pub level: LogLevel,
533    pub target: &'static str,
534}
535
536#[derive(Debug)]
537pub struct LogDirective {
538    name: Option<String>,
539    level: LogLevelFilter,
540}
541
542#[derive(thiserror::Error, Debug)]
543pub enum LogSpecParseError {
544    #[error("Too many '/'s: {0}")]
545    TooManySlashes(String),
546    #[error("Too many '='s: {0}")]
547    TooManyEquals(String),
548    #[error("Invalid log level: {0}")]
549    InvalidLogLevel(String),
550}
551
552pub fn parse_logging_spec(spec: &str) -> (Vec<LogDirective>, Vec<LogSpecParseError>) {
553    let mut dirs = Vec::new();
554    let mut errors = Vec::new();
555
556    let mut parts = spec.split('/');
557    let mods = parts.next();
558    let _ = parts.next();
559    if parts.next().is_some() {
560        errors.push(LogSpecParseError::TooManySlashes(spec.to_string()));
561    }
562    if let Some(m) = mods {
563        for s in m.split(',') {
564            if s.is_empty() {
565                continue;
566            }
567            let mut parts = s.split('=');
568            let (log_level, name) =
569                match (parts.next(), parts.next().map(|s| s.trim()), parts.next()) {
570                    (Some(part0), None, None) => {
571                        // if the single argument is a log-level string or number,
572                        // treat that as a global fallback
573                        match part0.parse() {
574                            Ok(num) => (num, None),
575                            Err(_) => {
576                                errors.push(LogSpecParseError::InvalidLogLevel(s.to_string()));
577                                (LogLevelFilter::max(), None)
578                            }
579                        }
580                    }
581                    (Some(part0), Some(""), None) => (LogLevelFilter::max(), Some(part0)),
582                    (Some(part0), Some(part1), None) => match part1.parse() {
583                        Ok(num) => (num, Some(part0)),
584                        Err(_) => {
585                            errors.push(LogSpecParseError::InvalidLogLevel(s.to_string()));
586                            continue;
587                        }
588                    },
589                    _ => {
590                        errors.push(LogSpecParseError::TooManyEquals(s.to_string()));
591                        continue;
592                    }
593                };
594            dirs.push(LogDirective {
595                name: name.map(|s| s.to_string()),
596                level: log_level,
597            });
598        }
599    }
600
601    for error in &errors {
602        println!("{error:?}");
603    }
604    (dirs, errors)
605}
606
607/// start the logger with all logs and access logs on stdout
608pub fn setup_default_logging(
609    log_colored: bool,
610    log_level: &str,
611    tag: &str,
612) -> Result<(), LogError> {
613    setup_logging("stdout", log_colored, None, None, None, log_level, tag)
614}
615
616/// start the logger from config (takes RUST_LOG into account)
617pub fn setup_logging_with_config(config: &Config, tag: &str) -> Result<(), LogError> {
618    setup_logging(
619        &config.log_target,
620        config.log_colored,
621        config.access_logs_target.as_deref(),
622        config.access_logs_format.clone(),
623        config.access_logs_colored,
624        &config.log_level,
625        tag,
626    )
627}
628
629/// start the logger, after:
630///
631/// - determining logging backends
632/// - taking RUST_LOG into account
633pub fn setup_logging(
634    log_target: &str,
635    log_colored: bool,
636    access_logs_target: Option<&str>,
637    access_logs_format: Option<AccessLogFormat>,
638    access_logs_colored: Option<bool>,
639    log_level: &str,
640    tag: &str,
641) -> Result<(), LogError> {
642    Logger::init(
643        tag.to_string(),
644        env::var("RUST_LOG").as_deref().unwrap_or(log_level),
645        log_target,
646        log_colored,
647        access_logs_target,
648        access_logs_format,
649        access_logs_colored,
650    )
651}
652
653/// defaults to stdout if the log target is unparseable
654fn target_or_default(target: &str) -> LoggerBackend {
655    match target_to_backend(target) {
656        Ok(backend) => backend,
657        Err(target_error) => {
658            eprintln!("{target_error}, defaulting to stdout");
659            LoggerBackend::Stdout(stdout())
660        }
661    }
662}
663
664pub fn target_to_backend(target: &str) -> Result<LoggerBackend, LogError> {
665    if target == "stdout" {
666        return Ok(LoggerBackend::Stdout(stdout()));
667    }
668
669    if let Some(addr) = target.strip_prefix("udp://") {
670        let address = addr
671            .parse::<SocketAddr>()
672            .map_err(|e| LogError::InvalidSocketAddress(target.to_owned(), e))?;
673
674        let socket = UdpSocket::bind(("0.0.0.0", 0)).map_err(LogError::UdpBind)?;
675
676        return Ok(LoggerBackend::Udp(socket, address));
677    }
678
679    if let Some(addr) = target.strip_prefix("tcp://") {
680        let tcp_stream =
681            TcpStream::connect(addr).map_err(|e| LogError::TcpConnect(target.to_owned(), e))?;
682
683        return Ok(LoggerBackend::Tcp(tcp_stream));
684    }
685
686    if let Some(addr) = target.strip_prefix("unix://") {
687        let socket = UnixDatagram::unbound().map_err(LogError::CreateUnixSocket)?;
688
689        socket
690            .connect(addr)
691            .map_err(|e| LogError::ConnectToUnixSocket(target.to_owned(), e))?;
692
693        return Ok(LoggerBackend::Unix(socket));
694    }
695
696    if let Some(addr) = target.strip_prefix("file://") {
697        let path = Path::new(addr);
698        let file = OpenOptions::new()
699            .create(true)
700            .append(true)
701            .open(path)
702            .map_err(|e| LogError::OpenFile(target.to_owned(), e))?;
703
704        return Ok(LoggerBackend::File(MultiLineWriter::new(file)));
705    }
706
707    Err(LogError::InvalidLogTarget(
708        target.to_owned(),
709        "Log target is not parseable",
710    ))
711}
712
713#[macro_export]
714macro_rules! _prompt_log {
715    {
716        logger: $logger:expr,
717        is_access: $access:expr,
718        condition: $cond:expr,
719        prompt: [$($p:tt)*],
720        standard: {$($std:tt)*}$(,)?
721    } => {
722        $crate::_prompt_log!{
723            logger: $logger,
724            is_access: $access,
725            condition: $cond,
726            prompt: [$($p)*],
727            standard: {$($std)*},
728            colored: {$($std)*},
729        }
730    };
731    {
732        logger: $logger:expr,
733        is_access: $access:expr,
734        condition: $cond:expr,
735        prompt: [$($p:tt)*],
736        standard: {
737            formats: [$($std_fmt:tt)*],
738            args: [$($std_args:expr),*$(,)?]$(,)?
739        },
740        colored: {
741            formats: [$($col_fmt:tt)*],
742            args: @$(,)?
743        }$(,)?
744    } => {
745        $crate::_prompt_log!{
746            logger: $logger,
747            is_access: $access,
748            condition: $cond,
749            prompt: [$($p)*],
750            standard: {
751                formats: [$($std_fmt)*],
752                args: [$($std_args),*],
753            },
754            colored: {
755                formats: [$($col_fmt)*],
756                args: [$($std_args),*],
757            },
758        }
759    };
760    {
761        logger: $logger:expr,
762        is_access: $access:expr,
763        condition: $cond:expr,
764        prompt: [$now:expr, $precise_time:expr, $pid:expr, $lvl:expr, $tag:expr$(,)?],
765        standard: {
766            formats: [$($std_fmt:tt)*],
767            args: [$($std_args:expr),*$(,)?]$(,)?
768        },
769        colored: {
770            formats: [$($col_fmt:tt)*],
771            args: [$($col_args:expr),*$(,)?]$(,)?
772        }$(,)?
773    } => {
774        if $cond {
775            $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),*)
776        } else {
777            $crate::_prompt_log!(@bind [$logger, concat!("{} {} {} {} {}\t", $($std_fmt)*)] [$now, $precise_time, $pid, $lvl.as_str($access, false), $tag] $($std_args),*)
778        }
779    };
780    (@bind [$logger:expr, $fmt:expr] [$($bindings:expr),*] $arg:expr $(, $args:expr)*) => {{
781        let binding = &$arg;
782        $crate::_prompt_log!(@bind [$logger, $fmt] [$($bindings),* , binding] $($args),*)
783    }};
784    (@bind [$logger:expr, $fmt:expr] [$($bindings:expr),*]) => {
785        $logger(format_args!($fmt, $($bindings),*))
786    };
787}
788
789#[derive(Clone, Copy, Debug)]
790pub struct LogLineCachedState(u8);
791const LOG_LINE_ENABLED: u8 = 1 << 7;
792
793impl Default for LogLineCachedState {
794    fn default() -> Self {
795        Self::new()
796    }
797}
798
799impl LogLineCachedState {
800    pub const fn new() -> Self {
801        Self(0)
802    }
803    #[inline(always)]
804    pub fn version(&self) -> u8 {
805        self.0 & !LOG_LINE_ENABLED
806    }
807    #[inline(always)]
808    pub fn enabled(&self) -> bool {
809        self.0 & LOG_LINE_ENABLED != 0
810    }
811    #[inline(always)]
812    pub fn set(&mut self, version: u8, enabled: bool) {
813        self.0 = version;
814        if enabled {
815            self.0 |= LOG_LINE_ENABLED
816        }
817    }
818}
819
820#[macro_export]
821macro_rules! _log_enabled {
822    ($logger:expr, $lvl:expr) => {{
823        let logger = $logger.borrow_mut();
824        if !logger.enabled($crate::logging::Metadata {
825            level: $lvl,
826            target: module_path!(),
827        }) {
828            return;
829        }
830        logger
831    }};
832}
833
834#[macro_export]
835macro_rules! _log {
836    ($lvl:expr, $format:expr $(, $args:expr)*) => {{
837        $crate::logging::LOGGER.with(|logger| {
838            let mut logger = $crate::_log_enabled!(logger, $lvl);
839            let (pid, tag, inner) = logger.split();
840            let (now, precise_time) = $crate::logging::now();
841
842            $crate::_prompt_log!{
843                logger: |args| inner.log(args),
844                is_access: false,
845                condition: inner.colored,
846                prompt: [now, precise_time, pid, $lvl, tag],
847                standard: {
848                    formats: [$format, '\n'],
849                    args: [$($args),*]
850                }
851            };
852        })
853    }};
854}
855
856#[macro_export]
857macro_rules! _log_access {
858    ($lvl:expr, $on_failure:block, $($request_record_fields:tt)*) => {{
859         $crate::logging::LOGGER.with(|logger| {
860            let success = {
861                let mut logger = $crate::_log_enabled!(logger, $lvl);
862                let (pid, tag, inner) = logger.split();
863                let (now, precise_time) = $crate::logging::now();
864
865                inner.log_access(
866                    $crate::_structured_access_log!(
867                        [$crate::logging::RequestRecord]
868                        pid, tag, now, precise_time, level: $lvl, $($request_record_fields)*
869                    )
870                )
871            }; // logger dropped here
872
873            if !success {
874                // recording this metric may borrow the logger, so we have
875                // to perform this action after the block above
876                $on_failure
877            }
878        });
879    }};
880}
881
882#[macro_export]
883macro_rules! _structured_access_log {
884    ([$($struct_name:tt)+] $($fields:tt)*) => {{
885        $($struct_name)+ {$(
886            $fields
887        )*}
888    }};
889}
890
891#[macro_export]
892/// dynamically chose between info_access and error_access
893macro_rules! log_access {
894    ($error:expr, on_failure: $on_failure:block, $($request_record_fields:tt)*) => {
895        let lvl = if $error {
896            $crate::logging::LogLevel::Error
897        } else {
898            $crate::logging::LogLevel::Info
899        };
900        _log_access!(lvl, $on_failure, $($request_record_fields)*);
901    };
902}
903
904/// log a failure concerning an HTTP or TCP request
905#[macro_export]
906macro_rules! error_access {
907    (on_failure: $on_failure:block, $($request_record_fields:tt)*) => {
908        $crate::_log_access!($crate::logging::LogLevel::Error, $on_failure, $($request_record_fields)*);
909    };
910}
911
912/// log the success of an HTTP or TCP request
913#[macro_export]
914macro_rules! info_access {
915    (on_failure: $on_failure:block, $($request_record_fields:tt)*) => {
916        $crate::_log_access!($crate::logging::LogLevel::Info, $on_failure, $($request_record_fields)*);
917    };
918}
919
920/// log an error with Sōzu's custom log stack
921#[macro_export]
922macro_rules! error {
923    ($format:expr $(, $args:expr)* $(,)?) => {
924        $crate::_log!($crate::logging::LogLevel::Error, $format $(, $args)*)
925    };
926}
927
928/// log a warning with Sōzu’s custom log stack
929#[macro_export]
930macro_rules! warn {
931    ($format:expr $(, $args:expr)* $(,)?) => {
932        $crate::_log!($crate::logging::LogLevel::Warn, $format $(, $args)*)
933    };
934}
935
936/// log an info with Sōzu’s custom log stack
937#[macro_export]
938macro_rules! info {
939    ($format:expr $(, $args:expr)* $(,)?) => {
940        $crate::_log!($crate::logging::LogLevel::Info, $format $(, $args)*)
941    };
942}
943
944/// log a debug with Sōzu’s custom log stack
945#[macro_export]
946macro_rules! debug {
947    ($format:expr $(, $args:expr)* $(,)?) => {{
948        #[cfg(any(debug_assertions, feature = "logs-debug", feature = "logs-trace"))]
949        $crate::_log!($crate::logging::LogLevel::Debug, concat!("{}\t", $format), module_path!() $(, $args)*);
950        #[cfg(not(any(debug_assertions, feature = "logs-trace")))]
951        if false {$( let _ = $args; )*}
952    }};
953}
954
955/// log a trace with Sōzu’s custom log stack
956#[macro_export]
957macro_rules! trace {
958    ($format:expr $(, $args:expr)* $(,)?) => {{
959        #[cfg(any(debug_assertions, feature = "logs-trace"))]
960        $crate::_log!($crate::logging::LogLevel::Trace, concat!("{}\t", $format), module_path!() $(, $args)*);
961        #[cfg(not(any(debug_assertions, feature = "logs-trace")))]
962        if false {$( let _ = $args; )*}
963    }};
964}
965
966/// write a log with a "FIXME" prefix on an info level
967#[macro_export]
968macro_rules! fixme {
969    ($(, $args:expr)* $(,)?) => {
970        $crate::_log!($crate::logging::LogLevel::Info, "FIXME: {}:{} in {}: {}", file!(), line!(), module_path!() $(, $args)*)
971    };
972}
973
974pub struct CompatLogger;
975
976impl From<log::Level> for LogLevel {
977    fn from(lvl: log::Level) -> Self {
978        match lvl {
979            log::Level::Error => LogLevel::Error,
980            log::Level::Warn => LogLevel::Warn,
981            log::Level::Info => LogLevel::Info,
982            log::Level::Debug => LogLevel::Debug,
983            log::Level::Trace => LogLevel::Trace,
984        }
985    }
986}
987
988impl log::Log for CompatLogger {
989    fn enabled(&self, _: &log::Metadata) -> bool {
990        true
991    }
992
993    fn log(&self, record: &log::Record) {
994        LOGGER.with(|logger| {
995            let mut logger = logger.borrow_mut();
996            if !logger.compat_enabled(record.metadata()) {
997                return;
998            }
999            let (pid, tag, inner) = logger.split();
1000            let (now, precise_time) = now();
1001            crate::_prompt_log! {
1002                logger: |args| inner.log(args),
1003                is_access: false,
1004                condition: inner.colored,
1005                prompt: [
1006                    now, precise_time, pid, LogLevel::from(record.level()), tag
1007                ],
1008                standard: {
1009                    formats: ["{}\n"],
1010                    args: [record.args()]
1011                }
1012            };
1013        })
1014    }
1015
1016    fn flush(&self) {}
1017}
1018
1019/// start a logger used in test environment
1020#[macro_export]
1021macro_rules! setup_test_logger {
1022    () => {
1023        let _ = $crate::logging::Logger::init(
1024            module_path!().to_string(),
1025            "error",
1026            sozu_command_lib::config::DEFAULT_LOG_TARGET,
1027            false,
1028            None,
1029            None,
1030            None,
1031        );
1032    };
1033}
1034
1035pub struct Rfc3339Time {
1036    pub inner: ::time::OffsetDateTime,
1037}
1038
1039/// yields (Rfc3339Time, unix_epoch)
1040pub fn now() -> (Rfc3339Time, i128) {
1041    let t = time::OffsetDateTime::now_utc();
1042    (
1043        Rfc3339Time { inner: t },
1044        (t - time::OffsetDateTime::UNIX_EPOCH).whole_nanoseconds(),
1045    )
1046}
sozu_command_lib/logging/logs.rs

sozu_command_lib/logging/
logs.rs
