syd 3.42.0

//
// Syd: rock-solid application kernel
// src/log.rs: Simple logging on standard error using JSON lines
//
// Copyright (c) 2023, 2024, 2025 Ali Polatel <alip@chesswob.org>
// Based in part upon musl's src/time/__secs_to_tm.c which is:
//   Copyright © 2005-2020 Rich Felker, et al.
//   SPDX-License-Identifier: MIT
//
// SPDX-License-Identifier: GPL-3.0

use std::{
    fmt,
    io::Write,
    os::fd::{BorrowedFd, RawFd},
    sync::OnceLock,
    thread::ThreadId,
    time::{SystemTime, UNIX_EPOCH},
};

use btoi::btoi;
use data_encoding::HEXLOWER;
use nix::{
    errno::Errno,
    unistd::{write, Pid, Uid},
};
use serde_json::{Map, Value};

use crate::{
    config::*,
    err::SydResult,
    fs::is_active_fd,
    ofd::{lock_fd, unlock_fd},
    proc::{proc_cmdline, proc_comm, proc_cwd, proc_tty},
    retry::retry_on_eintr,
    syslog::LogLevel,
};

/// Formatted print which returns Result as Errno rather than panicking.
#[macro_export]
macro_rules! printf {
    () => {{}};
    ($($arg:tt)*) => {{
        use ::std::io::Write as _;
        let __s = format!($($arg)*);
        ::std::io::stdout().write_all(__s.as_bytes())
            .map_err(|error| $crate::err::err2no(&error))
    }};
}

/// Formatted println which returns Result as Errno rather than panicking.
#[macro_export]
macro_rules! printfln {
    () => {{
        use ::std::io::Write as _;
        ::std::io::stdout().write_all(b"\n")
            .map_err(|error| $crate::err::err2no(&error))
    }};
    ($($arg:tt)*) => {{
        use ::std::io::Write as _;
        let mut __s = format!($($arg)*);
        __s.push('\n');
        ::std::io::stdout().write_all(__s.as_bytes())
            .map_err(|error| $crate::err::err2no(&error))
    }};
}

// Whether we concluded the output is a TTY.
pub(crate) static LOG_TTY: std::sync::atomic::AtomicBool =
    std::sync::atomic::AtomicBool::new(false);
// Log destination file descriptor.
pub(crate) static LOG_FD: std::sync::atomic::AtomicI32 = std::sync::atomic::AtomicI32::new(-42);

// Main thread identifier, used to decide on panic hook.
pub(crate) static LOG_MAIN_TID: OnceLock<ThreadId> = OnceLock::new();

// Set this in main thread after namespace forks and other dances.
pub(crate) fn log_init_main() -> SydResult<()> {
    LOG_MAIN_TID
        .set(std::thread::current().id())
        .map_err(|_| Errno::EBUSY.into())
}

// Sets the global panic hook for Syd threads.
pub(crate) fn log_set_panic_hook() {
    // Set a logging panic hook. The default panic
    // hook calls system calls not permitted by emulators
    // such as getcwd(2), stat(2) etc.
    #[expect(clippy::cognitive_complexity)]
    std::panic::set_hook(Box::new(|info| {
        let this = std::thread::current();
        let name = this.name().unwrap_or("?");

        let err = match info.payload().downcast_ref::<&'static str>() {
            Some(s) => *s,
            None => match info.payload().downcast_ref::<String>() {
                Some(s) => &**s,
                None => "?",
            },
        };

        let file = info.location().map(|l| l.file());
        let line = info.location().map(|l| l.line());

        if log_is_main() {
            // Main thread panicking isn't recoverable unlike others.
            // Ensure clean exit right away.
            crate::alert!("ctx": "panic",
                "op": "panic_syd_main_thread",
                "msg": err, "file": file, "line": line);
            std::process::exit(101);
        } else {
            crate::crit!("ctx": "panic",
                "op": format!("panic_{name}_thread"),
                "msg": err, "file": file, "line": line);
        }
    }));
}

// Use this to check for main thread in panic handler.
#[inline]
fn log_is_main() -> bool {
    LOG_MAIN_TID
        .get()
        .map(|&tid| tid == std::thread::current().id())
        .unwrap_or(false)
}

/// emerg! logging macro
#[macro_export]
macro_rules! emerg {
    ($($key:literal : $value:expr),+) => {
        if $crate::log_enabled!($crate::syslog::LogLevel::Emergent) {
            let timestamp = $crate::log::now();
            let mut map = serde_json::Map::new();
            $(
                if let Ok(value) = serde_json::to_value($value) {
                    map.insert($key.to_string(), value);
                } else {
                    map.insert($key.to_string(), serde_json::Value::Null);
                }
            )+
            if !map.is_empty() {
                $crate::log::log($crate::syslog::LogLevel::Emergent, timestamp, map);
            }
        }
    }
}

