freeswitch_log_parser/
line.rs

1pub(crate) use crate::uuid::{is_uuid_at, UUID_PREFIX_LEN};
2use freeswitch_types::LogLevel;
3
4use crate::mask::Mask;
5use crate::uuid::{find_uuid_in, UUID_LEN};
6
7use std::fmt;
8use std::ops::Range;
9
10/// Classification of a single log line's structural format.
11///
12/// FreeSWITCH's `switch_log_printf` emits five distinct line shapes depending
13/// on whether a session UUID is active, whether the line has a timestamp, and
14/// whether a buffer collision truncated the output; a blank line is the sixth
15/// kind. The full anatomy is documented in the repository's CLAUDE.md.
16#[non_exhaustive]
17#[derive(Debug, Clone, Copy, PartialEq, Eq)]
18pub enum LineKind {
19    /// Format A — UUID, timestamp, idle%, level, source, and message.
20    Full,
21    /// Format B — same as `Full` but without a UUID prefix (system/global events).
22    System,
23    /// Format C — UUID and message only, no timestamp or level.
24    UuidContinuation,
25    /// Format D — raw text with no UUID or timestamp; inherits context from the previous entry.
26    BareContinuation,
27    /// Format E — buffer collision produced a garbage prefix before the UUID.
28    Truncated,
29    /// Blank or whitespace-only line.
30    Empty,
31}
32
33impl fmt::Display for LineKind {
34    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
35        match self {
36            LineKind::Full => f.pad("full"),
37            LineKind::System => f.pad("system"),
38            LineKind::UuidContinuation => f.pad("uuid-cont"),
39            LineKind::BareContinuation => f.pad("bare-cont"),
40            LineKind::Truncated => f.pad("truncated"),
41            LineKind::Empty => f.pad("empty"),
42        }
43    }
44}
45
46/// Zero-copy result of parsing a single log line.
47///
48/// Fields are `None` when the line's format doesn't include them (e.g. a
49/// `BareContinuation` has no `uuid`, `timestamp`, `level`, or `source`).
50/// The `message` field always contains the remaining text.
51#[derive(Debug, PartialEq, Eq)]
52pub struct RawLine<'a> {
53    /// Session UUID, present for `Full`, `UuidContinuation`, and `Truncated` lines.
54    pub uuid: Option<&'a str>,
55    /// Microsecond-precision timestamp, present only for `Full` and `System` lines.
56    pub timestamp: Option<&'a str>,
57    /// Core scheduler idle percentage (e.g. `"95.97%"`), a system health indicator.
58    pub idle_pct: Option<&'a str>,
59    /// Log severity, present only for `Full` and `System` lines.
60    pub level: Option<LogLevel>,
61    /// Source file and line (e.g. `"sofia.c:7624"`), present only for `Full` and `System` lines.
62    pub source: Option<&'a str>,
63    /// The message text after all structured fields have been consumed.
64    pub message: &'a str,
65    /// Which line shape this line matched.
66    pub kind: LineKind,
67}
68
69pub(crate) fn is_date_at(bytes: &[u8], offset: usize) -> bool {
70    if bytes.len() < offset + 5 {
71        return false;
72    }
73    bytes[offset..offset + 4].iter().all(u8::is_ascii_digit) && bytes[offset + 4] == b'-'
74}
75
76/// `YYYY-MM-DD HH:MM:SS.ffffff`, the width `mod_logfile` writes.
77const TIMESTAMP_LEN: usize = 26;
78
79const TIMESTAMP_MASK: Mask = Mask {
80    len: TIMESTAMP_LEN,
81    separators: &[
82        (4, b'-'),
83        (7, b'-'),
84        (10, b' '),
85        (13, b':'),
86        (16, b':'),
87        (19, b'.'),
88    ],
89    filler: u8::is_ascii_digit,
90};
91
92/// Widest idle field the logger can write, `"100.00%"`.
93const MAX_IDLE_PCT_LEN: usize = 7;
94
95/// Where a FreeSWITCH log header's fields sit, as offsets into the bytes it
96/// was found in.
97pub(crate) struct HeaderSpan {
98    timestamp: Range<usize>,
99    idle_pct: Option<Range<usize>>,
100    /// Offset of the `[` opening the level.
101    level: usize,
102}
103
104/// The `D+.D+%` idle field at `from`. The logger writes it followed by a
105/// space, so anything else there is not one.
106fn idle_pct_span(bytes: &[u8], from: usize) -> Option<Range<usize>> {
107    let end = (from + MAX_IDLE_PCT_LEN).min(bytes.len());
108    let window = bytes.get(from..end)?;
109    let pct = window.iter().position(|&b| b == b'%')?;
110    if !window[0].is_ascii_digit()
111        || !window[..pct]
112            .iter()
113            .all(|&b| b.is_ascii_digit() || b == b'.')
114    {
115        return None;
116    }
117    (bytes.get(from + pct + 1) == Some(&b' ')).then(|| from..from + pct + 1)
118}
119
120/// The spans of a full FreeSWITCH log header at `offset`:
121/// `YYYY-MM-DD HH:MM:SS.ffffff [D+.D+% ][LEVEL]`.
122///
123/// The idle percentage is optional — older/eSInet FS builds omit it and emit
124/// `[LEVEL]` directly after the timestamp — but the level bracket is not, so a
125/// line the logger cut before it reads as no header rather than as one with an
126/// idle field and nothing else.
127pub(crate) fn header_at(bytes: &[u8], offset: usize) -> Option<HeaderSpan> {
128    if !TIMESTAMP_MASK.matches_at(bytes, offset) || bytes.get(offset + TIMESTAMP_LEN) != Some(&b' ')
129    {
130        return None;
131    }
132
133    let after_stamp = offset + TIMESTAMP_LEN + 1;
134    let idle_pct = idle_pct_span(bytes, after_stamp);
135    let level = idle_pct.as_ref().map_or(after_stamp, |r| r.end + 1);
136    if bytes.get(level) != Some(&b'[') {
137        return None;
138    }
139
140    Some(HeaderSpan {
141        timestamp: offset..offset + TIMESTAMP_LEN,
142        idle_pct,
143        level,
144    })
145}
146
147/// Longest name in the switch's `LEVELS[]`, `"CONSOLE"`.
148const MAX_LEVEL_LEN: usize = 7;
149
150/// Whether the `[` at `level` closes over a name the field can hold.
151fn level_field_closes(bytes: &[u8], level: usize) -> bool {
152    let end = (level + MAX_LEVEL_LEN + 2).min(bytes.len());
153    bytes
154        .get(level + 1..end)
155        .and_then(|w| w.iter().position(|&b| b == b']'))
156        .is_some_and(|p| p > 0)
157}
158
159/// Whether a complete FreeSWITCH log header starts at `offset`.
160///
161/// Used by Layer 2 to detect same-line collisions where multiple log entries
162/// were concatenated without a newline (thread contention on file write, or a
163/// caller format string missing its trailing `\n`). A record starts only at a
164/// header whose level field closes: an open bracket is a header the write
165/// budget cut, and splitting there invents a boundary the file does not hold.
166pub(crate) fn is_log_header_at(bytes: &[u8], offset: usize) -> bool {
167    header_at(bytes, offset).is_some_and(|h| level_field_closes(bytes, h.level))
168}
169
170/// The [`LogLevel`] inside a header's `[LEVEL]` field, or `None` when the
171/// brackets are missing or hold no level the switch knows.
172///
173/// `LogLevel`'s own `FromStr` is the switch's case-sensitive `LEVELS[]` lookup
174/// and the log spells the level in upper case, so the names are compared here
175/// instead: folding the name would allocate on every header line.
176pub fn level_from_bracketed(s: &str) -> Option<LogLevel> {
177    let inner = s.strip_prefix('[')?.strip_suffix(']')?;
178    LogLevel::ALL
179        .iter()
180        .find(|l| l.as_str().eq_ignore_ascii_case(inner))
181        .copied()
182}
183
184/// The header slices at bytes 26/27 (timestamp + separating space) are only
185/// valid when both land on char boundaries — a multi-byte char straddling
186/// either offset means the line is not a Format A/B header.
187fn header_boundaries_ok(s: &str) -> bool {
188    s.len() < 27 || (s.is_char_boundary(26) && s.is_char_boundary(27))
189}
190
191/// The structured fields of a timestamped line, each `None` where the line
192/// stops short of it.
193struct LineHeader<'a> {
194    timestamp: Option<&'a str>,
195    idle_pct: Option<&'a str>,
196    level: Option<LogLevel>,
197    source: Option<&'a str>,
198    message: &'a str,
199}
200
201fn parse_timestamped_fields(s: &str) -> LineHeader<'_> {
202    if s.len() < TIMESTAMP_LEN + 1 {
203        return LineHeader {
204            timestamp: None,
205            idle_pct: None,
206            level: None,
207            source: None,
208            message: s,
209        };
210    }
211    let (timestamp, idle_pct, rest) = match header_at(s.as_bytes(), 0) {
212        Some(h) => (&s[h.timestamp], h.idle_pct.map(|r| &s[r]), &s[h.level..]),
213        None => (&s[..TIMESTAMP_LEN], None, &s[TIMESTAMP_LEN + 1..]),
214    };
215    let timestamp = Some(timestamp);
216
217    let bracket_end = match rest.find(']') {
218        Some(p) => p,
219        None => {
220            return LineHeader {
221                timestamp,
222                idle_pct,
223                level: None,
224                source: None,
225                message: rest,
226            }
227        }
228    };
229    let level = level_from_bracketed(&rest[0..=bracket_end]);
230
231    if rest.len() < bracket_end + 3 || !rest.is_char_boundary(bracket_end + 2) {
232        return LineHeader {
233            timestamp,
234            idle_pct,
235            level,
236            source: None,
237            message: "",
238        };
239    }
240    let rest = &rest[bracket_end + 2..];
241
242    let source_end = rest.find(' ').unwrap_or(rest.len());
243    let message = if source_end < rest.len() {
244        &rest[source_end + 1..]
245    } else {
246        ""
247    };
248
249    LineHeader {
250        timestamp,
251        idle_pct,
252        level,
253        source: Some(&rest[0..source_end]),
254        message,
255    }
256}
257
258/// Layer 1 entry point: classify a single line and extract its fields.
259///
260/// Pure function — no state, no allocation. All returned string slices borrow
261/// from the input. Use [`classify_message`](crate::classify_message) on the
262/// `message` field for semantic classification.
263pub fn parse_line(line: &str) -> RawLine<'_> {
264    if line.trim().is_empty() {
265        return RawLine {
266            uuid: None,
267            timestamp: None,
268            idle_pct: None,
269            level: None,
270            source: None,
271            message: line,
272            kind: LineKind::Empty,
273        };
274    }
275
276    let bytes = line.as_bytes();
277
278    if is_uuid_at(bytes, 0) {
279        let uuid = &line[0..UUID_LEN];
280        let after_uuid = &line[UUID_PREFIX_LEN..];
281
282        if is_date_at(bytes, UUID_PREFIX_LEN) && header_boundaries_ok(after_uuid) {
283            let h = parse_timestamped_fields(after_uuid);
284            return RawLine {
285                uuid: Some(uuid),
286                timestamp: h.timestamp,
287                idle_pct: h.idle_pct,
288                level: h.level,
289                source: h.source,
290                message: h.message,
291                kind: LineKind::Full,
292            };
293        }
294
295        return RawLine {
296            uuid: Some(uuid),
297            timestamp: None,
298            idle_pct: None,
299            level: None,
300            source: None,
301            message: after_uuid,
302            kind: LineKind::UuidContinuation,
303        };
304    }
305
306    if is_date_at(bytes, 0) && header_boundaries_ok(line) {
307        let h = parse_timestamped_fields(line);
308        let (uuid, message) = if is_uuid_at(h.message.as_bytes(), 0) {
309            (Some(&h.message[0..UUID_LEN]), &h.message[UUID_PREFIX_LEN..])
310        } else {
311            (None, h.message)
312        };
313        return RawLine {
314            uuid,
315            timestamp: h.timestamp,
316            idle_pct: h.idle_pct,
317            level: h.level,
318            source: h.source,
319            message,
320            kind: LineKind::System,
321        };
322    }
323
324    if let Some(uuid_start) = find_uuid_in(bytes) {
325        let uuid = &line[uuid_start..uuid_start + UUID_LEN];
326        let message = if line.len() > uuid_start + UUID_PREFIX_LEN {
327            &line[uuid_start + UUID_PREFIX_LEN..]
328        } else {
329            ""
330        };
331        return RawLine {
332            uuid: Some(uuid),
333            timestamp: None,
334            idle_pct: None,
335            level: None,
336            source: None,
337            message,
338            kind: LineKind::Truncated,
339        };
340    }
341
342    RawLine {
343        uuid: None,
344        timestamp: None,
345        idle_pct: None,
346        level: None,
347        source: None,
348        message: line,
349        kind: LineKind::BareContinuation,
350    }
351}
352
353#[cfg(test)]
354mod tests {
355    use super::*;
356
357    const UUID1: &str = "a1b2c3d4-e5f6-7890-abcd-ef1234567890";
358
359    // --- Format A (Full) ---
360
361    #[test]
362    fn full_line_all_fields() {
363        let line = format!(
364            "{UUID1} 2025-01-15 10:30:45.123456 95.97% [DEBUG] sofia.c:100 Test message here"
365        );
366        let parsed = parse_line(&line);
367        assert_eq!(parsed.kind, LineKind::Full);
368        assert_eq!(parsed.uuid, Some(UUID1));
369        assert_eq!(parsed.timestamp, Some("2025-01-15 10:30:45.123456"));
370        assert_eq!(parsed.idle_pct, Some("95.97%"));
371        assert_eq!(parsed.level, Some(LogLevel::Debug));
372        assert_eq!(parsed.source, Some("sofia.c:100"));
373        assert_eq!(parsed.message, "Test message here");
374    }
375
376    #[test]
377    fn full_line_each_level() {
378        for (name, expected) in [
379            ("DEBUG", LogLevel::Debug),
380            ("INFO", LogLevel::Info),
381            ("NOTICE", LogLevel::Notice),
382            ("WARNING", LogLevel::Warning),
383            ("ERR", LogLevel::Error),
384            ("CRIT", LogLevel::Crit),
385            ("ALERT", LogLevel::Alert),
386            ("CONSOLE", LogLevel::Console),
387        ] {
388            let line =
389                format!("{UUID1} 2025-01-15 10:30:45.123456 95.97% [{name}] sofia.c:100 Test");
390            let parsed = parse_line(&line);
391            assert_eq!(parsed.kind, LineKind::Full);
392            assert_eq!(parsed.level, Some(expected), "failed for [{name}]");
393        }
394    }
395
396    #[test]
397    fn full_line_high_idle() {
398        let line =
399            format!("{UUID1} 2025-01-15 10:30:45.123456 99.99% [DEBUG] sofia.c:100 High idle");
400        let parsed = parse_line(&line);
401        assert_eq!(parsed.idle_pct, Some("99.99%"));
402    }
403
404    #[test]
405    fn full_line_low_idle() {
406        let line = format!("{UUID1} 2025-01-15 10:30:45.123456 0.00% [DEBUG] sofia.c:100 Low idle");
407        let parsed = parse_line(&line);
408        assert_eq!(parsed.idle_pct, Some("0.00%"));
409    }
410
411    /// The field is written `"% "`. Without the space it is not one, and
412    /// reporting it as one claimed a scheduler reading off a corrupt line.
413    #[test]
414    fn idle_pct_requires_the_space_after_the_sign() {
415        let line = format!("{UUID1} 2025-01-15 10:30:45.123456 9%X[DEBUG] sofia.c:100 Message");
416        assert_eq!(parse_line(&line).idle_pct, None);
417    }
418
419    #[test]
420    fn full_line_long_message() {
421        let line = format!(
422            "{UUID1} 2025-01-15 10:30:45.123456 95.97% [DEBUG] sofia.c:100 Channel [sofia/internal] key=val:123 (test) {{braces}}"
423        );
424        let parsed = parse_line(&line);
425        assert_eq!(
426            parsed.message,
427            "Channel [sofia/internal] key=val:123 (test) {braces}"
428        );
429    }
430
431    // --- Format B (System) ---
432
433    #[test]
434    fn system_line_no_uuid() {
435        let line =
436            "2025-01-15 10:30:45.123456 95.97% [INFO] mod_event_socket.c:1772 Event Socket command";
437        let parsed = parse_line(line);
438        assert_eq!(parsed.kind, LineKind::System);
439        assert_eq!(parsed.uuid, None);
440        assert_eq!(parsed.timestamp, Some("2025-01-15 10:30:45.123456"));
441        assert_eq!(parsed.idle_pct, Some("95.97%"));
442        assert_eq!(parsed.level, Some(LogLevel::Info));
443        assert_eq!(parsed.source, Some("mod_event_socket.c:1772"));
444        assert_eq!(parsed.message, "Event Socket command");
445    }
446
447    #[test]
448    fn system_line_with_embedded_uuid() {
449        let line = format!(
450            "2025-01-15 10:30:45.123456 95.97% [DEBUG] switch_cpp.cpp:1466 {UUID1} DAA-LOG WaveManager PSAP 911 originate"
451        );
452        let parsed = parse_line(&line);
453        assert_eq!(parsed.kind, LineKind::System);
454        assert_eq!(parsed.uuid, Some(UUID1));
455        assert_eq!(parsed.timestamp, Some("2025-01-15 10:30:45.123456"));
456        assert_eq!(parsed.level, Some(LogLevel::Debug));
457        assert_eq!(parsed.source, Some("switch_cpp.cpp:1466"));
458        assert_eq!(parsed.message, "DAA-LOG WaveManager PSAP 911 originate");
459    }
460
461    #[test]
462    fn system_line_with_embedded_uuid_empty_message() {
463        let line = format!("2025-01-15 10:30:45.123456 95.97% [INFO] switch_cpp.cpp:1466 {UUID1} ");
464        let parsed = parse_line(&line);
465        assert_eq!(parsed.kind, LineKind::System);
466        assert_eq!(parsed.uuid, Some(UUID1));
467        assert_eq!(parsed.message, "");
468    }
469
470    #[test]
471    fn system_line_without_embedded_uuid() {
472        let line =
473            "2025-01-15 10:30:45.123456 95.97% [INFO] mod_event_socket.c:1772 Event Socket command";
474        let parsed = parse_line(line);
475        assert_eq!(parsed.kind, LineKind::System);
476        assert_eq!(parsed.uuid, None);
477        assert_eq!(parsed.message, "Event Socket command");
478    }
479
480    #[test]
481    fn system_line_event_socket() {
482        let line = "2025-01-15 10:30:45.123456 95.97% [NOTICE] mod_logfile.c:217 New log started.";
483        let parsed = parse_line(line);
484        assert_eq!(parsed.kind, LineKind::System);
485        assert_eq!(parsed.level, Some(LogLevel::Notice));
486        assert_eq!(parsed.message, "New log started.");
487    }
488
489    // --- Format C (UuidContinuation) ---
490
491    #[test]
492    fn uuid_continuation_dialplan() {
493        let line =
494            format!("{UUID1} Dialplan: sofia/internal/+15550001234@192.0.2.1 parsing [public]");
495        let parsed = parse_line(&line);
496        assert_eq!(parsed.kind, LineKind::UuidContinuation);
497        assert_eq!(parsed.uuid, Some(UUID1));
498        assert_eq!(parsed.timestamp, None);
499        assert_eq!(parsed.level, None);
500        assert_eq!(
501            parsed.message,
502            "Dialplan: sofia/internal/+15550001234@192.0.2.1 parsing [public]"
503        );
504    }
505
506    #[test]
507    fn uuid_continuation_execute() {
508        let line =
509            format!("{UUID1} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 set(foo=bar)");
510        let parsed = parse_line(&line);
511        assert_eq!(parsed.kind, LineKind::UuidContinuation);
512        assert_eq!(parsed.uuid, Some(UUID1));
513        assert_eq!(
514            parsed.message,
515            "EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 set(foo=bar)"
516        );
517    }
518
519    #[test]
520    fn uuid_continuation_channel_var() {
521        let line = format!("{UUID1} Channel-State: [CS_EXECUTE]");
522        let parsed = parse_line(&line);
523        assert_eq!(parsed.kind, LineKind::UuidContinuation);
524        assert_eq!(parsed.uuid, Some(UUID1));
525        assert_eq!(parsed.message, "Channel-State: [CS_EXECUTE]");
526    }
527
528    #[test]
529    fn uuid_continuation_variable() {
530        let line = format!("{UUID1} variable_sip_call_id: [test123@192.0.2.1]");
531        let parsed = parse_line(&line);
532        assert_eq!(parsed.kind, LineKind::UuidContinuation);
533        assert_eq!(parsed.uuid, Some(UUID1));
534        assert_eq!(parsed.message, "variable_sip_call_id: [test123@192.0.2.1]");
535    }
536
537    #[test]
538    fn uuid_continuation_blank() {
539        let line = format!("{UUID1} ");
540        let parsed = parse_line(&line);
541        assert_eq!(parsed.kind, LineKind::UuidContinuation);
542        assert_eq!(parsed.uuid, Some(UUID1));
543        assert_eq!(parsed.message, "");
544    }
545
546    // --- Format D (BareContinuation) ---
547
548    #[test]
549    fn bare_variable() {
550        let line = "variable_foo: [bar]";
551        let parsed = parse_line(line);
552        assert_eq!(parsed.kind, LineKind::BareContinuation);
553        assert_eq!(parsed.uuid, None);
554        assert_eq!(parsed.message, "variable_foo: [bar]");
555    }
556
557    #[test]
558    fn bare_sdp_origin() {
559        let line = "o=- 1234 5678 IN IP4 192.0.2.1";
560        let parsed = parse_line(line);
561        assert_eq!(parsed.kind, LineKind::BareContinuation);
562        assert_eq!(parsed.message, line);
563    }
564
565    #[test]
566    fn bare_sdp_media() {
567        let line = "m=audio 47758 RTP/AVP 0 101";
568        let parsed = parse_line(line);
569        assert_eq!(parsed.kind, LineKind::BareContinuation);
570        assert_eq!(parsed.message, line);
571    }
572
573    #[test]
574    fn bare_sdp_attribute() {
575        let line = "a=rtpmap:0 PCMU/8000";
576        let parsed = parse_line(line);
577        assert_eq!(parsed.kind, LineKind::BareContinuation);
578        assert_eq!(parsed.message, line);
579    }
580
581    #[test]
582    fn bare_closing_bracket() {
583        let line = "]";
584        let parsed = parse_line(line);
585        assert_eq!(parsed.kind, LineKind::BareContinuation);
586        assert_eq!(parsed.message, "]");
587    }
588
589    #[test]
590    fn bare_empty_line() {
591        let parsed = parse_line("");
592        assert_eq!(parsed.kind, LineKind::Empty);
593        assert_eq!(parsed.message, "");
594    }
595
596    // --- Format E (Truncated) ---
597
598    #[test]
599    fn truncated_varia_prefix() {
600        let line = format!(
601            "varia{UUID1} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 set(x=y)"
602        );
603        let parsed = parse_line(&line);
604        assert_eq!(parsed.kind, LineKind::Truncated);
605        assert_eq!(parsed.uuid, Some(UUID1));
606        assert_eq!(
607            parsed.message,
608            "EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 set(x=y)"
609        );
610    }
611
612    #[test]
613    fn truncated_variab_prefix() {
614        let line = format!(
615            "variab{UUID1} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 set(x=y)"
616        );
617        let parsed = parse_line(&line);
618        assert_eq!(parsed.kind, LineKind::Truncated);
619        assert_eq!(parsed.uuid, Some(UUID1));
620    }
621
622    #[test]
623    fn truncated_var_prefix() {
624        let line =
625            format!("var{UUID1} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 set(x=y)");
626        let parsed = parse_line(&line);
627        assert_eq!(parsed.kind, LineKind::Truncated);
628        assert_eq!(parsed.uuid, Some(UUID1));
629    }
630
631    #[test]
632    fn truncated_variable_prefix() {
633        let line = format!(
634            "variable{UUID1} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 set(x=y)"
635        );
636        let parsed = parse_line(&line);
637        assert_eq!(parsed.kind, LineKind::Truncated);
638        assert_eq!(parsed.uuid, Some(UUID1));
639    }
640
641    // --- level_from_bracketed ---
642
643    #[test]
644    fn bracketed_level_folds_the_log_spelling() {
645        assert_eq!(level_from_bracketed("[DEBUG]"), Some(LogLevel::Debug));
646        assert_eq!(level_from_bracketed("[ERR]"), Some(LogLevel::Error));
647        assert_eq!(level_from_bracketed("[CONSOLE]"), Some(LogLevel::Console));
648    }
649
650    #[test]
651    fn bracketed_level_reads_any_case() {
652        assert_eq!(level_from_bracketed("[debug]"), Some(LogLevel::Debug));
653        assert_eq!(level_from_bracketed("[Warning]"), Some(LogLevel::Warning));
654    }
655
656    #[test]
657    fn bracketed_level_rejects_malformed() {
658        assert_eq!(level_from_bracketed("[FAKE]"), None);
659        assert_eq!(level_from_bracketed("DEBUG"), None);
660        assert_eq!(level_from_bracketed("[]"), None);
661        assert_eq!(level_from_bracketed("["), None);
662        assert_eq!(level_from_bracketed(""), None);
663    }
664
665    /// Least severe compares greatest, so `>= Debug` admits everything.
666    #[test]
667    fn levels_order_by_switch_log_level_numbering() {
668        assert!(LogLevel::Console < LogLevel::Alert);
669        assert!(LogLevel::Error < LogLevel::Warning);
670        assert!(LogLevel::Info < LogLevel::Debug);
671    }
672
673    // --- is_log_header_at (collision split marker) ---
674
675    #[test]
676    fn log_header_with_idle_pct() {
677        let line = "2024-04-02 10:31:28.785679 98.03% [NOTICE] sofia.c:1114 Hangup";
678        assert!(is_log_header_at(line.as_bytes(), 0));
679    }
680
681    #[test]
682    fn log_header_no_idle_pct() {
683        // Older/eSInet FS builds emit "[LEVEL]" directly after the timestamp.
684        let line = "2024-04-02 10:31:28.785679 [NOTICE] sofia.c:1114 Hangup";
685        assert!(is_log_header_at(line.as_bytes(), 0));
686    }
687
688    #[test]
689    fn log_header_no_idle_pct_at_offset() {
690        let line = "Session does not exist, aborting REFER.2024-04-02 10:31:28.785679 [WARNING] sofia_presence.c:4546 x";
691        let offset = line.find("2024").unwrap();
692        assert!(is_log_header_at(line.as_bytes(), offset));
693    }
694
695    /// The logger writes the idle field with `"%0.2f"`, so a run of anything
696    /// else before the sign is not one — and reading it as one claimed a
697    /// scheduler figure off text that never held one.
698    #[test]
699    fn idle_pct_rejects_non_numeric_run() {
700        let line = "2025-01-15 10:30:45.123456 ab% [DEBUG] sofia.c:100 Message";
701        assert!(!is_log_header_at(line.as_bytes(), 0));
702        assert_eq!(parse_line(line).idle_pct, None);
703    }
704
705    /// A header the write budget cut after the idle field carries no level, so
706    /// it is no header — and no idle reading either.
707    #[test]
708    fn idle_pct_needs_the_level_after_it() {
709        let line = "2025-01-15 10:30:45.123456 95.97%";
710        assert!(!is_log_header_at(line.as_bytes(), 0));
711        assert_eq!(parse_line(line).idle_pct, None);
712    }
713
714    /// A cut that lands inside the level field leaves a bracket that never
715    /// closes; the reading of the fields before it still stands.
716    #[test]
717    fn a_header_cut_inside_the_level_starts_no_record() {
718        for line in [
719            "2025-01-15 10:30:45.123456 95.97% [",
720            "2025-01-15 10:30:45.123456 95.97% [DEB",
721            "2025-01-15 10:30:45.123456 [",
722        ] {
723            assert!(!is_log_header_at(line.as_bytes(), 0), "split on {line}");
724        }
725        let cut = "2025-01-15 10:30:45.123456 95.97% [";
726        assert_eq!(parse_line(cut).idle_pct, Some("95.97%"));
727    }
728
729    #[test]
730    fn log_header_rejects_non_header() {
731        let line = "2024-04-02 not a real timestamp here";
732        assert!(!is_log_header_at(line.as_bytes(), 0));
733    }
734
735    // --- No idle percentage (issue #1) ---
736
737    #[test]
738    fn full_line_no_idle_pct() {
739        let line = format!(
740            "{UUID1} 2025-01-15 10:30:45.123456 [NOTICE] switch_core_session.c:1744 Session 3178948 ended"
741        );
742        let parsed = parse_line(&line);
743        assert_eq!(parsed.kind, LineKind::Full);
744        assert_eq!(parsed.uuid, Some(UUID1));
745        assert_eq!(parsed.timestamp, Some("2025-01-15 10:30:45.123456"));
746        assert_eq!(parsed.idle_pct, None);
747        assert_eq!(parsed.level, Some(LogLevel::Notice));
748        assert_eq!(parsed.source, Some("switch_core_session.c:1744"));
749        assert_eq!(parsed.message, "Session 3178948 ended");
750    }
751
752    #[test]
753    fn full_line_no_idle_pct_url_encoded_percent() {
754        let line = format!(
755            "{UUID1} 2025-01-15 10:30:45.123456 [NOTICE] switch_core_session.c:1744 Session 3178948 (sofia/psap/gw%2Bsg1vofswb-inbound@198.51.100.5:5060) Ended"
756        );
757        let parsed = parse_line(&line);
758        assert_eq!(parsed.kind, LineKind::Full);
759        assert_eq!(parsed.uuid, Some(UUID1));
760        assert_eq!(parsed.timestamp, Some("2025-01-15 10:30:45.123456"));
761        assert_eq!(parsed.idle_pct, None);
762        assert_eq!(parsed.level, Some(LogLevel::Notice));
763        assert_eq!(parsed.source, Some("switch_core_session.c:1744"));
764        assert_eq!(
765            parsed.message,
766            "Session 3178948 (sofia/psap/gw%2Bsg1vofswb-inbound@198.51.100.5:5060) Ended"
767        );
768    }
769
770    #[test]
771    fn system_line_no_idle_pct() {
772        let line = "2025-01-15 10:30:45.123456 [INFO] mod_event_socket.c:1772 Event Socket command";
773        let parsed = parse_line(line);
774        assert_eq!(parsed.kind, LineKind::System);
775        assert_eq!(parsed.uuid, None);
776        assert_eq!(parsed.timestamp, Some("2025-01-15 10:30:45.123456"));
777        assert_eq!(parsed.idle_pct, None);
778        assert_eq!(parsed.level, Some(LogLevel::Info));
779        assert_eq!(parsed.source, Some("mod_event_socket.c:1772"));
780        assert_eq!(parsed.message, "Event Socket command");
781    }
782
783    #[test]
784    fn full_line_no_idle_pct_hangup_url_encoded() {
785        let line = format!(
786            "{UUID1} 2025-01-15 10:30:45.123456 [NOTICE] sofia.c:1089 Hangup sofia/psap/gw%2Bgateway@198.51.100.5:5060 [CS_EXCHANGE_MEDIA] [CALL_AWARDED_DELIVERED]"
787        );
788        let parsed = parse_line(&line);
789        assert_eq!(parsed.kind, LineKind::Full);
790        assert_eq!(parsed.idle_pct, None);
791        assert_eq!(parsed.level, Some(LogLevel::Notice));
792        assert_eq!(parsed.source, Some("sofia.c:1089"));
793        assert_eq!(
794            parsed.message,
795            "Hangup sofia/psap/gw%2Bgateway@198.51.100.5:5060 [CS_EXCHANGE_MEDIA] [CALL_AWARDED_DELIVERED]"
796        );
797    }
798
799    // --- Edge cases ---
800
801    #[test]
802    fn not_uuid_36_chars() {
803        let line = "this-is-not-a-valid-uuid-value-12345 rest of line";
804        let parsed = parse_line(line);
805        assert_eq!(parsed.kind, LineKind::BareContinuation);
806        assert_eq!(parsed.message, line);
807    }
808
809    #[test]
810    fn uuid_in_message_not_prefix() {
811        let line =
812            format!("This is some log message body with extra context then {UUID1} appears here");
813        let parsed = parse_line(&line);
814        assert_eq!(parsed.kind, LineKind::BareContinuation);
815        assert_eq!(parsed.message, line.as_str());
816    }
817
818    #[test]
819    fn whitespace_only_is_empty() {
820        let parsed = parse_line("   \t  ");
821        assert_eq!(parsed.kind, LineKind::Empty);
822    }
823
824    // --- Multi-byte content at fixed header offsets (must not panic) ---
825
826    #[test]
827    fn multibyte_straddling_timestamp_end_not_system() {
828        // 'é' occupies bytes 25-26: slicing the timestamp at 26 splits it.
829        let line = "2025-01-15 10:30:45.12345é more content following here";
830        assert!(!line.is_char_boundary(26));
831        let parsed = parse_line(line);
832        assert_eq!(parsed.kind, LineKind::BareContinuation);
833        assert_eq!(parsed.timestamp, None);
834        assert_eq!(parsed.message, line);
835    }
836
837    #[test]
838    fn multibyte_after_timestamp_not_system() {
839        // 'é' occupies bytes 26-27: slicing the message start at 27 splits it.
840        let line = "2025-01-15 10:30:45.123456é more content following here";
841        assert!(!line.is_char_boundary(27));
842        let parsed = parse_line(line);
843        assert_eq!(parsed.kind, LineKind::BareContinuation);
844        assert_eq!(parsed.timestamp, None);
845        assert_eq!(parsed.message, line);
846    }
847
848    #[test]
849    fn multibyte_after_uuid_timestamp_is_continuation() {
850        let line = format!("{UUID1} 2025-01-15 10:30:45.123456é more content");
851        let parsed = parse_line(&line);
852        assert_eq!(parsed.kind, LineKind::UuidContinuation);
853        assert_eq!(parsed.uuid, Some(UUID1));
854        assert_eq!(parsed.timestamp, None);
855        assert_eq!(parsed.message, "2025-01-15 10:30:45.123456é more content");
856    }
857
858    #[test]
859    fn multibyte_after_idle_pct_degrades() {
860        // 'é' where the "% " separator's trailing space should be.
861        let line = "2025-01-15 10:30:45.123456 9%é[DEBUG] x";
862        let parsed = parse_line(line);
863        assert_eq!(parsed.kind, LineKind::System);
864        assert_eq!(parsed.timestamp, Some("2025-01-15 10:30:45.123456"));
865        assert_eq!(parsed.idle_pct, None);
866        assert_eq!(parsed.level, None);
867    }
868
869    #[test]
870    fn multibyte_after_level_bracket_degrades() {
871        // 'é' where the "] " separator's trailing space should be.
872        let line = "2025-01-15 10:30:45.123456 95.97% [DEBUG]éxx";
873        let parsed = parse_line(line);
874        assert_eq!(parsed.kind, LineKind::System);
875        assert_eq!(parsed.timestamp, Some("2025-01-15 10:30:45.123456"));
876        assert_eq!(parsed.idle_pct, Some("95.97%"));
877        assert_eq!(parsed.level, Some(LogLevel::Debug));
878        assert_eq!(parsed.source, None);
879        assert_eq!(parsed.message, "");
880    }
881}
freeswitch_log_parser/line.rs

freeswitch_log_parser/
line.rs
