robonix_scribe/
lib.rs

1//! Scribe — Robonix unified logging facade.
2//!
3//! Single entry point: [`log()`].  Every component calls the same function;
4//! Scribe routes each record to stderr (human-readable) and to a per-tag
5//! JSON-lines file under `$SCRIBE_LOG_DIR` (or `./logs`).
6//!
7//! # Quick start
8//!
9//! ```rust,ignore
10//! robonix_scribe::init("executor");
11//! robonix_scribe::info!("robonix-executor starting");
12//! robonix_scribe::warn!("retry {}/{}", n, max);
13//! ```
14//!
15//! The `init()` call sets a process-wide default tag used by all subsequent
16//! [`info!`] / [`warn!`] / [`error!`] / [`debug!`] macro calls.  For
17//! per-message dynamic tags, use the lower-level [`log()`] function.
18
19use serde::{Deserialize, Deserializer, Serialize, Serializer};
20use std::fmt;
21use std::sync::OnceLock;
22
23pub mod format;
24pub mod sink;
25
26/// Process-wide default tag, set once by [`init`].
27static DEFAULT_TAG: OnceLock<String> = OnceLock::new();
28
29/// Set the process-wide default tag.  Call once at startup, before any
30/// log call.  All [`info!`] / [`warn!`] / [`error!`] / [`debug!`] macros
31/// use this tag after it is set.
32///
33/// # Panics
34///
35/// Panics if called twice (intentional — one tag per process).
36pub fn init(tag: &str) {
37    DEFAULT_TAG
38        .set(tag.to_string())
39        .expect("robonix_scribe::init() called twice; set the tag once per process");
40}
41
42/// Initialise scribe with the process `tag` and apply the on-disk log level
43/// from a launch-config JSON — the system component's manifest config block
44/// that rbnx serialises and passes via `--config-json`. Reads the top-level
45/// `log` key (e.g. `{"log":"debug"}`); a valid level sets the file-sink floor
46/// for this process so the level actually reaches the log file (`rbnx logs`).
47///
48/// Use this instead of [`init`] in binaries launched with a config: the
49/// manifest's per-component `log:` had no effect before, because the level
50/// was parsed into a CLI flag the binary discarded. Absent / unparseable
51/// `log` falls back to the `SCRIBE_FILE_LEVEL` env / `Info` default.
52///
53/// Call once at startup, before the first log, on the main thread.
54pub fn init_from_config(tag: &str, config_json: Option<&str>) {
55    if let Some(level) = config_json
56        .and_then(|j| serde_json::from_str::<serde_json::Value>(j).ok())
57        .and_then(|v| v.get("log").and_then(|l| l.as_str()).and_then(parse_level))
58    {
59        let _ = FILE_LEVEL_OVERRIDE.set(level);
60    }
61    init(tag);
62}
63
64/// Return the process-wide default tag, or `"_default"` if `init()` has
65/// not been called yet.
66#[doc(hidden)]
67pub fn default_tag() -> &'static str {
68    DEFAULT_TAG.get().map(|s| s.as_str()).unwrap_or("_default")
69}
70
71/// Format a nanosecond UNIX timestamp as a local-time readable string:
72/// `"YYYY-MM-DD HH:MM:SS.nnnnnnnnn"`.
73///
74/// This is used for JSON serialisation of [`LogRecord::ts`].
75pub fn ts_fmt(ts_ns: u64) -> String {
76    let secs = (ts_ns / 1_000_000_000) as i64;
77    let nsec = (ts_ns % 1_000_000_000) as u32;
78    #[cfg(unix)]
79    let (year, month, day, hour, min, sec) = {
80        let ts = libc::time_t::try_from(secs).unwrap_or(0);
81        let mut tm: std::mem::MaybeUninit<libc::tm> = std::mem::MaybeUninit::uninit();
82        // SAFETY: localtime_r writes to caller-provided tm; no aliasing.
83        let tm_ptr = unsafe {
84            libc::localtime_r(&ts, tm.as_mut_ptr());
85            tm.assume_init()
86        };
87        (
88            tm_ptr.tm_year + 1900,
89            tm_ptr.tm_mon as u32 + 1,
90            tm_ptr.tm_mday as u32,
91            tm_ptr.tm_hour as u32,
92            tm_ptr.tm_min as u32,
93            tm_ptr.tm_sec as u32,
94        )
95    };
96    #[cfg(not(unix))]
97    let (year, month, day, hour, min, sec) = {
98        let day_secs = secs % 86400;
99        (
100            1970,
101            1u32,
102            1u32,
103            (day_secs / 3600) as u32,
104            ((day_secs % 3600) / 60) as u32,
105            (day_secs % 60) as u32,
106        )
107    };
108    format!("{year:04}-{month:02}-{day:02} {hour:02}:{min:02}:{sec:02}.{nsec:09}")
109}
110
111fn deserialize_ts<'de, D: Deserializer<'de>>(d: D) -> Result<u64, D::Error> {
112    struct TsVisitor;
113    impl serde::de::Visitor<'_> for TsVisitor {
114        type Value = u64;
115        fn expecting(&self, f: &mut fmt::Formatter) -> fmt::Result {
116            f.write_str("a nanosecond timestamp as string or integer")
117        }
118        fn visit_u64<E: serde::de::Error>(self, v: u64) -> Result<u64, E> {
119            Ok(v) // backward compat: accept raw integer
120        }
121        fn visit_str<E: serde::de::Error>(self, v: &str) -> Result<u64, E> {
122            ts_parse(v).ok_or_else(|| E::custom(format!("invalid ts: {v}")))
123        }
124    }
125    d.deserialize_any(TsVisitor)
126}
127
128/// Parse a `ts_fmt`-style string back to nanosecond u64.  Returns `None`
129/// on malformed input.
130pub fn ts_parse(s: &str) -> Option<u64> {
131    // "YYYY-MM-DD HH:MM:SS.nnnnnnnnn" = 29 chars
132    if s.len() < 29 {
133        return None;
134    }
135    let year: i32 = s[0..4].parse().ok()?;
136    let month: u32 = s[5..7].parse().ok()?;
137    let day: u32 = s[8..10].parse().ok()?;
138    let hour: u32 = s[11..13].parse().ok()?;
139    let min: u32 = s[14..16].parse().ok()?;
140    let sec: u32 = s[17..19].parse().ok()?;
141    let nsec: u32 = s[20..29].parse().ok()?;
142    // Build a libc tm for mktime (Unix) or crude UTC calc.
143    #[cfg(unix)]
144    let secs = {
145        let mut tm: libc::tm = unsafe { std::mem::zeroed() };
146        tm.tm_year = year - 1900;
147        tm.tm_mon = month as i32 - 1;
148        tm.tm_mday = day as i32;
149        tm.tm_hour = hour as i32;
150        tm.tm_min = min as i32;
151        tm.tm_sec = sec as i32;
152        tm.tm_isdst = -1; // let libc figure out DST
153        let t = unsafe { libc::mktime(&mut tm) };
154        if t < 0 {
155            // mktime failed (e.g. date out of range for this TZ).
156            // Fall back: compute UTC epoch directly.
157            let days_before: [u32; 12] = [0, 31, 59, 90, 120, 151, 181, 212, 243, 273, 304, 334];
158            let y = year as u32;
159            let leap =
160                |y: u32| y.is_multiple_of(4) && !y.is_multiple_of(100) || y.is_multiple_of(400);
161            let days = (y - 1970) as u64 * 365 + ((y - 1969) / 4) as u64
162                - ((y - 1901) / 100) as u64
163                + ((y - 1601) / 400) as u64
164                + days_before[(month - 1) as usize] as u64
165                + if month > 2 && leap(y) { 1 } else { 0 }
166                + day as u64
167                - 1;
168            days * 86400 + hour as u64 * 3600 + min as u64 * 60 + sec as u64
169        } else {
170            t as u64
171        }
172    };
173    let ts_ns = secs.checked_mul(1_000_000_000)?.checked_add(nsec as u64)?;
174    #[cfg(not(unix))]
175    let secs = {
176        let days_before_month: [u32; 12] = [0, 31, 59, 90, 120, 151, 181, 212, 243, 273, 304, 334];
177        let y = year as u32;
178        let leap = |y: u32| y.is_multiple_of(4) && !y.is_multiple_of(100) || y.is_multiple_of(400);
179        let days = (y - 1970) * 365 + ((y - 1969) / 4) - ((y - 1901) / 100)
180            + ((y - 1601) / 400)
181            + days_before_month[(month - 1) as usize]
182            + if month > 2 && leap(y) { 1 } else { 0 }
183            + day
184            - 1;
185        days as u64 * 86400 + hour as u64 * 3600 + min as u64 * 60 + sec as u64
186    };
187    Some(ts_ns)
188}
189
190/// Severity level, ordered `Debug < Info < Warn < Error`.
191#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Serialize, Deserialize)]
192#[serde(rename_all = "lowercase")]
193pub enum Level {
194    Debug,
195    Info,
196    Warn,
197    Error,
198}
199
200impl Level {
201    /// Single-character code used in console output.
202    pub fn code(self) -> &'static str {
203        match self {
204            Level::Debug => "D",
205            Level::Info => "I",
206            Level::Warn => "W",
207            Level::Error => "E",
208        }
209    }
210}
211
212impl fmt::Display for Level {
213    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
214        f.write_str(self.code())
215    }
216}
217
218/// A single structured log record.
219///
220/// `ts` is nanoseconds since UNIX epoch internally; serialised as a
221/// human-readable `"YYYY-MM-DD HH:MM:SS.nnnnnnnnn"` string in JSON.
222#[derive(Debug, Clone, Deserialize)]
223pub struct LogRecord {
224    /// Nanosecond UNIX timestamp (internal u64; JSON: readable string).
225    #[serde(deserialize_with = "deserialize_ts")]
226    pub ts: u64,
227    /// Severity.
228    pub level: Level,
229    /// Source identifier — `provider_id` or component name.
230    pub tag: String,
231    /// Free-form log message body.
232    pub msg: String,
233}
234
235// Manual Serialize impl needed because we can't mix derive(Serialize) with
236// field-level serialize_with on a non-structural level in a derive.
237impl Serialize for LogRecord {
238    fn serialize<S: Serializer>(&self, s: S) -> Result<S::Ok, S::Error> {
239        use serde::ser::SerializeStruct;
240        let mut st = s.serialize_struct("LogRecord", 4)?;
241        st.serialize_field("ts", &ts_fmt(self.ts))?;
242        st.serialize_field("level", &self.level)?;
243        st.serialize_field("tag", &self.tag)?;
244        st.serialize_field("msg", &self.msg)?;
245        st.end()
246    }
247}
248
249impl LogRecord {
250    /// Create a new record with the current wall-clock timestamp (u64 ns).
251    pub fn now(level: Level, tag: impl Into<String>, msg: impl Into<String>) -> Self {
252        let ts = system_time_ns();
253        Self {
254            ts,
255            level,
256            tag: tag.into(),
257            msg: msg.into(),
258        }
259    }
260}
261
262/// Best-effort nanosecond timestamp from `SystemTime`.
263///
264/// When chronos lands this will become `chronos::now()`.
265fn system_time_ns() -> u64 {
266    use std::time::{SystemTime, UNIX_EPOCH};
267    SystemTime::now()
268        .duration_since(UNIX_EPOCH)
269        .map(|d| d.as_nanos() as u64)
270        .unwrap_or(0)
271}
272
273// ── Global lazy state ──────────────────────────────────────────────
274
275use std::sync::LazyLock;
276
277use crate::sink::FileSink;
278
279// ── Level filter thresholds / directory / sink ──────────────────────
280
281/// Resolved log directory — `$SCRIBE_LOG_DIR` or `"./logs"`.
282static LOG_DIR: LazyLock<std::path::PathBuf> = LazyLock::new(|| {
283    std::env::var("SCRIBE_LOG_DIR")
284        .map(std::path::PathBuf::from)
285        .unwrap_or_else(|_| std::path::PathBuf::from("./logs"))
286});
287
288/// Global file sink; `None` when the log directory can't be created
289/// (read-only filesystem, full disk, etc.).  When `None`, file writes
290/// are silently skipped — the process keeps running console-only.
291static FILE_SINK: LazyLock<Option<FileSink>> =
292    LazyLock::new(|| FileSink::new(LOG_DIR.as_path()).ok());
293
294// ── Level filter thresholds (read from env, lazy) ───────────────────
295
296/// Parse a level word (`debug`/`info`/`warn`/`warning`/`error`,
297/// case-insensitive). `None` for anything else.
298fn parse_level(s: &str) -> Option<Level> {
299    match s.to_lowercase().as_str() {
300        "debug" => Some(Level::Debug),
301        "info" => Some(Level::Info),
302        "warn" | "warning" => Some(Level::Warn),
303        "error" => Some(Level::Error),
304        _ => None,
305    }
306}
307
308/// Parse `SCRIBE_CONSOLE_LEVEL` / `SCRIBE_FILE_LEVEL` env var to a
309/// numeric floor.  Unrecognised values default to the given fallback.
310fn parse_level_env(key: &str, fallback: Level) -> Level {
311    std::env::var(key)
312        .ok()
313        .as_deref()
314        .and_then(parse_level)
315        .unwrap_or(fallback)
316}
317
318/// Per-process on-disk level override, set once by [`init_from_config`] from
319/// the launch config's `log` key. Takes precedence over `SCRIBE_FILE_LEVEL`
320/// when present, so a per-component `log:` in the deploy manifest actually
321/// controls that component's log file.
322static FILE_LEVEL_OVERRIDE: OnceLock<Level> = OnceLock::new();
323
324/// Minimum level for console (stderr) output.
325///
326/// Default: [`Level::Warn`]  — only Warn + Error reach the terminal.
327/// Set `SCRIBE_CONSOLE_LEVEL=info` to also see Info, or
328/// `SCRIBE_CONSOLE_LEVEL=debug` for everything.
329static CONSOLE_MIN: LazyLock<Level> =
330    LazyLock::new(|| parse_level_env("SCRIBE_CONSOLE_LEVEL", Level::Warn));
331
332/// Minimum level for per-tag log files.
333///
334/// Default: [`Level::Info`]  — Debug is suppressed on disk unless
335/// `SCRIBE_FILE_LEVEL=debug` is set.  Set `SCRIBE_FILE_LEVEL=error`
336/// to only persist errors.
337static FILE_MIN: LazyLock<Level> =
338    LazyLock::new(|| parse_level_env("SCRIBE_FILE_LEVEL", Level::Info));
339
340// ── Public API ─────────────────────────────────────────────────────
341
342/// Log a record with the given `level`, `tag`, and `msg`.
343///
344/// This is the **only** entry point for structured logging.  The first
345/// call transparently initialises the log directory and file sink.
346///
347/// # Per-sink level filtering
348///
349/// | Level  | Console (default) | File (default) |
350/// |--------|:-----:|:----:|
351/// | Debug  |  ✗    |  ✗   |
352/// | Info   |  ✗    |  ✓   |
353/// | Warn   |  ✓    |  ✓   |
354/// | Error  |  ✓    |  ✓   |
355///
356/// Override with `SCRIBE_CONSOLE_LEVEL` / `SCRIBE_FILE_LEVEL`.
357pub fn log(level: Level, tag: &str, msg: &str) {
358    // Only construct the timestamped record when at least one sink
359    // accepts this level — avoid wasted clock syscalls for Debug.
360    let console_ok = level >= *CONSOLE_MIN;
361    let file_min = FILE_LEVEL_OVERRIDE.get().copied().unwrap_or(*FILE_MIN);
362    let file_ok = level >= file_min;
363    if !console_ok && !file_ok {
364        return;
365    }
366    let record = LogRecord::now(level, tag, msg);
367    if console_ok {
368        let _ = format::write_console(&record);
369    }
370    if file_ok && let Some(sink) = FILE_SINK.as_ref() {
371        let _ = sink.write(&record);
372    }
373}
374
375/// Convenience: [`Level::Debug`].
376pub fn debug(tag: &str, msg: &str) {
377    log(Level::Debug, tag, msg);
378}
379
380/// Convenience: [`Level::Info`].
381pub fn info(tag: &str, msg: &str) {
382    log(Level::Info, tag, msg);
383}
384
385/// Convenience: [`Level::Warn`].
386pub fn warn(tag: &str, msg: &str) {
387    log(Level::Warn, tag, msg);
388}
389
390/// Convenience: [`Level::Error`].
391pub fn error(tag: &str, msg: &str) {
392    log(Level::Error, tag, msg);
393}
394
395/// Ingest a captured stdout/stderr line from a child process under `tag`.
396///
397/// A child that uses Scribe (Python `scribe_logger` in a docker container,
398/// or any binary that mirrors records to its console) emits lines already in
399/// console format — `MM-DD HH:MM:SS.mmm  L tag  msg`. Re-logging the whole
400/// line as a fresh record's `msg` double-stamps the timestamp/level/tag (it
401/// appears once in the JSON fields and again embedded in `msg`). When the line
402/// is recognised as Scribe console output, strip the prefix and re-emit just
403/// the inner message at its original level under `tag`; otherwise treat the
404/// line as opaque output and log it verbatim at Info.
405pub fn ingest(tag: &str, line: &str) {
406    match parse_console_line(line) {
407        Some((level, msg)) => log(level, tag, msg),
408        None => info(tag, line),
409    }
410}
411
412/// Recognise a Scribe console line and return its `(level, inner message)`.
413///
414/// Layout (see `format::format_console`): two-digit `MM-DD`, space, `HH:MM:SS`,
415/// `.mmm`, two spaces, a single level char `D/I/W/E`, space, the tag padded to
416/// 24 columns, space, then the message at byte 47. Validated by fixed ASCII
417/// positions so a non-Scribe line (e.g. raw ROS2 output) falls through to None.
418fn parse_console_line(line: &str) -> Option<(Level, &str)> {
419    let b = line.as_bytes();
420    // Shortest possible: 47-char prefix + at least one msg byte.
421    if b.len() < 48 {
422        return None;
423    }
424    if b[2] != b'-'
425        || b[5] != b' '
426        || b[8] != b':'
427        || b[11] != b':'
428        || b[14] != b'.'
429        || b[18] != b' '
430        || b[19] != b' '
431        || b[21] != b' '
432        || b[46] != b' '
433    {
434        return None;
435    }
436    for &i in &[0usize, 1, 3, 4, 6, 7, 9, 10, 12, 13, 15, 16, 17] {
437        if !b[i].is_ascii_digit() {
438            return None;
439        }
440    }
441    let level = match b[20] {
442        b'D' => Level::Debug,
443        b'I' => Level::Info,
444        b'W' => Level::Warn,
445        b'E' => Level::Error,
446        _ => return None,
447    };
448    // Byte 47 is the first message byte; it is a char boundary because bytes
449    // 0..=46 are all ASCII when every check above passed.
450    line.get(47..).map(|msg| (level, msg))
451}
452
453// ── Macros — process-wide default tag ───────────────────────────────
454
455/// Log at INFO level using the process-wide default tag set by [`init`].
456///
457/// ```rust,ignore
458/// robonix_scribe::init("executor");
459/// robonix_scribe::info!("connecting to atlas at {}", addr);
460/// ```
461#[macro_export]
462macro_rules! info {
463    ($($arg:tt)*) => {
464        $crate::log($crate::Level::Info, $crate::default_tag(), &format!($($arg)*))
465    };
466}
467
468/// Log at WARN level using the process-wide default tag set by [`init`].
469#[macro_export]
470macro_rules! warn {
471    ($($arg:tt)*) => {
472        $crate::log($crate::Level::Warn, $crate::default_tag(), &format!($($arg)*))
473    };
474}
475
476/// Log at ERROR level using the process-wide default tag set by [`init`].
477#[macro_export]
478macro_rules! error {
479    ($($arg:tt)*) => {
480        $crate::log($crate::Level::Error, $crate::default_tag(), &format!($($arg)*))
481    };
482}
483
484/// Log at DEBUG level using the process-wide default tag set by [`init`].
485#[macro_export]
486macro_rules! debug {
487    ($($arg:tt)*) => {
488        $crate::log($crate::Level::Debug, $crate::default_tag(), &format!($($arg)*))
489    };
490}
491
492// ── Tests ───────────────────────────────────────────────────────────
493
494#[cfg(test)]
495mod tests {
496    use super::*;
497
498    #[test]
499    fn level_codes() {
500        assert_eq!(Level::Debug.code(), "D");
501        assert_eq!(Level::Info.code(), "I");
502        assert_eq!(Level::Warn.code(), "W");
503        assert_eq!(Level::Error.code(), "E");
504    }
505
506    #[test]
507    fn parse_console_round_trips_formatter() {
508        // A line produced by format_console must parse back to its level + msg,
509        // so re-ingesting a child's console echo strips the prefix (no
510        // double-stamped timestamp/tag).
511        for (level, msg) in [
512            (Level::Info, "[nav2] [smoother_server-2] launched."),
513            (Level::Warn, "rtabmap: republishing map"),
514            (Level::Error, "webui GET /api/map.png failed"),
515            (Level::Debug, "x"),
516        ] {
517            let rec = LogRecord::now(level, "nav2", msg);
518            let line = format::format_console(&rec);
519            let line = line.trim_end_matches('\n');
520            assert_eq!(
521                parse_console_line(line),
522                Some((level, msg)),
523                "line={line:?}"
524            );
525        }
526    }
527
528    #[test]
529    fn parse_console_rejects_non_console_lines() {
530        // Raw child output (ROS2 logs, start-script prints) must fall through.
531        for raw in [
532            "[nav2/start] mode=docker (FORCE= PLATFORM=)",
533            "[INFO] [1782660318.498] [planner_server]: activating",
534            "",
535            "short",
536            "06-28 15:41:51.183 X nav2  bad level char",
537        ] {
538            assert_eq!(parse_console_line(raw), None, "raw={raw:?}");
539        }
540    }
541
542    #[test]
543    fn level_display_is_code() {
544        assert_eq!(Level::Info.to_string(), "I");
545    }
546
547    #[test]
548    fn level_ordering() {
549        assert!(Level::Debug < Level::Info);
550        assert!(Level::Info < Level::Warn);
551        assert!(Level::Warn < Level::Error);
552    }
553
554    #[test]
555    fn log_record_serialization_is_readable_string() {
556        let rec = LogRecord {
557            ts: 1765432100123456789,
558            level: Level::Info,
559            tag: "scene_svc".into(),
560            msg: "object registered".into(),
561        };
562        let json = serde_json::to_string(&rec).unwrap();
563        // ts is now a human-readable "YYYY-MM-DD HH:MM:SS.nnnnnnnnn" string.
564        assert!(
565            json.contains(r#""ts":""#),
566            "ts should be a JSON string, got: {json}"
567        );
568        assert!(json.contains(r#""level":"info""#));
569        assert!(json.contains(r#""tag":"scene_svc""#));
570        assert!(json.contains(r#""msg":"object registered""#));
571    }
572
573    #[test]
574    fn log_record_deserialization_readable_string() {
575        // New format: ts as readable string
576        let json = r#"{"ts":"2025-12-11 13:48:20.123456789","level":"info","tag":"scene_svc","msg":"object registered"}"#;
577        let rec: LogRecord = serde_json::from_str(json).unwrap();
578        assert_eq!(rec.level, Level::Info);
579        assert_eq!(rec.tag, "scene_svc");
580        assert_eq!(rec.msg, "object registered");
581        // The nanosecond value depends on local TZ → we just verify it's non-zero
582        assert!(rec.ts > 0, "parsed ts should be positive");
583    }
584
585    #[test]
586    fn log_record_deserialization_legacy_integer() {
587        // Legacy format: ts as raw integer (backward compat)
588        let json = r#"{"ts":1765432100123456789,"level":"info","tag":"scene_svc","msg":"object registered"}"#;
589        let rec: LogRecord = serde_json::from_str(json).unwrap();
590        assert_eq!(rec.ts, 1765432100123456789);
591        assert_eq!(rec.level, Level::Info);
592        assert_eq!(rec.tag, "scene_svc");
593        assert_eq!(rec.msg, "object registered");
594    }
595
596    #[test]
597    fn log_record_roundtrip() {
598        let rec = LogRecord {
599            ts: 1_700_000_000_000_000_000,
600            level: Level::Error,
601            tag: "test".into(),
602            msg: "roundtrip".into(),
603        };
604        let json = serde_json::to_string(&rec).unwrap();
605        let back: LogRecord = serde_json::from_str(&json).unwrap();
606        assert_eq!(back.level, rec.level);
607        assert_eq!(back.tag, rec.tag);
608        assert_eq!(back.msg, rec.msg);
609        // ts may differ slightly due to TZ roundtrip; verify within 1 day
610        let diff = back.ts.abs_diff(rec.ts);
611        assert!(
612            diff < 86_400_000_000_000,
613            "roundtrip ts diff too large: {diff} ns"
614        );
615    }
616
617    #[test]
618    fn log_record_now_has_reasonable_ts() {
619        let rec = LogRecord::now(Level::Debug, "test", "hello");
620        // After 2020-01-01 in nanos
621        assert!(rec.ts > 1_577_836_800_000_000_000);
622        // Not in the far future
623        assert!(rec.ts < 4_000_000_000_000_000_000);
624    }
625
626    // ── log() integration tests ─────────────────────────────────
627    //
628    // NOTE: FILE_SINK is a LazyLock — it initialises once per process.
629    // These tests only verify the public API does not panic and that
630    // convenience wrappers route to the correct level.  File/directory
631    // behaviour is covered exhaustively by `sink::tests`.
632
633    #[test]
634    fn log_does_not_panic() {
635        log(Level::Debug, "smoke", "smoke test");
636        debug("smoke_d", "debug smoke");
637        info("smoke_i", "info smoke");
638        warn("smoke_w", "warn smoke");
639        error("smoke_e", "error smoke");
640    }
641
642    #[test]
643    fn convenience_wrappers_use_correct_levels() {
644        // Verify by inspecting a LogRecord produced by each wrapper.
645        let r_d = LogRecord::now(Level::Debug, "t", "d");
646        let r_i = LogRecord::now(Level::Info, "t", "i");
647        let r_w = LogRecord::now(Level::Warn, "t", "w");
648        let r_e = LogRecord::now(Level::Error, "t", "e");
649        assert_eq!(r_d.level, Level::Debug);
650        assert_eq!(r_i.level, Level::Info);
651        assert_eq!(r_w.level, Level::Warn);
652        assert_eq!(r_e.level, Level::Error);
653    }
654
655    #[test]
656    fn default_log_dir_is_dot_logs() {
657        let default = std::env::var("SCRIBE_LOG_DIR")
658            .map(std::path::PathBuf::from)
659            .unwrap_or_else(|_| std::path::PathBuf::from("./logs"));
660        assert_eq!(default, std::path::PathBuf::from("./logs"));
661    }
662
663    #[test]
664    fn default_tag_is_default_until_init() {
665        assert_eq!(default_tag(), "_default");
666    }
667
668    #[test]
669    fn macro_info_uses_default_tag() {
670        // This test parses the msg field to verify the tag used.
671        // We can't easily intercept the macro's output in unit tests,
672        // so we verify the default_tag() function works correctly.
673        // The actual macro routing is smoke-tested in integration.
674        assert_eq!(default_tag(), "_default");
675    }
676}
robonix_scribe/lib.rs

robonix_scribe/
lib.rs