/// alert! logging macro
#[macro_export]
macro_rules! alert {
    ($($key:literal : $value:expr),+) => {
        if $crate::log_enabled!($crate::syslog::LogLevel::Alert) {
            let timestamp = $crate::log::now();
            let mut map = serde_json::Map::new();
            $(
                if let Ok(value) = serde_json::to_value($value) {
                    map.insert($key.to_string(), value);
                } else {
                    map.insert($key.to_string(), serde_json::Value::Null);
                }
            )+
            if !map.is_empty() {
                $crate::log::log($crate::syslog::LogLevel::Alert, timestamp, map);
            }
        }
    }
}

/// crit! logging macro
#[macro_export]
macro_rules! crit {
    ($($key:literal : $value:expr),+) => {
        if $crate::log_enabled!($crate::syslog::LogLevel::Crit) {
            let timestamp = $crate::log::now();
            let mut map = serde_json::Map::new();
            $(
                if let Ok(value) = serde_json::to_value($value) {
                    map.insert($key.to_string(), value);
                } else {
                    map.insert($key.to_string(), serde_json::Value::Null);
                }
            )+
            if !map.is_empty() {
                $crate::log::log($crate::syslog::LogLevel::Crit, timestamp, map);
            }
        }
    }
}

/// error! logging macro
#[macro_export]
macro_rules! error {
    ($($key:literal : $value:expr),+) => {
        if $crate::log_enabled!($crate::syslog::LogLevel::Err) {
            let timestamp = $crate::log::now();
            let mut map = serde_json::Map::new();
            $(
                if let Ok(value) = serde_json::to_value($value) {
                    map.insert($key.to_string(), value);
                } else {
                    map.insert($key.to_string(), serde_json::Value::Null);
                }
            )+
            if !map.is_empty() {
                $crate::log::log($crate::syslog::LogLevel::Err, timestamp, map);
            }
        }
    }
}

/// warn! logging macro
#[macro_export]
macro_rules! warn {
    ($($key:literal : $value:expr),+) => {
        if $crate::log_enabled!($crate::syslog::LogLevel::Warn) {
            let timestamp = $crate::log::now();
            let mut map = serde_json::Map::new();
            $(
                if let Ok(value) = serde_json::to_value($value) {
                    map.insert($key.to_string(), value);
                } else {
                    map.insert($key.to_string(), serde_json::Value::Null);
                }
            )+
            if !map.is_empty() {
                $crate::log::log($crate::syslog::LogLevel::Warn, timestamp, map);
            }
        }
    }
}

/// notice! logging macro
#[macro_export]
macro_rules! notice {
    ($($key:literal : $value:expr),+) => {
        if $crate::log_enabled!($crate::syslog::LogLevel::Notice) {
            let timestamp = $crate::log::now();
            let mut map = serde_json::Map::new();
            $(
                if let Ok(value) = serde_json::to_value($value) {
                    map.insert($key.to_string(), value);
                } else {
                    map.insert($key.to_string(), serde_json::Value::Null);
                }
            )+
            if !map.is_empty() {
                $crate::log::log($crate::syslog::LogLevel::Notice, timestamp, map);
            }
        }
    }
}

/// info! logging macro
#[macro_export]
macro_rules! info {
    ($($key:literal : $value:expr),+) => {
        if $crate::log_enabled!($crate::syslog::LogLevel::Info) {
            let timestamp = $crate::log::now();
            let mut map = serde_json::Map::new();
            $(
                if let Ok(value) = serde_json::to_value($value) {
                    map.insert($key.to_string(), value);
                } else {
                    map.insert($key.to_string(), serde_json::Value::Null);
                }
            )+
            if !map.is_empty() {
                $crate::log::log($crate::syslog::LogLevel::Info, timestamp, map);
            }
        }
    }
}

/// debug! logging macro
#[macro_export]
macro_rules! debug {
    ($($key:literal : $value:expr),+) => {
        if $crate::log_enabled!($crate::syslog::LogLevel::Debug) {
            let timestamp = $crate::log::now();
            let mut map = serde_json::Map::new();
            $(
                if let Ok(value) = serde_json::to_value($value) {
                    map.insert($key.to_string(), value);
                } else {
                    map.insert($key.to_string(), serde_json::Value::Null);
                }
            )+
            if !map.is_empty() {
                $crate::log::log($crate::syslog::LogLevel::Debug, timestamp, map);
            }
        }
    }
}

// A wrapper that implements Write for a raw fd, but does not close it
// on drop. We can then use standard .write_all(...) to handle EINTR.
pub(crate) struct LockedWriter<'a> {
    fd: BorrowedFd<'a>,
}

