syd/
log.rs

1//
2// Syd: rock-solid application kernel
3// src/log.rs: Simple logging on standard error using JSON lines
4//
5// Copyright (c) 2023, 2024, 2025 Ali Polatel <alip@chesswob.org>
6// Based in part upon musl's src/time/__secs_to_tm.c which is:
7//   Copyright © 2005-2020 Rich Felker, et al.
8//   SPDX-License-Identifier: MIT
9//
10// SPDX-License-Identifier: GPL-3.0
11
12use std::{
13    fmt,
14    io::Write,
15    os::fd::{BorrowedFd, RawFd},
16    sync::OnceLock,
17    thread::ThreadId,
18    time::{SystemTime, UNIX_EPOCH},
19};
20
21use btoi::btoi;
22use data_encoding::HEXLOWER;
23use nix::{
24    errno::Errno,
25    unistd::{write, Pid, Uid},
26};
27use serde_json::{Map, Value};
28
29use crate::{
30    config::*,
31    err::SydResult,
32    fs::{is_active_fd, lock_fd, retry_on_eintr, unlock_fd},
33    proc::{proc_cmdline, proc_comm, proc_cwd, proc_tty},
34    syslog::LogLevel,
35};
36
37/// Formatted print which returns Result as Errno rather than panicking.
38#[macro_export]
39macro_rules! printf {
40    () => {{}};
41    ($($arg:tt)*) => {{
42        use ::std::io::Write as _;
43        let __s = format!($($arg)*);
44        ::std::io::stdout().write_all(__s.as_bytes())
45            .map_err(|error| $crate::err::err2no(&error))
46    }};
47}
48
49/// Formatted println which returns Result as Errno rather than panicking.
50#[macro_export]
51macro_rules! printfln {
52    () => {{
53        use ::std::io::Write as _;
54        ::std::io::stdout().write_all(b"\n")
55            .map_err(|error| $crate::err::err2no(&error))
56    }};
57    ($($arg:tt)*) => {{
58        use ::std::io::Write as _;
59        let mut __s = format!($($arg)*);
60        __s.push('\n');
61        ::std::io::stdout().write_all(__s.as_bytes())
62            .map_err(|error| $crate::err::err2no(&error))
63    }};
64}
65
66// Whether we concluded the output is a TTY.
67pub(crate) static LOG_TTY: std::sync::atomic::AtomicBool =
68    std::sync::atomic::AtomicBool::new(false);
69// Log destination file descriptor.
70pub(crate) static LOG_FD: std::sync::atomic::AtomicI32 = std::sync::atomic::AtomicI32::new(-42);
71
72// Main thread identifier, used to decide on panic hook.
73pub(crate) static LOG_MAIN_TID: OnceLock<ThreadId> = OnceLock::new();
74
75// Set this in main thread after namespace forks and other dances.
76pub(crate) fn log_init_main() -> SydResult<()> {
77    LOG_MAIN_TID
78        .set(std::thread::current().id())
79        .map_err(|_| Errno::EBUSY.into())
80}
81
82// Sets the global panic hook for Syd threads.
83pub(crate) fn log_set_panic_hook() {
84    // Set a logging panic hook. The default panic
85    // hook calls system calls not permitted by emulators
86    // such as getcwd(2), stat(2) etc.
87    #[expect(clippy::cognitive_complexity)]
88    std::panic::set_hook(Box::new(|info| {
89        let this = std::thread::current();
90        let name = this.name().unwrap_or("?");
91
92        let err = match info.payload().downcast_ref::<&'static str>() {
93            Some(s) => *s,
94            None => match info.payload().downcast_ref::<String>() {
95                Some(s) => &**s,
96                None => "?",
97            },
98        };
99
100        let file = info.location().map(|l| l.file());
101        let line = info.location().map(|l| l.line());
102
103        if log_is_main() {
104            // Main thread panicking isn't recoverable unlike others.
105            // Ensure clean exit right away.
106            crate::alert!("ctx": "panic",
107                "op": "panic_syd_main_thread",
108                "msg": err, "file": file, "line": line);
109            std::process::exit(101);
110        } else {
111            crate::crit!("ctx": "panic",
112                "op": format!("panic_{name}_thread"),
113                "msg": err, "file": file, "line": line);
114        }
115    }));
116}
117
118// Use this to check for main thread in panic handler.
119#[inline]
120fn log_is_main() -> bool {
121    LOG_MAIN_TID
122        .get()
123        .map(|&tid| tid == std::thread::current().id())
124        .unwrap_or(false)
125}
126
127/// emerg! logging macro
128#[macro_export]
129macro_rules! emerg {
130    ($($key:literal : $value:expr),+) => {
131        if $crate::log_enabled!($crate::syslog::LogLevel::Emergent) {
132            let timestamp = $crate::log::now();
133            let mut map = serde_json::Map::new();
134            $(
135                if let Ok(value) = serde_json::to_value($value) {
136                    map.insert($key.to_string(), value);
137                } else {
138                    map.insert($key.to_string(), serde_json::Value::Null);
139                }
140            )+
141            if !map.is_empty() {
142                $crate::log::log($crate::syslog::LogLevel::Emergent, timestamp, map);
143            }
144        }
145    }
146}
147
148/// alert! logging macro
149#[macro_export]
150macro_rules! alert {
151    ($($key:literal : $value:expr),+) => {
152        if $crate::log_enabled!($crate::syslog::LogLevel::Alert) {
153            let timestamp = $crate::log::now();
154            let mut map = serde_json::Map::new();
155            $(
156                if let Ok(value) = serde_json::to_value($value) {
157                    map.insert($key.to_string(), value);
158                } else {
159                    map.insert($key.to_string(), serde_json::Value::Null);
160                }
161            )+
162            if !map.is_empty() {
163                $crate::log::log($crate::syslog::LogLevel::Alert, timestamp, map);
164            }
165        }
166    }
167}
168
169/// crit! logging macro
170#[macro_export]
171macro_rules! crit {
172    ($($key:literal : $value:expr),+) => {
173        if $crate::log_enabled!($crate::syslog::LogLevel::Crit) {
174            let timestamp = $crate::log::now();
175            let mut map = serde_json::Map::new();
176            $(
177                if let Ok(value) = serde_json::to_value($value) {
178                    map.insert($key.to_string(), value);
179                } else {
180                    map.insert($key.to_string(), serde_json::Value::Null);
181                }
182            )+
183            if !map.is_empty() {
184                $crate::log::log($crate::syslog::LogLevel::Crit, timestamp, map);
185            }
186        }
187    }
188}
189
190/// error! logging macro
191#[macro_export]
192macro_rules! error {
193    ($($key:literal : $value:expr),+) => {
194        if $crate::log_enabled!($crate::syslog::LogLevel::Err) {
195            let timestamp = $crate::log::now();
196            let mut map = serde_json::Map::new();
197            $(
198                if let Ok(value) = serde_json::to_value($value) {
199                    map.insert($key.to_string(), value);
200                } else {
201                    map.insert($key.to_string(), serde_json::Value::Null);
202                }
203            )+
204            if !map.is_empty() {
205                $crate::log::log($crate::syslog::LogLevel::Err, timestamp, map);
206            }
207        }
208    }
209}
210
211/// warn! logging macro
212#[macro_export]
213macro_rules! warn {
214    ($($key:literal : $value:expr),+) => {
215        if $crate::log_enabled!($crate::syslog::LogLevel::Warn) {
216            let timestamp = $crate::log::now();
217            let mut map = serde_json::Map::new();
218            $(
219                if let Ok(value) = serde_json::to_value($value) {
220                    map.insert($key.to_string(), value);
221                } else {
222                    map.insert($key.to_string(), serde_json::Value::Null);
223                }
224            )+
225            if !map.is_empty() {
226                $crate::log::log($crate::syslog::LogLevel::Warn, timestamp, map);
227            }
228        }
229    }
230}
231
232/// notice! logging macro
233#[macro_export]
234macro_rules! notice {
235    ($($key:literal : $value:expr),+) => {
236        if $crate::log_enabled!($crate::syslog::LogLevel::Notice) {
237            let timestamp = $crate::log::now();
238            let mut map = serde_json::Map::new();
239            $(
240                if let Ok(value) = serde_json::to_value($value) {
241                    map.insert($key.to_string(), value);
242                } else {
243                    map.insert($key.to_string(), serde_json::Value::Null);
244                }
245            )+
246            if !map.is_empty() {
247                $crate::log::log($crate::syslog::LogLevel::Notice, timestamp, map);
248            }
249        }
250    }
251}
252
253/// info! logging macro
254#[macro_export]
255macro_rules! info {
256    ($($key:literal : $value:expr),+) => {
257        if $crate::log_enabled!($crate::syslog::LogLevel::Info) {
258            let timestamp = $crate::log::now();
259            let mut map = serde_json::Map::new();
260            $(
261                if let Ok(value) = serde_json::to_value($value) {
262                    map.insert($key.to_string(), value);
263                } else {
264                    map.insert($key.to_string(), serde_json::Value::Null);
265                }
266            )+
267            if !map.is_empty() {
268                $crate::log::log($crate::syslog::LogLevel::Info, timestamp, map);
269            }
270        }
271    }
272}
273
274/// debug! logging macro
275#[macro_export]
276macro_rules! debug {
277    ($($key:literal : $value:expr),+) => {
278        if $crate::log_enabled!($crate::syslog::LogLevel::Debug) {
279            let timestamp = $crate::log::now();
280            let mut map = serde_json::Map::new();
281            $(
282                if let Ok(value) = serde_json::to_value($value) {
283                    map.insert($key.to_string(), value);
284                } else {
285                    map.insert($key.to_string(), serde_json::Value::Null);
286                }
287            )+
288            if !map.is_empty() {
289                $crate::log::log($crate::syslog::LogLevel::Debug, timestamp, map);
290            }
291        }
292    }
293}
294
295// A wrapper that implements Write for a raw fd, but does not close it
296// on drop. We can then use standard .write_all(...) to handle EINTR.
297pub(crate) struct LockedWriter<'a> {
298    fd: BorrowedFd<'a>,
299}
300
301impl<'a> LockedWriter<'a> {
302    pub(crate) fn new(fd: BorrowedFd<'a>) -> Result<Self, Errno> {
303        retry_on_eintr(|| lock_fd(fd, true, true))?;
304        Ok(Self { fd })
305    }
306}
307
308impl Drop for LockedWriter<'_> {
309    fn drop(&mut self) {
310        let _ = self.flush();
311        let _ = unlock_fd(self.fd);
312    }
313}
314
315impl Write for LockedWriter<'_> {
316    fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
317        write(self.fd, buf).map_err(|e| std::io::Error::from_raw_os_error(e as i32))
318    }
319
320    fn flush(&mut self) -> std::io::Result<()> {
321        Ok(())
322    }
323}
324
325/// Initializes Syslog global object, reading environment variables.
326#[cfg(feature = "log")]
327#[expect(clippy::cognitive_complexity)]
328pub fn log_init(default_level: LogLevel, default_log_fd: Option<RawFd>) -> Result<(), Errno> {
329    use std::os::unix::ffi::OsStrExt;
330
331    use crate::syslog::{init_global_syslog, parse_loglevel};
332
333    // Parse the desired console log level from ENV_LOG,
334    // or use default_level if not set/invalid.
335    let level = if let Some(val) = std::env::var_os(ENV_LOG) {
336        parse_loglevel(val.as_os_str().as_bytes(), default_level)
337    } else {
338        default_level
339    };
340
341    // Determine the main FD for logging:
342    // By default, we use stderr.
343    // If ENV_LOG_FD is set, we parse it:
344    // 1. negative fd is ok as a shorthand to disable logging.
345    // 2. positive fd must be a valid fd or we bail with EBADF.
346    let fd = match std::env::var_os(ENV_LOG_FD) {
347        None => default_log_fd,
348        Some(val) => {
349            let fd = btoi::<RawFd>(val.as_os_str().as_bytes()).map_err(|_| Errno::EBADF)?;
350            if fd >= 0 {
351                // SAFETY: fd only used after validation.
352                let fd = unsafe { BorrowedFd::borrow_raw(fd) };
353                if !is_active_fd(fd) {
354                    return Err(Errno::EBADF);
355                }
356            }
357            Some(fd)
358        }
359    };
360    if let Some(fd) = fd {
361        LOG_FD.store(fd, std::sync::atomic::Ordering::Relaxed);
362    }
363
364    // Decide if we want a TTY-like console.
365    let mut tty = std::env::var_os(ENV_FORCE_TTY).is_some();
366    if !tty {
367        if std::env::var_os(ENV_QUIET_TTY).is_none() {
368            let fd = fd.unwrap_or(libc::STDERR_FILENO);
369            // Check if log FD is a TTY.
370            // SAFETY: In libc we trust.
371            tty = unsafe { libc::isatty(fd) } == 1;
372        } else {
373            tty = false;
374        }
375    }
376
377    // Record TTY information to an atomic for easy access.
378    LOG_TTY.store(tty, std::sync::atomic::Ordering::Relaxed);
379
380    // Allocate the syslog(2) ring buffer on the stack by default.
381    // The size is architecture-dependent, see config.rs.
382    //
383    // If the user specifies an alternative capacity with `SYD_LOG_BUF_LEN`,
384    // parse this size using parse-size and use it instead.
385    let mut logbuflen = 0usize;
386    let mut use_stack = true;
387    if let Some(var) = std::env::var_os(ENV_LOG_BUF_LEN) {
388        logbuflen = parse_size::Config::new()
389            .with_binary()
390            .parse_size(var.as_bytes())
391            .or(Err(Errno::EINVAL))?
392            .try_into()
393            .or(Err(Errno::EINVAL))?;
394        use_stack = false;
395    }
396    init_global_syslog(logbuflen, fd, level, use_stack)?;
397
398    // Finally let's make some noise!
399    //
400    // ENV_SING avoids duplicating this message over memfd-reexec.
401    if std::env::var_os(ENV_SING).is_none() {
402        info!("ctx": "init", "op": "sing", "chapter": 24,
403            "msg": "Change return success. Going and coming without error. Action brings good fortune.");
404        std::env::set_var(ENV_SING, "");
405    }
406
407    Ok(())
408}
409
410/// A simpler variant that turns off host syslog from the start and
411/// locks the ring buffer.  This can be used by small utilities that do
412/// not want the ring buffer overhead.
413#[cfg(feature = "log")]
414pub fn log_init_simple(default_level: LogLevel) -> Result<(), Errno> {
415    use std::os::unix::ffi::OsStrExt;
416
417    use crate::syslog::{global_syslog, init_global_syslog, parse_loglevel};
418
419    // Parse the desired console log level from ENV_LOG,
420    // or use default_level if not set/invalid.
421    let level = if let Some(val) = std::env::var_os(ENV_LOG) {
422        parse_loglevel(val.as_os_str().as_bytes(), default_level)
423    } else {
424        default_level
425    };
426
427    // Determine the main FD for logging:
428    // By default, we use stderr.
429    // If ENV_LOG_FD is set, we parse it:
430    // 1. negative fd is ok as a shorthand to disable logging.
431    // 2. positive fd must be a valid fd or we bail with EBADF.
432    let fd = match std::env::var_os(ENV_LOG_FD) {
433        None => libc::STDERR_FILENO,
434        Some(val) => {
435            let fd = btoi::<RawFd>(val.as_os_str().as_bytes()).map_err(|_| Errno::EBADF)?;
436            if fd >= 0 {
437                // SAFETY: fd only used after validation.
438                let fd = unsafe { BorrowedFd::borrow_raw(fd) };
439                if !is_active_fd(fd) {
440                    return Err(Errno::EBADF);
441                }
442            }
443            fd
444        }
445    };
446    LOG_FD.store(fd, std::sync::atomic::Ordering::Relaxed);
447
448    // Decide if we want a TTY-like console.
449    let mut tty = std::env::var_os(ENV_FORCE_TTY).is_some();
450    if !tty {
451        if std::env::var_os(ENV_QUIET_TTY).is_none() {
452            // Check if log FD is a TTY.
453            // SAFETY: In libc we trust.
454            tty = unsafe { libc::isatty(fd) } == 1;
455        } else {
456            tty = false;
457        }
458    }
459
460    // Record TTY information to an atomic for easy access.
461    LOG_TTY.store(tty, std::sync::atomic::Ordering::Relaxed);
462
463    // Create a global syslog with ring.
464    init_global_syslog(0, Some(fd), level, true)?;
465
466    if let Some(sys) = global_syslog() {
467        // Now lock it immediately,
468        // so ring is unavailable.
469        sys.lock();
470    }
471
472    Ok(())
473}
474
475/// Main entry point for appending log entries in JSON-line style.
476#[cfg(feature = "log")]
477#[expect(clippy::cognitive_complexity)]
478pub fn log(level: crate::syslog::LogLevel, timestamp: u64, mut msg: Map<String, Value>) {
479    let sys = if let Some(sys) = crate::syslog::global_syslog() {
480        sys
481    } else {
482        return; // Logging is disabled.
483    };
484
485    // For "higher" severities, we add more contextual fields.
486    let add_context = level.as_u8() <= crate::syslog::LogLevel::Notice.as_u8();
487    let tty = LOG_TTY.load(std::sync::atomic::Ordering::Relaxed);
488
489    // If there's a "pid", we might add cmd/cwd, etc.
490    // We remove and re-add to reorder for better visibility.
491    if let Some(pid_v) = msg.remove("pid").and_then(|v| v.as_i64()) {
492        #[expect(clippy::cast_possible_truncation)]
493        let pid = Pid::from_raw(pid_v as libc::pid_t);
494        if pid.as_raw() != 0 {
495            if add_context {
496                if let Ok(cmd) = proc_cmdline(pid) {
497                    msg.insert("cmd".to_string(), cmd.to_string().into());
498                }
499            } else if let Ok(cmd) = proc_comm(pid) {
500                msg.insert("cmd".to_string(), cmd.to_string().into());
501            }
502            if let Ok(dir) = proc_cwd(pid) {
503                msg.insert("cwd".to_string(), dir.to_string().into());
504            }
505            if add_context {
506                if let Ok(tty) = proc_tty(pid) {
507                    msg.insert("tty".to_string(), tty.to_string().into());
508                }
509            }
510        }
511        msg.insert("pid".to_string(), pid.as_raw().into());
512    }
513
514    // Add current user if add_context.
515    if add_context {
516        msg.insert("uid".to_string(), Uid::current().as_raw().into());
517    }
518
519    // Add "syd" = current thread ID.
520    let syd = nix::unistd::gettid().as_raw().into();
521    msg.insert("syd".to_string(), Value::Number(syd));
522
523    // Add ISO8601 date, fallback to timestamp.
524    if let Ok(date) = format_iso8601(timestamp) {
525        msg.insert("time".to_string(), date.into());
526    } else {
527        msg.insert("time".to_string(), timestamp.into());
528    }
529
530    // Reorder req and informational fields for better visibility.
531    if let Some(src) = msg.remove("req") {
532        msg.insert("req".to_string(), src);
533    }
534    if let Some(m) = msg.remove("msg") {
535        msg.insert("msg".to_string(), m);
536    }
537    if let Some(tip) = msg.remove("tip") {
538        msg.insert("tip".to_string(), tip);
539    }
540
541    // Convert to JSON line.
542    let msg_data = serde_json::to_string(&msg).unwrap_or_else(|e| {
543        let e = serde_json::to_string(&format!("{e:?}")).unwrap_or("?".to_string());
544        format!("{{\"ctx\":\"log\",\"op\":\"serialize\",\"error\": \"{e}\"}}")
545    });
546    let msg_pretty = if tty {
547        // A "pretty" output for TTY.
548        Some(serde_json::to_string_pretty(&msg).unwrap_or_else(|e| {
549            let e = serde_json::to_string(&format!("{e:?}")).unwrap_or("?".to_string());
550            format!("{{\"ctx\":\"log\",\"op\":\"serialize\",\"error\": \"{e}\"}}")
551        }))
552    } else {
553        None
554    };
555
556    sys.write_log(level, &msg_data, msg_pretty.as_deref());
557}
558
559/// Initializes Syslog global object, reading environment variables.
560#[cfg(not(feature = "log"))]
561#[inline(always)]
562#[expect(clippy::cognitive_complexity)]
563pub fn log_init(_default_level: LogLevel, default_log_fd: Option<RawFd>) -> Result<(), Errno> {
564    use std::os::unix::ffi::OsStrExt;
565
566    // Determine the main FD for logging:
567    // By default, we use stderr.
568    // If ENV_LOG_FD is set, we parse it:
569    // 1. negative fd is ok as a shorthand to disable logging.
570    // 2. positive fd must be a valid fd or we bail with EBADF.
571    let fd = match std::env::var_os(ENV_LOG_FD) {
572        None => default_log_fd,
573        Some(val) => {
574            let fd = btoi::<RawFd>(val.as_os_str().as_bytes()).map_err(|_| Errno::EBADF)?;
575            if fd >= 0 {
576                // SAFETY: fd only used after validation.
577                let fd = unsafe { BorrowedFd::borrow_raw(fd) };
578                if !is_active_fd(fd) {
579                    return Err(Errno::EBADF);
580                }
581            }
582            Some(fd)
583        }
584    };
585    if let Some(fd) = fd {
586        LOG_FD.store(fd, std::sync::atomic::Ordering::Relaxed);
587    }
588
589    // Decide if we want a TTY-like console.
590    let mut tty = std::env::var_os(ENV_FORCE_TTY).is_some();
591    if !tty {
592        if std::env::var_os(ENV_QUIET_TTY).is_none() {
593            let fd = fd.unwrap_or(libc::STDERR_FILENO);
594            // Check if log FD is a TTY.
595            // SAFETY: In libc we trust.
596            tty = unsafe { libc::isatty(fd) } == 1;
597        } else {
598            tty = false;
599        }
600    }
601
602    // Record TTY information to an atomic for easy access.
603    LOG_TTY.store(tty, std::sync::atomic::Ordering::Relaxed);
604
605    // Determine the main FD for logging:
606    // By default, we use stderr.
607    // If ENV_LOG_FD is set, we parse it:
608    // 1. negative fd is ok as a shorthand to disable logging.
609    // 2. positive fd must be a valid fd or we bail with EBADF.
610    let fd = match std::env::var_os(ENV_LOG_FD) {
611        None => default_log_fd,
612        Some(val) => {
613            let fd = btoi::<RawFd>(val.as_os_str().as_bytes()).map_err(|_| Errno::EBADF)?;
614            if fd >= 0 {
615                // SAFETY: fd only used after validation.
616                let fd = unsafe { BorrowedFd::borrow_raw(fd) };
617                if !is_active_fd(fd) {
618                    return Err(Errno::EBADF);
619                }
620            }
621            Some(fd)
622        }
623    };
624    if let Some(fd) = fd {
625        LOG_FD.store(fd, std::sync::atomic::Ordering::Relaxed);
626    }
627
628    // Finally let's make some noise!
629    //
630    // ENV_SING avoids duplicating this message over memfd-reexec.
631    if std::env::var_os(ENV_SING).is_none() {
632        info!("ctx": "init", "op": "sing", "chapter": 24,
633            "msg": "Change return success. Going and coming without error. Action brings good fortune.");
634        std::env::set_var(ENV_SING, "");
635    }
636
637    Ok(())
638}
639
640/// A simpler variant that turns off host syslog from the start and
641/// locks the ring buffer.  This can be used by small utilities that do
642/// not want the ring buffer overhead.
643#[cfg(not(feature = "log"))]
644#[inline(always)]
645pub fn log_init_simple(default_level: LogLevel) -> Result<(), Errno> {
646    log_init(default_level, Some(libc::STDERR_FILENO))
647}
648
649/// Main entry point for appending log entries in JSON-line style.
650#[cfg(not(feature = "log"))]
651#[expect(clippy::cognitive_complexity)]
652pub fn log(level: crate::syslog::LogLevel, timestamp: u64, mut msg: Map<String, Value>) {
653    // Setting LOG-FD to negative is OK to disable logging.
654    let fd = LOG_FD.load(std::sync::atomic::Ordering::Relaxed);
655    let fd = if fd < 0 {
656        return; // Logging is disabled.
657    } else {
658        // SAFETY: we trust log fd is valid.
659        unsafe { BorrowedFd::borrow_raw(fd) }
660    };
661
662    // For "higher" severities, we add more contextual fields.
663    let add_context = level.as_u8() <= crate::syslog::LogLevel::Notice.as_u8();
664    let tty = LOG_TTY.load(std::sync::atomic::Ordering::Relaxed);
665
666    // If there's a "pid", we might add cmd/cwd, etc.
667    // We remove and re-add to reorder for better visibility.
668    if let Some(pid_v) = msg.remove("pid").and_then(|v| v.as_i64()) {
669        #[expect(clippy::cast_possible_truncation)]
670        let pid = Pid::from_raw(pid_v as libc::pid_t);
671        if pid.as_raw() != 0 {
672            if add_context {
673                if let Ok(cmd) = proc_cmdline(pid) {
674                    msg.insert("cmd".to_string(), cmd.to_string().into());
675                }
676            } else if let Ok(cmd) = proc_comm(pid) {
677                msg.insert("cmd".to_string(), cmd.to_string().into());
678            }
679            if let Ok(dir) = proc_cwd(pid) {
680                msg.insert("cwd".to_string(), dir.to_string().into());
681            }
682            if add_context {
683                if let Ok(tty) = proc_tty(pid) {
684                    msg.insert("tty".to_string(), tty.to_string().into());
685                }
686            }
687        }
688        msg.insert("pid".to_string(), pid.as_raw().into());
689    }
690
691    // Add current user if add_context.
692    if add_context {
693        msg.insert("uid".to_string(), Uid::current().as_raw().into());
694    }
695
696    // Add "syd" = current thread ID.
697    let syd = nix::unistd::gettid().as_raw().into();
698    msg.insert("syd".to_string(), Value::Number(syd));
699
700    // Add ISO8601 date, fallback to timestamp.
701    if let Ok(date) = format_iso8601(timestamp) {
702        msg.insert("time".to_string(), date.into());
703    } else {
704        msg.insert("time".to_string(), timestamp.into());
705    }
706
707    // Reorder req and informational fields for better visibility.
708    if let Some(src) = msg.remove("req") {
709        msg.insert("req".to_string(), src);
710    }
711    if let Some(m) = msg.remove("msg") {
712        msg.insert("msg".to_string(), m);
713    }
714    if let Some(tip) = msg.remove("tip") {
715        msg.insert("tip".to_string(), tip);
716    }
717
718    // Convert to JSON line
719    let msg_data = serde_json::to_string(&msg).unwrap_or_else(|e| {
720        let e = serde_json::to_string(&format!("{e:?}")).unwrap_or("?".to_string());
721        format!("{{\"ctx\":\"log\",\"op\":\"serialize\",\"error\": \"{e}\"}}")
722    });
723
724    let msg_info = if tty {
725        // A "pretty" output for TTY.
726        Some(serde_json::to_string_pretty(&msg).unwrap_or_else(|e| {
727            let e = serde_json::to_string(&format!("{e:?}")).unwrap_or("?".to_string());
728            format!("{{\"ctx\":\"log\",\"op\":\"serialize\",\"error\": \"{e}\"}}")
729        }))
730    } else {
731        None
732    };
733
734    // Finally, log to fd or standard error.
735    if let Ok(mut writer) = LockedWriter::new(fd).map(std::io::BufWriter::new) {
736        if let Some(ref msg) = msg_info {
737            let _ = writer.write_all(msg.as_bytes());
738        } else {
739            let _ = writer.write_all(msg_data.as_bytes());
740        }
741        let _ = writer.write_all(b"\n");
742    }
743}
744
745/// Return the current time in seconds since the unix epoch.
746pub fn now() -> u64 {
747    SystemTime::now()
748        .duration_since(UNIX_EPOCH)
749        .unwrap_or_default()
750        .as_secs()
751}
752
753/// Returns current time as a compact ISO8601-formatted string.
754///
755/// The format is currently "YYYYMMDDThhmmssZ". The format may change in
756/// the future but it will always remain conformant to the ISO8601
757/// standard.
758fn format_iso8601(timestamp: u64) -> Result<String, Errno> {
759    let t = i64::try_from(timestamp).or(Err(Errno::EINVAL))?;
760    let t: Tm = t.try_into()?;
761    Ok(t.to_string())
762}
763
764/// Logs an untrusted buffer, escaping it as hex if it contains control characters.
765/// Returns a boolean in addition to the String which is true if String is hex-encoded.
766pub fn log_untrusted_buf(buf: &[u8]) -> (String, bool) {
767    if contains_ascii_unprintable(buf) {
768        (HEXLOWER.encode(buf), true)
769    } else if let Ok(s) = std::str::from_utf8(buf) {
770        (s.to_string(), false)
771    } else {
772        (HEXLOWER.encode(buf), true)
773    }
774}
775
776/// Checks if the buffer contains ASCII unprintable characters.
777pub fn contains_ascii_unprintable(buf: &[u8]) -> bool {
778    buf.iter().any(|byte| !is_ascii_printable(*byte))
779}
780
781/// Checks if the given character is ASCII printable.
782pub fn is_ascii_printable(byte: u8) -> bool {
783    (0x20..=0x7e).contains(&byte)
784}
785
786/// Rust port of musl's `struct tm`.
787#[derive(Clone, Copy, Debug, Eq, PartialEq, Hash)]
788pub struct Tm {
789    tm_year: i32, // years since 1900
790    tm_mon: i32,  // 0..11
791    tm_mday: i32, // 1..31
792    tm_wday: i32, // 0..6, Sunday=0
793    tm_yday: i32, // 0..365
794    tm_hour: i32, // 0..23
795    tm_min: i32,  // 0..59
796    tm_sec: i32,  // 0..60 (leap second tolerated like musl)
797}
798
799impl Tm {
800    /// Get the year of the date.
801    pub fn year(&self) -> i32 {
802        self.tm_year.saturating_add(1900)
803    }
804
805    /// Get the month of the date.
806    pub fn month(&self) -> i32 {
807        self.tm_mon.saturating_add(1)
808    }
809
810    /// Get the month day of the date.
811    pub fn day(&self) -> i32 {
812        self.tm_mday
813    }
814
815    /// Get the hour of the date.
816    pub fn hour(&self) -> i32 {
817        self.tm_hour
818    }
819
820    /// Get the minute of the date.
821    pub fn minute(&self) -> i32 {
822        self.tm_min
823    }
824
825    /// Get the second of the date.
826    pub fn second(&self) -> i32 {
827        self.tm_sec
828    }
829}
830
831impl TryFrom<i64> for Tm {
832    type Error = Errno;
833
834    fn try_from(t: i64) -> Result<Self, Errno> {
835        const LEAPOCH: i64 = 951_868_800; // 2000-03-01 00:00:00 UTC
836        const SECS_PER_DAY: i64 = 86_400;
837        const DAYS_PER_400Y: i64 = 146_097;
838        const DAYS_PER_100Y: i64 = 36_524;
839        const DAYS_PER_4Y: i64 = 1_461;
840
841        // Reject time_t values whose year would overflow int.
842        let limit_unit = 31_622_400i64; // 366 days in seconds
843        let low = i64::from(i32::MIN)
844            .checked_mul(limit_unit)
845            .ok_or(Errno::EOVERFLOW)?;
846        let high = i64::from(i32::MAX)
847            .checked_mul(limit_unit)
848            .ok_or(Errno::EOVERFLOW)?;
849        if t < low || t > high {
850            return Err(Errno::EOVERFLOW);
851        }
852
853        let secs = t.checked_sub(LEAPOCH).ok_or(Errno::EOVERFLOW)?;
854        let mut days = secs.checked_div(SECS_PER_DAY).ok_or(Errno::EOVERFLOW)?;
855        let mut remsecs = secs.checked_rem(SECS_PER_DAY).ok_or(Errno::EOVERFLOW)?;
856        if remsecs < 0 {
857            remsecs = remsecs.checked_add(SECS_PER_DAY).ok_or(Errno::EOVERFLOW)?;
858            days = days.checked_sub(1).ok_or(Errno::EOVERFLOW)?;
859        }
860
861        // Weekday: 2000-03-01 was Wednesday (3)
862        let mut wday = (3i64)
863            .checked_add(days)
864            .ok_or(Errno::EOVERFLOW)?
865            .checked_rem(7)
866            .ok_or(Errno::EOVERFLOW)?;
867        if wday < 0 {
868            wday = wday.checked_add(7).ok_or(Errno::EOVERFLOW)?;
869        }
870
871        // Gregorian cycles
872        let mut qc_cycles = days.checked_div(DAYS_PER_400Y).ok_or(Errno::EOVERFLOW)?;
873        let mut remdays = days.checked_rem(DAYS_PER_400Y).ok_or(Errno::EOVERFLOW)?;
874        if remdays < 0 {
875            remdays = remdays.checked_add(DAYS_PER_400Y).ok_or(Errno::EOVERFLOW)?;
876            qc_cycles = qc_cycles.checked_sub(1).ok_or(Errno::EOVERFLOW)?;
877        }
878
879        let mut c_cycles = remdays.checked_div(DAYS_PER_100Y).ok_or(Errno::EOVERFLOW)?;
880        if c_cycles == 4 {
881            c_cycles = c_cycles.checked_sub(1).ok_or(Errno::EOVERFLOW)?;
882        }
883        remdays = remdays
884            .checked_sub(
885                c_cycles
886                    .checked_mul(DAYS_PER_100Y)
887                    .ok_or(Errno::EOVERFLOW)?,
888            )
889            .ok_or(Errno::EOVERFLOW)?;
890
891        let mut q_cycles = remdays.checked_div(DAYS_PER_4Y).ok_or(Errno::EOVERFLOW)?;
892        if q_cycles == 25 {
893            q_cycles = q_cycles.checked_sub(1).ok_or(Errno::EOVERFLOW)?;
894        }
895        remdays = remdays
896            .checked_sub(q_cycles.checked_mul(DAYS_PER_4Y).ok_or(Errno::EOVERFLOW)?)
897            .ok_or(Errno::EOVERFLOW)?;
898
899        let mut remyears = remdays.checked_div(365).ok_or(Errno::EOVERFLOW)?;
900        if remyears == 4 {
901            remyears = remyears.checked_sub(1).ok_or(Errno::EOVERFLOW)?;
902        }
903        remdays = remdays
904            .checked_sub(remyears.checked_mul(365).ok_or(Errno::EOVERFLOW)?)
905            .ok_or(Errno::EOVERFLOW)?;
906
907        let leap = remyears == 0 && (q_cycles != 0 || c_cycles == 0);
908        let leap_i = if leap { 1i64 } else { 0i64 };
909
910        let mut yday = remdays
911            .checked_add(59)
912            .ok_or(Errno::EOVERFLOW)?
913            .checked_add(leap_i)
914            .ok_or(Errno::EOVERFLOW)?;
915        let yday_lim = 365i64.checked_add(leap_i).ok_or(Errno::EOVERFLOW)?;
916        if yday >= yday_lim {
917            yday = yday.checked_sub(yday_lim).ok_or(Errno::EOVERFLOW)?;
918        }
919
920        let years = remyears
921            .checked_add(4i64.checked_mul(q_cycles).ok_or(Errno::EOVERFLOW)?)
922            .ok_or(Errno::EOVERFLOW)?
923            .checked_add(100i64.checked_mul(c_cycles).ok_or(Errno::EOVERFLOW)?)
924            .ok_or(Errno::EOVERFLOW)?
925            .checked_add(400i64.checked_mul(qc_cycles).ok_or(Errno::EOVERFLOW)?)
926            .ok_or(Errno::EOVERFLOW)?;
927
928        // Month & day within "Mar..Feb" year layout.
929        let dim: [i64; 12] = [31, 30, 31, 30, 31, 31, 30, 31, 30, 31, 31, 29];
930        let mut months = 0i64;
931        let mut rd = remdays;
932        while months < 12 {
933            let d = *dim
934                .get(usize::try_from(months).or(Err(Errno::EOVERFLOW))?)
935                .ok_or(Errno::EOVERFLOW)?;
936            if d > rd {
937                break;
938            }
939            rd = rd.checked_sub(d).ok_or(Errno::EOVERFLOW)?;
940            months = months.checked_add(1).ok_or(Errno::EOVERFLOW)?;
941        }
942
943        let mut years_adj = years;
944        let mut months_adj = months;
945        if months_adj >= 10 {
946            months_adj = months_adj.checked_sub(12).ok_or(Errno::EOVERFLOW)?;
947            years_adj = years_adj.checked_add(1).ok_or(Errno::EOVERFLOW)?;
948        }
949
950        let years_plus_100 = years_adj.checked_add(100).ok_or(Errno::EOVERFLOW)?;
951        if years_plus_100 > i64::from(i32::MAX) || years_plus_100 < i64::from(i32::MIN) {
952            return Err(Errno::EOVERFLOW);
953        }
954
955        let hour = remsecs.checked_div(3600).ok_or(Errno::EOVERFLOW)?;
956        let min = remsecs
957            .checked_div(60)
958            .ok_or(Errno::EOVERFLOW)?
959            .checked_rem(60)
960            .ok_or(Errno::EOVERFLOW)?;
961        let sec = remsecs.checked_rem(60).ok_or(Errno::EOVERFLOW)?;
962
963        Ok(Self {
964            tm_year: i32::try_from(years_plus_100).or(Err(Errno::EOVERFLOW))?,
965            tm_mon: i32::try_from(months_adj.checked_add(2).ok_or(Errno::EOVERFLOW)?)
966                .or(Err(Errno::EOVERFLOW))?,
967            tm_mday: i32::try_from(rd.checked_add(1).ok_or(Errno::EOVERFLOW)?)
968                .or(Err(Errno::EOVERFLOW))?,
969            tm_wday: i32::try_from(wday).or(Err(Errno::EOVERFLOW))?,
970            tm_yday: i32::try_from(yday).or(Err(Errno::EOVERFLOW))?,
971            tm_hour: i32::try_from(hour).or(Err(Errno::EOVERFLOW))?,
972            tm_min: i32::try_from(min).or(Err(Errno::EOVERFLOW))?,
973            tm_sec: i32::try_from(sec).or(Err(Errno::EOVERFLOW))?,
974        })
975    }
976}
977
978impl fmt::Display for Tm {
979    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
980        let year = self.year();
981        let month = self.month();
982        let day = self.day();
983        let hour = self.hour();
984        let minute = self.minute();
985        let second = self.second();
986
987        // Format: YYYYMMDDThhmmssZ
988        write!(
989            f,
990            "{year:04}{month:02}{day:02}T{hour:02}{minute:02}{second:02}Z"
991        )
992    }
993}
syd/log.rs

syd/
log.rs
