syd 3.52.0

//
// Syd: rock-solid application kernel
// src/log.rs: Simple logging on standard error using JSON lines
//
// Copyright (c) 2023, 2024, 2025, 2026 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::{AsFd, BorrowedFd, RawFd},
    sync::{atomic::Ordering, OnceLock},
    thread::ThreadId,
    time::{SystemTime, UNIX_EPOCH},
};

use btoi::btoi;
use data_encoding::HEXLOWER;
use lexis::ToName;
use libseccomp::ScmpArch;
use nix::{
    errno::Errno,
    unistd::{getpid, gettid, write, Pid, Uid},
};
use serde_json::{Map, Value};

use crate::{
    config::*,
    err::SydResult,
    fd::{is_active_fd, is_writable_fd},
    ioctl::{Ioctl, IoctlMap, IoctlName},
    ofd::{lock_fd, unlock_fd},
    proc::{proc_cmdline, proc_comm, proc_cwd, proc_tty},
    retry::retry_on_eintr,
    sandbox::Action,
    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();

// Validate log file descriptor.
fn validate_log_fd<Fd: AsFd>(fd: Fd) -> Result<(), Errno> {
    if !is_active_fd(&fd) {
        return Err(Errno::EBADF);
    }
    if !is_writable_fd(fd).unwrap_or(false) {
        return Err(Errno::EBADFD);
    }
    Ok(())
}

// 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());
        let main = log_is_main(this.id());
        let name = if main { "main" } else { name };

        if main {
            crate::alert!("ctx": "panic", "act": Action::Exit,
                "name": name, "msg": err, "file": file, "line": line);

            // Main thread panicking isn't recoverable unlike others.
            // Ensure clean exit right away.
            std::process::exit(101);
        } else {
            crate::crit!("ctx": "panic", "act": Action::Deny,
                "name": name, "msg": err, "file": file, "line": line);
        }
    }));
}