impl<'a> LockedWriter<'a> {
    pub(crate) fn new(fd: BorrowedFd<'a>) -> Result<Self, Errno> {
        retry_on_eintr(|| lock_fd(fd, true, true))?;
        Ok(Self { fd })
    }
}

impl Drop for LockedWriter<'_> {
    fn drop(&mut self) {
        let _ = self.flush();
        let _ = unlock_fd(self.fd);
    }
}

impl Write for LockedWriter<'_> {
    fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
        write(self.fd, buf).map_err(|e| std::io::Error::from_raw_os_error(e as i32))
    }

    fn flush(&mut self) -> std::io::Result<()> {
        Ok(())
    }
}

/// Initializes Syslog global object, reading environment variables.
#[cfg(feature = "log")]
#[expect(clippy::cognitive_complexity)]
pub fn log_init(default_level: LogLevel, default_log_fd: Option<RawFd>) -> Result<(), Errno> {
    use std::os::unix::ffi::OsStrExt;

    use crate::syslog::{init_global_syslog, parse_loglevel};

    // Parse the desired console log level from ENV_LOG,
    // or use default_level if not set/invalid.
    let level = if let Some(val) = std::env::var_os(ENV_LOG) {
        parse_loglevel(val.as_os_str().as_bytes(), default_level)
    } else {
        default_level
    };

    // Determine the main FD for logging:
    // By default, we use stderr.
    // If ENV_LOG_FD is set, we parse it:
    // 1. negative fd is ok as a shorthand to disable logging.
    // 2. positive fd must be a valid fd or we bail with EBADF.
    let fd = match std::env::var_os(ENV_LOG_FD) {
        None => default_log_fd,
        Some(val) => {
            let fd = btoi::<RawFd>(val.as_os_str().as_bytes()).map_err(|_| Errno::EBADF)?;
            if fd >= 0 {
                // SAFETY: fd only used after validation.
                let fd = unsafe { BorrowedFd::borrow_raw(fd) };
                if !is_active_fd(fd) {
                    return Err(Errno::EBADF);
                }
            }
            Some(fd)
        }
    };
    if let Some(fd) = fd {
        LOG_FD.store(fd, std::sync::atomic::Ordering::Relaxed);
    }

    // Decide if we want a TTY-like console.
    let mut tty = std::env::var_os(ENV_FORCE_TTY).is_some();
    if !tty {
        if std::env::var_os(ENV_QUIET_TTY).is_none() {
            let fd = fd.unwrap_or(libc::STDERR_FILENO);
            // Check if log FD is a TTY.
            // SAFETY: In libc we trust.
            tty = unsafe { libc::isatty(fd) } == 1;
        } else {
            tty = false;
        }
    }

    // Record TTY information to an atomic for easy access.
    LOG_TTY.store(tty, std::sync::atomic::Ordering::Relaxed);

    // Allocate the syslog(2) ring buffer on the stack by default.
    // The size is architecture-dependent, see config.rs.
    //
    // If the user specifies an alternative capacity with `SYD_LOG_BUF_LEN`,
    // parse this size using parse-size and use it instead.
    let mut logbuflen = 0usize;
    let mut use_stack = true;
    if let Some(var) = std::env::var_os(ENV_LOG_BUF_LEN) {
        logbuflen = parse_size::Config::new()
            .with_binary()
            .parse_size(var.as_bytes())
            .or(Err(Errno::EINVAL))?
            .try_into()
            .or(Err(Errno::EINVAL))?;
        use_stack = false;
    }
    init_global_syslog(logbuflen, fd, level, use_stack)?;

    // Finally let's make some noise!
    //
    // ENV_SING avoids duplicating this message over memfd-reexec.
    if std::env::var_os(ENV_SING).is_none() {
        info!("ctx": "init", "op": "sing", "chapter": 24,
            "msg": "Change return success. Going and coming without error. Action brings good fortune.");
        std::env::set_var(ENV_SING, "");
    }

    Ok(())
}

/// A simpler variant that turns off host syslog from the start and
/// locks the ring buffer.  This can be used by small utilities that do
/// not want the ring buffer overhead.
#[cfg(feature = "log")]
pub fn log_init_simple(default_level: LogLevel) -> Result<(), Errno> {
    use std::os::unix::ffi::OsStrExt;

    use crate::syslog::{global_syslog, init_global_syslog, parse_loglevel};

    // Parse the desired console log level from ENV_LOG,
    // or use default_level if not set/invalid.
    let level = if let Some(val) = std::env::var_os(ENV_LOG) {
        parse_loglevel(val.as_os_str().as_bytes(), default_level)
    } else {
        default_level
    };

    // Determine the main FD for logging:
    // By default, we use stderr.
    // If ENV_LOG_FD is set, we parse it:
    // 1. negative fd is ok as a shorthand to disable logging.
    // 2. positive fd must be a valid fd or we bail with EBADF.
    let fd = match std::env::var_os(ENV_LOG_FD) {
        None => libc::STDERR_FILENO,
        Some(val) => {
            let fd = btoi::<RawFd>(val.as_os_str().as_bytes()).map_err(|_| Errno::EBADF)?;
            if fd >= 0 {
                // SAFETY: fd only used after validation.
                let fd = unsafe { BorrowedFd::borrow_raw(fd) };
                if !is_active_fd(fd) {
                    return Err(Errno::EBADF);
                }
            }
            fd
        }
    };
    LOG_FD.store(fd, std::sync::atomic::Ordering::Relaxed);

    // Decide if we want a TTY-like console.
    let mut tty = std::env::var_os(ENV_FORCE_TTY).is_some();
    if !tty {
        if std::env::var_os(ENV_QUIET_TTY).is_none() {
            // Check if log FD is a TTY.
            // SAFETY: In libc we trust.
            tty = unsafe { libc::isatty(fd) } == 1;
        } else {
            tty = false;
        }
    }

    // Record TTY information to an atomic for easy access.
    LOG_TTY.store(tty, std::sync::atomic::Ordering::Relaxed);

    // Create a global syslog with ring.
    init_global_syslog(0, Some(fd), level, true)?;

    if let Some(sys) = global_syslog() {
        // Now lock it immediately,
        // so ring is unavailable.
        sys.lock();
    }

    Ok(())
}

/// Main entry point for appending log entries in JSON-line style.
#[cfg(feature = "log")]
#[expect(clippy::cognitive_complexity)]
pub fn log(level: crate::syslog::LogLevel, timestamp: u64, mut msg: Map<String, Value>) {
    let sys = if let Some(sys) = crate::syslog::global_syslog() {
        sys
    } else {
        return; // Logging is disabled.
    };

    // For "higher" severities, we add more contextual fields.
    let add_context = level.as_u8() <= crate::syslog::LogLevel::Notice.as_u8();
    let tty = LOG_TTY.load(std::sync::atomic::Ordering::Relaxed);

    // If there's a "pid", we might add cmd/cwd, etc.
    // We remove and re-add to reorder for better visibility.
    if let Some(pid_v) = msg.remove("pid").and_then(|v| v.as_i64()) {
        #[expect(clippy::cast_possible_truncation)]
        let pid = Pid::from_raw(pid_v as libc::pid_t);
        if pid.as_raw() != 0 {
            if add_context {
                if let Ok(cmd) = proc_cmdline(pid) {
                    msg.insert("cmd".to_string(), cmd.to_string().into());
                }
            } else if let Ok(cmd) = proc_comm(pid) {
                msg.insert("cmd".to_string(), cmd.to_string().into());
            }
            if let Ok(dir) = proc_cwd(pid) {
                msg.insert("cwd".to_string(), dir.to_string().into());
            }
            if add_context {
                if let Ok(tty) = proc_tty(pid) {
                    msg.insert("tty".to_string(), tty.to_string().into());
                }
            }
        }
        msg.insert("pid".to_string(), pid.as_raw().into());
    }

    // Add current user if add_context.
    if add_context {
        msg.insert("uid".to_string(), Uid::current().as_raw().into());
    }

    // Add "syd" = current thread ID.
    let syd = nix::unistd::gettid().as_raw().into();
    msg.insert("syd".to_string(), Value::Number(syd));

    // Add ISO8601 date, fallback to timestamp.
    if let Ok(date) = format_iso8601(timestamp) {
        msg.insert("time".to_string(), date.into());
    } else {
        msg.insert("time".to_string(), timestamp.into());
    }

    // Reorder req and informational fields for better visibility.
    if let Some(src) = msg.remove("req") {
        msg.insert("req".to_string(), src);
    }
    if let Some(m) = msg.remove("msg") {
        msg.insert("msg".to_string(), m);
    }
    if let Some(tip) = msg.remove("tip") {
        msg.insert("tip".to_string(), tip);
    }

    // Remove NULL elements to save space.
    msg.retain(|_, value| !value.is_null());

    // Convert to JSON line.
    let msg_data = serde_json::to_string(&msg).unwrap_or_else(|e| {
        let e = serde_json::to_string(&format!("{e:?}")).unwrap_or("?".to_string());
        format!("{{\"ctx\":\"log\",\"op\":\"serialize\",\"error\": \"{e}\"}}")
    });
    let msg_pretty = if tty {
        // A "pretty" output for TTY.
        Some(serde_json::to_string_pretty(&msg).unwrap_or_else(|e| {
            let e = serde_json::to_string(&format!("{e:?}")).unwrap_or("?".to_string());
            format!("{{\"ctx\":\"log\",\"op\":\"serialize\",\"error\": \"{e}\"}}")
        }))
    } else {
        None
    };

    sys.write_log(level, &msg_data, msg_pretty.as_deref());
}