// Use this to check for main thread in panic handler.
pub(crate) fn log_is_main(tid: ThreadId) -> bool {
    LOG_MAIN_TID
        .get()
        .map(|&main_tid| main_tid == tid)
        .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")]
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.
    // 3. positive fd must be a writable fd or we bail with EBADFD.
    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` was parsed from the environment and
                // checked `>= 0`; only used momentarily for validation.
                let fd = unsafe { BorrowedFd::borrow_raw(fd) };
                validate_log_fd(fd)?;
            }
            Some(fd)
        }
    };
    if let Some(fd) = fd {
        LOG_FD.store(fd, 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);
            // SAFETY: `fd` is a valid fd (either `STDERR_FILENO`
            // or validated above); `isatty` is always safe to call.
            tty = unsafe { libc::isatty(fd) } == 1;
        } else {
            tty = false;
        }
    }

    // Record TTY information to an atomic for easy access.
    LOG_TTY.store(tty, 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, level, use_stack)?;

    // Finally let's make some noise!
    info!("ctx": "init", "op": "sing", "chapter": 24,
        "msg": "Change return success. Going and coming without error. Action brings good fortune.");

    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.
    // 3. positive fd must be a writable fd or we bail with EBADFD.
    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` was parsed from the environment and
                // checked `>= 0`; only used momentarily for validation.
                let fd = unsafe { BorrowedFd::borrow_raw(fd) };
                validate_log_fd(fd)?;
            }
            fd
        }
    };
    LOG_FD.store(fd, 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() {
            // SAFETY: `fd` is valid (either `STDERR_FILENO`
            // or validated above); `isatty` is always safe to call.
            tty = unsafe { libc::isatty(fd) } == 1;
        } else {
            tty = false;
        }
    }

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

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

    if let Some(sys) = global_syslog() {
        // 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(Ordering::Relaxed);

    // Log "id" with unique sandbox ID.
    #[expect(clippy::disallowed_methods)]
    if let Ok(id) = std::env::var(ENV_ID) {
        msg.insert("id".to_string(), id.into());
    }

    // Log "sid" with human readable Syd process name.
    // Log "syd" with current Syd thread.
    msg.shift_insert(0, "syd".to_string(), gettid().as_raw().into());
    #[expect(clippy::cast_sign_loss)]
    msg.shift_insert(
        0,
        "sid".to_string(),
        (getpid().as_raw() as u32).to_name().into(),
    );

    // Log "id" with unique sandbox ID.
    #[expect(clippy::disallowed_methods)]
    if let Ok(id) = std::env::var(ENV_ID) {
        msg.shift_insert(0, "id".to_string(), id.into());
    }

    // 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 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.
    // If KCOV is enabled, log in a way syzkaller can easily understand.
    let msg_data = if cfg!(feature = "kcov") && level <= crate::syslog::LogLevel::Warn {
        const MSG_KEYS: &[&str] = &["err", "error", "file", "line", "msg"];
        msg.retain(|key, _| MSG_KEYS.binary_search(&key.as_str()).is_ok());
        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}\"}}")
        });
        format!("BUG: {msg_data}")
    } else {
        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 && !cfg!(feature = "kcov") {
        // 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)]
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.
    // 3. positive fd must be a writable fd or we bail with EBADFD.
    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` was parsed from the environment and
                // checked `>= 0`; only used momentarily for validation.
                let fd = unsafe { BorrowedFd::borrow_raw(fd) };
                validate_log_fd(fd)?;
            }
            Some(fd)
        }
    };
    if let Some(fd) = fd {
        LOG_FD.store(fd, 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);
            // SAFETY: `fd` is valid (either `STDERR_FILENO`
            // or validated above); `isatty` is always safe to call.
            tty = unsafe { libc::isatty(fd) } == 1;
        } else {
            tty = false;
        }
    }

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

    // Finally let's make some noise!
    info!("ctx": "init", "op": "sing", "chapter": 24,
        "msg": "Change return success. Going and coming without error. Action brings good fortune.");

    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(Ordering::Relaxed);
    let fd = if fd < 0 {
        return; // Logging is disabled.
    } else {
        // SAFETY: `LOG_FD` is valid for process lifetime.
        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(Ordering::Relaxed);

    // Log "sid" with human readable Syd process name.
    // Log "syd" with current Syd thread.
    msg.shift_insert(0, "syd".to_string(), gettid().as_raw().into());
    #[expect(clippy::cast_sign_loss)]
    msg.shift_insert(
        0,
        "sid".to_string(),
        (getpid().as_raw() as u32).to_name().into(),
    );

    // Log "id" with unique sandbox ID.
    #[expect(clippy::disallowed_methods)]
    if let Ok(id) = std::env::var(ENV_ID) {
        msg.shift_insert(0, "id".to_string(), id.into());
    }

    // 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 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.
    // If KCOV is enabled, log in a way syzkaller can easily understand.
    let msg_data = if cfg!(feature = "kcov") && level <= crate::syslog::LogLevel::Warn {
        const MSG_KEYS: &[&str] = &["err", "error", "file", "line", "msg"];
        msg.retain(|key, _| MSG_KEYS.binary_search(&key.as_str()).is_ok());
        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}\"}}")
        });
        format!("BUG: {msg_data}")
    } else {
        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 && !cfg!(feature = "kcov") {
        // 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)
}

/// Helper to validly allocate and return ioctl names for logging.
pub fn get_ioctl_log(
    val: Ioctl,
    arch: ScmpArch,
    resolve: bool,
) -> Result<Option<Vec<IoctlName>>, Errno> {
    if !resolve {
        let mut vec = Vec::new();
        vec.try_reserve(1).or(Err(Errno::ENOMEM))?;
        vec.push(IoctlName::Val(val));
        return Ok(Some(vec));
    }
    match IoctlMap::new(None, true).get_log(val, arch)? {
        Some(names) => Ok(Some(names)),
        None => {
            let mut vec = Vec::new();
            vec.try_reserve(1).or(Err(Errno::ENOMEM))?;
            vec.push(IoctlName::Val(val));
            Ok(Some(vec))
        }
    }
}

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"
        )
    }
}

#[cfg(test)]
mod tests {
    use super::*;

    #[test]
    fn test_is_ascii_printable_1() {
        assert!(is_ascii_printable(b' '));
        assert!(is_ascii_printable(b'A'));
        assert!(is_ascii_printable(b'z'));
        assert!(is_ascii_printable(b'~'));
    }

    #[test]
    fn test_is_ascii_printable_2() {
        assert!(!is_ascii_printable(0x00));
        assert!(!is_ascii_printable(0x1F));
        assert!(!is_ascii_printable(0x7F));
        assert!(!is_ascii_printable(0xFF));
    }

    #[test]
    fn test_contains_ascii_unprintable_1() {
        assert!(!contains_ascii_unprintable(b"hello world"));
    }

    #[test]
    fn test_contains_ascii_unprintable_2() {
        assert!(contains_ascii_unprintable(b"hello\x00world"));
    }

    #[test]
    fn test_contains_ascii_unprintable_3() {
        assert!(!contains_ascii_unprintable(b""));
    }

    #[test]
    fn test_contains_ascii_unprintable_4() {
        assert!(contains_ascii_unprintable(b"\x01"));
    }

    #[test]
    fn test_contains_ascii_unprintable_5() {
        assert!(contains_ascii_unprintable(b"\x7f"));
    }

    #[test]
    fn test_log_untrusted_buf_1() {
        let (s, is_hex) = log_untrusted_buf(b"hello");
        assert_eq!(s, "hello");
        assert!(!is_hex);
    }

    #[test]
    fn test_log_untrusted_buf_2() {
        let (s, is_hex) = log_untrusted_buf(b"\x00\x01");
        assert!(is_hex);
        assert_eq!(s, "0001");
    }

    #[test]
    fn test_log_untrusted_buf_3() {
        let (_, is_hex) = log_untrusted_buf(&[0x80, 0x81]);
        assert!(is_hex);
    }

    #[test]
    fn test_try_from_1() {
        let tm: Tm = 0i64.try_into().unwrap();
        assert_eq!(tm.year(), 1970);
        assert_eq!(tm.month(), 1);
        assert_eq!(tm.day(), 1);
        assert_eq!(tm.hour(), 0);
        assert_eq!(tm.minute(), 0);
        assert_eq!(tm.second(), 0);
    }

    #[test]
    fn test_try_from_2() {
        let tm: Tm = 951_868_800i64.try_into().unwrap();
        assert_eq!(tm.year(), 2000);
        assert_eq!(tm.month(), 3);
        assert_eq!(tm.day(), 1);
    }

    #[test]
    fn test_try_from_3() {
        let tm: Tm = 1_704_067_200i64.try_into().unwrap();
        assert_eq!(tm.year(), 2024);
        assert_eq!(tm.month(), 1);
        assert_eq!(tm.day(), 1);
    }

    #[test]
    fn test_display_1() {
        let tm: Tm = 0i64.try_into().unwrap();
        let s = format!("{tm}");
        assert_eq!(s, "19700101T000000Z");
    }

    #[test]
    fn test_display_2() {
        let tm: Tm = 1_704_067_200i64.try_into().unwrap();
        let s = format!("{tm}");
        assert!(s.starts_with("2024"));
        assert!(s.ends_with('Z'));
    }

    #[test]
    fn test_year_1() {
        let tm: Tm = 0i64.try_into().unwrap();
        assert_eq!(tm.year(), 1970);
    }

    #[test]
    fn test_weekday_1() {
        let tm: Tm = 0i64.try_into().unwrap();
        assert_eq!(tm.weekday(), 4);
    }

    #[test]
    fn test_now_1() {
        let t = now();
        assert!(t > 1_704_067_200);
    }

    #[test]
    fn test_format_iso8601_1() {
        let s = format_iso8601(0).unwrap();
        assert_eq!(s, "19700101T000000Z");
    }

    #[test]
    fn test_format_iso8601_2() {
        let s = format_iso8601(1_704_067_200).unwrap();
        assert!(s.starts_with("2024"));
    }
}