/// Initializes Syslog global object, reading environment variables.
#[cfg(not(feature = "log"))]
#[inline(always)]
#[expect(clippy::cognitive_complexity)]
pub fn log_init(_default_level: LogLevel, default_log_fd: Option<RawFd>) -> Result<(), Errno> {
    use std::os::unix::ffi::OsStrExt;

    // Determine the main FD for logging:
    // By default, we use stderr.
    // If ENV_LOG_FD is set, we parse it:
    // 1. negative fd is ok as a shorthand to disable logging.
    // 2. positive fd must be a valid fd or we bail with EBADF.
    let fd = match std::env::var_os(ENV_LOG_FD) {
        None => default_log_fd,
        Some(val) => {
            let fd = btoi::<RawFd>(val.as_os_str().as_bytes()).map_err(|_| Errno::EBADF)?;
            if fd >= 0 {
                // SAFETY: fd only used after validation.
                let fd = unsafe { BorrowedFd::borrow_raw(fd) };
                if !is_active_fd(fd) {
                    return Err(Errno::EBADF);
                }
            }
            Some(fd)
        }
    };
    if let Some(fd) = fd {
        LOG_FD.store(fd, std::sync::atomic::Ordering::Relaxed);
    }

    // Decide if we want a TTY-like console.
    let mut tty = std::env::var_os(ENV_FORCE_TTY).is_some();
    if !tty {
        if std::env::var_os(ENV_QUIET_TTY).is_none() {
            let fd = fd.unwrap_or(libc::STDERR_FILENO);
            // Check if log FD is a TTY.
            // SAFETY: In libc we trust.
            tty = unsafe { libc::isatty(fd) } == 1;
        } else {
            tty = false;
        }
    }

    // Record TTY information to an atomic for easy access.
    LOG_TTY.store(tty, std::sync::atomic::Ordering::Relaxed);

    // Determine the main FD for logging:
    // By default, we use stderr.
    // If ENV_LOG_FD is set, we parse it:
    // 1. negative fd is ok as a shorthand to disable logging.
    // 2. positive fd must be a valid fd or we bail with EBADF.
    let fd = match std::env::var_os(ENV_LOG_FD) {
        None => default_log_fd,
        Some(val) => {
            let fd = btoi::<RawFd>(val.as_os_str().as_bytes()).map_err(|_| Errno::EBADF)?;
            if fd >= 0 {
                // SAFETY: fd only used after validation.
                let fd = unsafe { BorrowedFd::borrow_raw(fd) };
                if !is_active_fd(fd) {
                    return Err(Errno::EBADF);
                }
            }
            Some(fd)
        }
    };
    if let Some(fd) = fd {
        LOG_FD.store(fd, std::sync::atomic::Ordering::Relaxed);
    }

    // Finally let's make some noise!
    //
    // ENV_SING avoids duplicating this message over memfd-reexec.
    if std::env::var_os(ENV_SING).is_none() {
        info!("ctx": "init", "op": "sing", "chapter": 24,
            "msg": "Change return success. Going and coming without error. Action brings good fortune.");
        std::env::set_var(ENV_SING, "");
    }

    Ok(())
}

/// A simpler variant that turns off host syslog from the start and
/// locks the ring buffer.  This can be used by small utilities that do
/// not want the ring buffer overhead.
#[cfg(not(feature = "log"))]
#[inline(always)]
pub fn log_init_simple(default_level: LogLevel) -> Result<(), Errno> {
    log_init(default_level, Some(libc::STDERR_FILENO))
}

/// Main entry point for appending log entries in JSON-line style.
#[cfg(not(feature = "log"))]
#[expect(clippy::cognitive_complexity)]
pub fn log(level: crate::syslog::LogLevel, timestamp: u64, mut msg: Map<String, Value>) {
    // Setting LOG-FD to negative is OK to disable logging.
    let fd = LOG_FD.load(std::sync::atomic::Ordering::Relaxed);
    let fd = if fd < 0 {
        return; // Logging is disabled.
    } else {
        // SAFETY: we trust log fd is valid.
        unsafe { BorrowedFd::borrow_raw(fd) }
    };

    // For "higher" severities, we add more contextual fields.
    let add_context = level.as_u8() <= crate::syslog::LogLevel::Notice.as_u8();
    let tty = LOG_TTY.load(std::sync::atomic::Ordering::Relaxed);

    // If there's a "pid", we might add cmd/cwd, etc.
    // We remove and re-add to reorder for better visibility.
    if let Some(pid_v) = msg.remove("pid").and_then(|v| v.as_i64()) {
        #[expect(clippy::cast_possible_truncation)]
        let pid = Pid::from_raw(pid_v as libc::pid_t);
        if pid.as_raw() != 0 {
            if add_context {
                if let Ok(cmd) = proc_cmdline(pid) {
                    msg.insert("cmd".to_string(), cmd.to_string().into());
                }
            } else if let Ok(cmd) = proc_comm(pid) {
                msg.insert("cmd".to_string(), cmd.to_string().into());
            }
            if let Ok(dir) = proc_cwd(pid) {
                msg.insert("cwd".to_string(), dir.to_string().into());
            }
            if add_context {
                if let Ok(tty) = proc_tty(pid) {
                    msg.insert("tty".to_string(), tty.to_string().into());
                }
            }
        }
        msg.insert("pid".to_string(), pid.as_raw().into());
    }

    // Add current user if add_context.
    if add_context {
        msg.insert("uid".to_string(), Uid::current().as_raw().into());
    }

    // Add "syd" = current thread ID.
    let syd = nix::unistd::gettid().as_raw().into();
    msg.insert("syd".to_string(), Value::Number(syd));

    // Add ISO8601 date, fallback to timestamp.
    if let Ok(date) = format_iso8601(timestamp) {
        msg.insert("time".to_string(), date.into());
    } else {
        msg.insert("time".to_string(), timestamp.into());
    }

    // Reorder req and informational fields for better visibility.
    if let Some(src) = msg.remove("req") {
        msg.insert("req".to_string(), src);
    }
    if let Some(m) = msg.remove("msg") {
        msg.insert("msg".to_string(), m);
    }
    if let Some(tip) = msg.remove("tip") {
        msg.insert("tip".to_string(), tip);
    }

    // Remove NULL elements to save space.
    msg.retain(|_, value| !value.is_null());

    // Convert to JSON line
    let msg_data = serde_json::to_string(&msg).unwrap_or_else(|e| {
        let e = serde_json::to_string(&format!("{e:?}")).unwrap_or("?".to_string());
        format!("{{\"ctx\":\"log\",\"op\":\"serialize\",\"error\": \"{e}\"}}")
    });

    let msg_info = if tty {
        // A "pretty" output for TTY.
        Some(serde_json::to_string_pretty(&msg).unwrap_or_else(|e| {
            let e = serde_json::to_string(&format!("{e:?}")).unwrap_or("?".to_string());
            format!("{{\"ctx\":\"log\",\"op\":\"serialize\",\"error\": \"{e}\"}}")
        }))
    } else {
        None
    };

    // Finally, log to fd or standard error.
    if let Ok(mut writer) = LockedWriter::new(fd).map(std::io::BufWriter::new) {
        if let Some(ref msg) = msg_info {
            let _ = writer.write_all(msg.as_bytes());
        } else {
            let _ = writer.write_all(msg_data.as_bytes());
        }
        let _ = writer.write_all(b"\n");
    }
}

/// Return the current time in seconds since the unix epoch.
pub fn now() -> u64 {
    SystemTime::now()
        .duration_since(UNIX_EPOCH)
        .unwrap_or_default()
        .as_secs()
}

/// Returns current time as a compact ISO8601-formatted string.
///
/// The format is currently "YYYYMMDDThhmmssZ". The format may change in
/// the future but it will always remain conformant to the ISO8601
/// standard.
fn format_iso8601(timestamp: u64) -> Result<String, Errno> {
    let t = i64::try_from(timestamp).or(Err(Errno::EINVAL))?;
    let t: Tm = t.try_into()?;
    Ok(t.to_string())
}

/// Logs an untrusted buffer, escaping it as hex if it contains control characters.
/// Returns a boolean in addition to the String which is true if String is hex-encoded.
pub fn log_untrusted_buf(buf: &[u8]) -> (String, bool) {
    if contains_ascii_unprintable(buf) {
        (HEXLOWER.encode(buf), true)
    } else if let Ok(s) = std::str::from_utf8(buf) {
        (s.to_string(), false)
    } else {
        (HEXLOWER.encode(buf), true)
    }
}

/// Checks if the buffer contains ASCII unprintable characters.
pub fn contains_ascii_unprintable(buf: &[u8]) -> bool {
    buf.iter().any(|byte| !is_ascii_printable(*byte))
}

/// Checks if the given character is ASCII printable.
pub fn is_ascii_printable(byte: u8) -> bool {
    (0x20..=0x7e).contains(&byte)
}

/// Rust port of musl's `struct tm`.
#[derive(Clone, Copy, Debug, Eq, PartialEq, Hash)]
pub struct Tm {
    tm_year: i32, // years since 1900
    tm_mon: i32,  // 0..11
    tm_mday: i32, // 1..31
    tm_wday: i32, // 0..6, Sunday=0
    tm_yday: i32, // 0..365
    tm_hour: i32, // 0..23
    tm_min: i32,  // 0..59
    tm_sec: i32,  // 0..60 (leap second tolerated like musl)
}

impl Tm {
    /// Get the year of the date.
    pub fn year(&self) -> i32 {
        self.tm_year.saturating_add(1900)
    }

    /// Get the month of the date.
    pub fn month(&self) -> i32 {
        self.tm_mon.saturating_add(1)
    }

    /// Get the month day of the date.
    pub fn day(&self) -> i32 {
        self.tm_mday
    }

    /// Get the week day of the date, where Sunday=0.
    pub fn weekday(&self) -> i32 {
        self.tm_wday
    }

    /// Get the hour of the date.
    pub fn hour(&self) -> i32 {
        self.tm_hour
    }

    /// Get the minute of the date.
    pub fn minute(&self) -> i32 {
        self.tm_min
    }

    /// Get the second of the date.
    pub fn second(&self) -> i32 {
        self.tm_sec
    }
}

impl TryFrom<i64> for Tm {
    type Error = Errno;

    fn try_from(t: i64) -> Result<Self, Errno> {
        const LEAPOCH: i64 = 951_868_800; // 2000-03-01 00:00:00 UTC
        const SECS_PER_DAY: i64 = 86_400;
        const DAYS_PER_400Y: i64 = 146_097;
        const DAYS_PER_100Y: i64 = 36_524;
        const DAYS_PER_4Y: i64 = 1_461;

        // Reject time_t values whose year would overflow int.
        let limit_unit = 31_622_400i64; // 366 days in seconds
        let low = i64::from(i32::MIN)
            .checked_mul(limit_unit)
            .ok_or(Errno::EOVERFLOW)?;
        let high = i64::from(i32::MAX)
            .checked_mul(limit_unit)
            .ok_or(Errno::EOVERFLOW)?;
        if t < low || t > high {
            return Err(Errno::EOVERFLOW);
        }

        let secs = t.checked_sub(LEAPOCH).ok_or(Errno::EOVERFLOW)?;
        let mut days = secs.checked_div(SECS_PER_DAY).ok_or(Errno::EOVERFLOW)?;
        let mut remsecs = secs.checked_rem(SECS_PER_DAY).ok_or(Errno::EOVERFLOW)?;
        if remsecs < 0 {
            remsecs = remsecs.checked_add(SECS_PER_DAY).ok_or(Errno::EOVERFLOW)?;
            days = days.checked_sub(1).ok_or(Errno::EOVERFLOW)?;
        }

        // Weekday: 2000-03-01 was Wednesday (3)
        let mut wday = (3i64)
            .checked_add(days)
            .ok_or(Errno::EOVERFLOW)?
            .checked_rem(7)
            .ok_or(Errno::EOVERFLOW)?;
        if wday < 0 {
            wday = wday.checked_add(7).ok_or(Errno::EOVERFLOW)?;
        }

        // Gregorian cycles
        let mut qc_cycles = days.checked_div(DAYS_PER_400Y).ok_or(Errno::EOVERFLOW)?;
        let mut remdays = days.checked_rem(DAYS_PER_400Y).ok_or(Errno::EOVERFLOW)?;
        if remdays < 0 {
            remdays = remdays.checked_add(DAYS_PER_400Y).ok_or(Errno::EOVERFLOW)?;
            qc_cycles = qc_cycles.checked_sub(1).ok_or(Errno::EOVERFLOW)?;
        }

        let mut c_cycles = remdays.checked_div(DAYS_PER_100Y).ok_or(Errno::EOVERFLOW)?;
        if c_cycles == 4 {
            c_cycles = c_cycles.checked_sub(1).ok_or(Errno::EOVERFLOW)?;
        }
        remdays = remdays
            .checked_sub(
                c_cycles
                    .checked_mul(DAYS_PER_100Y)
                    .ok_or(Errno::EOVERFLOW)?,
            )
            .ok_or(Errno::EOVERFLOW)?;

        let mut q_cycles = remdays.checked_div(DAYS_PER_4Y).ok_or(Errno::EOVERFLOW)?;
        if q_cycles == 25 {
            q_cycles = q_cycles.checked_sub(1).ok_or(Errno::EOVERFLOW)?;
        }
        remdays = remdays
            .checked_sub(q_cycles.checked_mul(DAYS_PER_4Y).ok_or(Errno::EOVERFLOW)?)
            .ok_or(Errno::EOVERFLOW)?;

        let mut remyears = remdays.checked_div(365).ok_or(Errno::EOVERFLOW)?;
        if remyears == 4 {
            remyears = remyears.checked_sub(1).ok_or(Errno::EOVERFLOW)?;
        }
        remdays = remdays
            .checked_sub(remyears.checked_mul(365).ok_or(Errno::EOVERFLOW)?)
            .ok_or(Errno::EOVERFLOW)?;

        let leap = remyears == 0 && (q_cycles != 0 || c_cycles == 0);
        let leap_i = if leap { 1i64 } else { 0i64 };

        let mut yday = remdays
            .checked_add(59)
            .ok_or(Errno::EOVERFLOW)?
            .checked_add(leap_i)
            .ok_or(Errno::EOVERFLOW)?;
        let yday_lim = 365i64.checked_add(leap_i).ok_or(Errno::EOVERFLOW)?;
        if yday >= yday_lim {
            yday = yday.checked_sub(yday_lim).ok_or(Errno::EOVERFLOW)?;
        }

        let years = remyears
            .checked_add(4i64.checked_mul(q_cycles).ok_or(Errno::EOVERFLOW)?)
            .ok_or(Errno::EOVERFLOW)?
            .checked_add(100i64.checked_mul(c_cycles).ok_or(Errno::EOVERFLOW)?)
            .ok_or(Errno::EOVERFLOW)?
            .checked_add(400i64.checked_mul(qc_cycles).ok_or(Errno::EOVERFLOW)?)
            .ok_or(Errno::EOVERFLOW)?;

        // Month & day within "Mar..Feb" year layout.
        let dim: [i64; 12] = [31, 30, 31, 30, 31, 31, 30, 31, 30, 31, 31, 29];
        let mut months = 0i64;
        let mut rd = remdays;
        while months < 12 {
            let d = *dim
                .get(usize::try_from(months).or(Err(Errno::EOVERFLOW))?)
                .ok_or(Errno::EOVERFLOW)?;
            if d > rd {
                break;
            }
            rd = rd.checked_sub(d).ok_or(Errno::EOVERFLOW)?;
            months = months.checked_add(1).ok_or(Errno::EOVERFLOW)?;
        }

        let mut years_adj = years;
        let mut months_adj = months;
        if months_adj >= 10 {
            months_adj = months_adj.checked_sub(12).ok_or(Errno::EOVERFLOW)?;
            years_adj = years_adj.checked_add(1).ok_or(Errno::EOVERFLOW)?;
        }

        let years_plus_100 = years_adj.checked_add(100).ok_or(Errno::EOVERFLOW)?;
        if years_plus_100 > i64::from(i32::MAX) || years_plus_100 < i64::from(i32::MIN) {
            return Err(Errno::EOVERFLOW);
        }

        let hour = remsecs.checked_div(3600).ok_or(Errno::EOVERFLOW)?;
        let min = remsecs
            .checked_div(60)
            .ok_or(Errno::EOVERFLOW)?
            .checked_rem(60)
            .ok_or(Errno::EOVERFLOW)?;
        let sec = remsecs.checked_rem(60).ok_or(Errno::EOVERFLOW)?;

        Ok(Self {
            tm_year: i32::try_from(years_plus_100).or(Err(Errno::EOVERFLOW))?,
            tm_mon: i32::try_from(months_adj.checked_add(2).ok_or(Errno::EOVERFLOW)?)
                .or(Err(Errno::EOVERFLOW))?,
            tm_mday: i32::try_from(rd.checked_add(1).ok_or(Errno::EOVERFLOW)?)
                .or(Err(Errno::EOVERFLOW))?,
            tm_wday: i32::try_from(wday).or(Err(Errno::EOVERFLOW))?,
            tm_yday: i32::try_from(yday).or(Err(Errno::EOVERFLOW))?,
            tm_hour: i32::try_from(hour).or(Err(Errno::EOVERFLOW))?,
            tm_min: i32::try_from(min).or(Err(Errno::EOVERFLOW))?,
            tm_sec: i32::try_from(sec).or(Err(Errno::EOVERFLOW))?,
        })
    }
}

impl fmt::Display for Tm {
    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
        let year = self.year();
        let month = self.month();
        let day = self.day();
        let hour = self.hour();
        let minute = self.minute();
        let second = self.second();

        // Format: YYYYMMDDThhmmssZ
        write!(
            f,
            "{year:04}{month:02}{day:02}T{hour:02}{minute:02}{second:02}Z"
        )
    }
}