Skip to main content

freeswitch_log_parser/
stream.rs

1use crate::attached::AttachedLines;
2use crate::codec::{CodecMedia, CodecOffer};
3use crate::decode::truncate_at_char_boundary;
4use crate::level::LogLevel;
5use crate::line::{
6    is_date_at, is_log_header_at, is_uuid_at, parse_line, LineKind, UUID_PREFIX_LEN,
7};
8use crate::message::{classify_message, MessageKind, SdpDirection};
9use std::collections::VecDeque;
10
11/// Structured data extracted from a multi-line dump that follows a primary log entry.
12///
13/// Each variant corresponds to a block type that the stream state machine
14/// recognizes and reassembles from continuation lines.
15#[derive(Debug, Clone, PartialEq, Eq)]
16#[non_exhaustive]
17pub enum Block {
18    /// Channel variable dump — `Channel-*` fields and `variable_*` key-value pairs.
19    /// Multi-line variable values (e.g. embedded SDP) are reassembled with `\n` separators.
20    ChannelData {
21        fields: Vec<(String, String)>,
22        variables: Vec<(String, String)>,
23    },
24    /// SDP session description body, collected line by line.
25    Sdp {
26        direction: SdpDirection,
27        body: Vec<String>,
28    },
29    /// Codec negotiation sequence for one media type. A run only ever covers a
30    /// single [`CodecMedia`]; audio and video traces never share a block.
31    CodecNegotiation {
32        media: CodecMedia,
33        /// `(remote offer, local implementation)` for each pair compared.
34        comparisons: Vec<(CodecOffer, CodecOffer)>,
35        matched: Vec<CodecOffer>,
36        /// Codecs kept as fallbacks because only their ptime differed.
37        near_matched: Vec<CodecOffer>,
38    },
39}
40
41#[cfg(feature = "sdp")]
42impl Block {
43    /// Codecs described by an SDP body.
44    ///
45    /// `None` when there is no body to read — another block type, or an SDP
46    /// marker that carried none. Sofia logs several (`Duplicate SDP`,
47    /// `Processing updated SDP`) purely as announcements, and an empty body is
48    /// absence rather than a malformed session.
49    ///
50    /// Parsed on each call rather than stored — see `docs/design-rationale.md`.
51    /// Only a session-level failure is an `Err`: a malformed `a=rtpmap` or a
52    /// broken media section degrades into
53    /// [`SdpCodecs::warnings`](freeswitch_types::sdp::SdpCodecs::warnings).
54    pub fn sdp_codecs(
55        &self,
56    ) -> Option<Result<freeswitch_types::sdp::SdpCodecs, freeswitch_types::sdp::SdpCodecError>>
57    {
58        let Block::Sdp { body, .. } = self else {
59            return None;
60        };
61        let text = body.join("\n");
62        if text.trim().is_empty() {
63            return None;
64        }
65        Some(freeswitch_types::sdp::SdpCodecs::parse(&text))
66    }
67}
68
69/// Controls how much detail is recorded for lines that couldn't be fully classified.
70///
71/// Higher fidelity levels allocate more memory. The default is `CountOnly`.
72#[derive(Debug, Clone, Copy, PartialEq, Eq)]
73pub enum UnclassifiedTracking {
74    /// Increment the counter only — zero allocation.
75    CountOnly,
76    /// Record line number and reason for each unclassified line.
77    TrackLines,
78    /// Like `TrackLines` plus the full line content.
79    CaptureData,
80}
81
82/// Why a line was marked as unclassified.
83#[derive(Debug, Clone, PartialEq, Eq)]
84#[non_exhaustive]
85pub enum UnclassifiedReason {
86    /// Bare continuation line arrived with no pending entry to attach to.
87    OrphanContinuation,
88    /// Line was parsed but the message didn't match any known pattern.
89    UnknownMessageFormat,
90    /// EXECUTE or variable line was only partially readable.
91    TruncatedField,
92}
93
94/// Record of a single unclassified line, captured when tracking is enabled.
95#[derive(Debug, Clone, PartialEq, Eq)]
96pub struct UnclassifiedLine {
97    pub line_number: u64,
98    pub reason: UnclassifiedReason,
99    /// The full line content; only populated under [`UnclassifiedTracking::CaptureData`].
100    pub data: Option<String>,
101}
102
103/// Cumulative parsing statistics, updated as lines flow through the stream.
104#[derive(Debug, Clone, Default)]
105pub struct ParseStats {
106    pub lines_processed: u64,
107    pub lines_unclassified: u64,
108    /// Lines that became part of entries (primary line + attached lines per entry).
109    pub lines_in_entries: u64,
110    /// Empty lines that arrived with no pending entry to attach to.
111    pub lines_empty_orphan: u64,
112    /// Physical lines that were split into multiple logical entries due to
113    /// mod_logfile's 2048-byte snprintf truncation causing same-line collisions.
114    pub lines_split: u64,
115    /// Populated only when tracking is `TrackLines` or `CaptureData`.
116    pub unclassified_lines: Vec<UnclassifiedLine>,
117}
118
119impl ParseStats {
120    /// Lines that were processed but not accounted for by any tracking category.
121    ///
122    /// Returns 0 when the parser correctly accounts for every input line.
123    /// A non-zero value indicates a parser bug — lines were silently lost.
124    ///
125    /// Invariant: `lines_processed + lines_split == lines_in_entries + lines_empty_orphan`
126    pub fn unaccounted_lines(&self) -> u64 {
127        let expected = self.lines_in_entries + self.lines_empty_orphan;
128        let actual = self.lines_processed + self.lines_split;
129        actual.saturating_sub(expected)
130    }
131}
132
133/// A complete parsed log entry with all context resolved.
134///
135/// Produced by [`LogStream`]. Continuation lines have been grouped,
136/// UUID/timestamp inherited from context where needed, and multi-line blocks
137/// reassembled.
138#[derive(Debug)]
139pub struct LogEntry {
140    /// Session UUID, or empty string for system lines.
141    pub uuid: String,
142    /// Timestamp with microsecond precision; inherited from the previous entry for continuations.
143    pub timestamp: String,
144    /// `None` for continuation and truncated lines.
145    pub level: Option<LogLevel>,
146    /// Core scheduler idle percentage; `None` for continuations.
147    pub idle_pct: Option<String>,
148    /// Source file:line; `None` for continuations.
149    pub source: Option<String>,
150    /// The primary message text.
151    pub message: String,
152    /// Which line format originated this entry.
153    pub kind: LineKind,
154    /// Semantic classification of the message content.
155    pub message_kind: MessageKind,
156    /// Typed, parsed multi-line block; `None` for entries without a trailing block.
157    pub block: Option<Block>,
158    /// Raw continuation lines that followed the primary line.
159    pub attached: AttachedLines,
160    /// 1-based line number in the input stream.
161    pub line_number: u64,
162    /// Per-entry warnings about parsing anomalies.
163    pub warnings: Vec<String>,
164}
165
166fn parse_field_line(msg: &str) -> Option<(String, String)> {
167    let colon = msg.find(": ")?;
168    let name = &msg[..colon];
169    if name.contains(' ') || name.is_empty() {
170        return None;
171    }
172    let value_part = &msg[colon + 2..];
173    let value = if let Some(inner) = value_part.strip_prefix('[') {
174        inner.strip_suffix(']').unwrap_or(inner)
175    } else {
176        value_part
177    };
178    Some((name.to_string(), value.to_string()))
179}
180
181enum StreamState {
182    Idle,
183    InChannelData {
184        fields: Vec<(String, String)>,
185        variables: Vec<(String, String)>,
186        // Name and accumulated value of a variable whose `[` has not been closed
187        // yet. One field, so a half-open variable cannot be represented.
188        open_var: Option<(String, String)>,
189    },
190    InSdp {
191        direction: SdpDirection,
192        body: Vec<String>,
193    },
194    InCodecNegotiation {
195        media: CodecMedia,
196        comparisons: Vec<(CodecOffer, CodecOffer)>,
197        matched: Vec<CodecOffer>,
198        near_matched: Vec<CodecOffer>,
199    },
200}
201
202impl StreamState {
203    fn take_idle(&mut self) -> StreamState {
204        std::mem::replace(self, StreamState::Idle)
205    }
206}
207
208/// Layer 2 structural state machine — groups continuation lines, classifies
209/// messages, and detects multi-line blocks (CHANNEL_DATA, SDP, codec negotiation).
210///
211/// Wraps any `Iterator<Item = String>` and yields [`LogEntry`] values.
212/// Maintains `last_uuid` and `last_timestamp` to fill in context for
213/// continuation lines that lack their own.
214///
215/// Use the builder method [`unclassified_tracking()`](LogStream::unclassified_tracking)
216/// to control diagnostic detail before iterating.
217pub struct LogStream<I> {
218    lines: I,
219    last_uuid: String,
220    last_timestamp: String,
221    pending: Option<LogEntry>,
222    state: StreamState,
223    stats: ParseStats,
224    tracking: UnclassifiedTracking,
225    line_number: u64,
226    split_pending: VecDeque<String>,
227    deferred_warning: Option<String>,
228}
229
230impl<I: Iterator<Item = String>> LogStream<I> {
231    /// Create a new stream from any line iterator.
232    pub fn new(lines: I) -> Self {
233        LogStream {
234            lines,
235            last_uuid: String::new(),
236            last_timestamp: String::new(),
237            pending: None,
238            state: StreamState::Idle,
239            stats: ParseStats::default(),
240            tracking: UnclassifiedTracking::CountOnly,
241            line_number: 0,
242            split_pending: VecDeque::new(),
243            deferred_warning: None,
244        }
245    }
246
247    /// Set the unclassified line tracking level (builder pattern). Defaults to `CountOnly`.
248    pub fn unclassified_tracking(mut self, level: UnclassifiedTracking) -> Self {
249        self.tracking = level;
250        self
251    }
252
253    /// Cumulative parsing statistics up to the current position.
254    pub fn stats(&self) -> &ParseStats {
255        &self.stats
256    }
257
258    /// Take all accumulated unclassified line records, leaving the internal vec empty.
259    ///
260    /// The `lines_unclassified` counter is not reset.
261    pub fn drain_unclassified(&mut self) -> Vec<UnclassifiedLine> {
262        std::mem::take(&mut self.stats.unclassified_lines)
263    }
264
265    fn record_unclassified(&mut self, reason: UnclassifiedReason, data: Option<&str>) {
266        self.stats.lines_unclassified += 1;
267        match self.tracking {
268            UnclassifiedTracking::CountOnly => {}
269            UnclassifiedTracking::TrackLines => {
270                self.stats.unclassified_lines.push(UnclassifiedLine {
271                    line_number: self.line_number,
272                    reason,
273                    data: None,
274                });
275            }
276            UnclassifiedTracking::CaptureData => {
277                self.stats.unclassified_lines.push(UnclassifiedLine {
278                    line_number: self.line_number,
279                    reason,
280                    data: data.map(|s| s.to_string()),
281                });
282            }
283        }
284    }
285
286    fn finalize_block(&mut self) -> (Option<Block>, Vec<String>) {
287        let mut warnings = Vec::new();
288        match self.state.take_idle() {
289            StreamState::Idle => (None, warnings),
290            StreamState::InChannelData {
291                fields,
292                mut variables,
293                open_var,
294            } => {
295                if let Some((name, value)) = open_var {
296                    warnings.push(format!("unclosed multi-line variable: {name}"));
297                    variables.push((name, value));
298                }
299                (Some(Block::ChannelData { fields, variables }), warnings)
300            }
301            StreamState::InSdp { direction, body } => {
302                (Some(Block::Sdp { direction, body }), warnings)
303            }
304            StreamState::InCodecNegotiation {
305                media,
306                comparisons,
307                matched,
308                near_matched,
309            } => (
310                Some(Block::CodecNegotiation {
311                    media,
312                    comparisons,
313                    matched,
314                    near_matched,
315                }),
316                warnings,
317            ),
318        }
319    }
320
321    fn finalize_pending(&mut self) -> Option<LogEntry> {
322        let (block, warnings) = self.finalize_block();
323        if let Some(ref mut p) = self.pending {
324            p.block = block;
325            p.warnings.extend(warnings);
326            self.stats.lines_in_entries += 1 + p.attached.len() as u64;
327        }
328        self.pending.take()
329    }
330
331    fn start_block_for_message(&mut self, message_kind: &MessageKind) {
332        self.state = match message_kind {
333            MessageKind::ChannelData => StreamState::InChannelData {
334                fields: Vec::new(),
335                variables: Vec::new(),
336                open_var: None,
337            },
338            MessageKind::SdpMarker { direction } => StreamState::InSdp {
339                direction: direction.clone(),
340                body: Vec::new(),
341            },
342            MessageKind::CodecNegotiation { media } => StreamState::InCodecNegotiation {
343                media: *media,
344                comparisons: Vec::new(),
345                matched: Vec::new(),
346                near_matched: Vec::new(),
347            },
348            _ => StreamState::Idle,
349        };
350    }
351
352    /// Returns a warning when the line is not one of the known trace shapes.
353    /// The caller owns attaching it, because the entry a block's opening line
354    /// belongs to is not built yet when this runs.
355    #[must_use]
356    fn accumulate_codec_entry(&mut self, msg: &str) -> Option<String> {
357        let mut warning = None;
358        if let StreamState::InCodecNegotiation {
359            media,
360            comparisons,
361            matched,
362            near_matched,
363        } = &mut self.state
364        {
365            let media = *media;
366            let parse = |token: &str| {
367                CodecOffer::parse(media, token).map_err(|e| {
368                    format!(
369                        "unrecognized codec negotiation line ({e}): {}",
370                        truncate_at_char_boundary(msg, 80)
371                    )
372                })
373            };
374
375            // `Audio Codec Compare [a:…]/[b:…]` vs the single-token verdicts
376            // `[a:…] ++++ is saved as a match` / `is saved as a near-match` /
377            // `was not saved as a near-match. Too many. Ignoring.`
378            let rest = msg
379                .strip_prefix("Audio Codec Compare ")
380                .or_else(|| msg.strip_prefix("Video Codec Compare "))
381                .unwrap_or(msg);
382
383            let result = if let Some(slash) = rest.find("]/[") {
384                let offered = &rest[1..slash];
385                let local = rest[slash + 3..].trim_end_matches(']');
386                parse(offered).and_then(|o| parse(local).map(|l| comparisons.push((o, l))))
387            } else if let Some(end) = rest.find(']') {
388                let token = &rest[1..end];
389                let verdict = &rest[end + 1..];
390                if verdict.contains("was not saved") {
391                    // Reported only so the count is not silently short; the
392                    // codec was dropped for exceeding MAX_MATCHES.
393                    parse(token).map(|_| ())
394                } else if verdict.contains("near-match") {
395                    parse(token).map(|c| near_matched.push(c))
396                } else if verdict.contains("is saved as a match") {
397                    parse(token).map(|c| matched.push(c))
398                } else {
399                    Err(format!(
400                        "unrecognized codec negotiation line: {}",
401                        truncate_at_char_boundary(msg, 80)
402                    ))
403                }
404            } else {
405                Err(format!(
406                    "unrecognized codec negotiation line: {}",
407                    truncate_at_char_boundary(msg, 80)
408                ))
409            };
410            warning = result.err();
411        }
412        warning
413    }
414
415    fn accumulate_continuation(&mut self, msg: &str, line: &str) {
416        let msg_kind = classify_message(msg);
417        let mut warning = None;
418        match &mut self.state {
419            StreamState::InChannelData {
420                fields,
421                variables,
422                open_var,
423            } => {
424                if let Some((_, val)) = open_var {
425                    val.push('\n');
426                    val.push_str(msg);
427                    if msg.ends_with(']') {
428                        if let Some((name, val)) = open_var.take() {
429                            variables.push((name, val.trim_end_matches(']').to_string()));
430                        }
431                    }
432                } else {
433                    match &msg_kind {
434                        MessageKind::ChannelField { name, value } => {
435                            fields.push((name.clone(), value.clone()));
436                        }
437                        MessageKind::Variable { name, value } => {
438                            if !msg.ends_with(']') && msg.contains(": [") {
439                                *open_var = Some((name.clone(), value.clone()));
440                            } else {
441                                variables.push((name.clone(), value.clone()));
442                            }
443                        }
444                        _ => {
445                            if let Some((name, value)) = parse_field_line(msg) {
446                                fields.push((name, value));
447                            } else {
448                                warning = Some(format!(
449                                    "unparseable CHANNEL_DATA line: {}",
450                                    truncate_at_char_boundary(msg, 80)
451                                ));
452                            }
453                        }
454                    }
455                }
456            }
457            StreamState::InSdp { body, .. } => {
458                body.push(msg.to_string());
459            }
460            StreamState::InCodecNegotiation { .. } => {
461                warning = Some(format!(
462                    "unexpected codec negotiation continuation: {}",
463                    truncate_at_char_boundary(msg, 80)
464                ));
465            }
466            StreamState::Idle => {}
467        }
468        if let Some(ref mut pending) = self.pending {
469            if let Some(w) = warning {
470                pending.warnings.push(w);
471            }
472            pending.attached.push(line);
473        }
474    }
475
476    fn new_entry(
477        &mut self,
478        uuid: String,
479        timestamp: String,
480        message: String,
481        kind: LineKind,
482        message_kind: MessageKind,
483    ) -> LogEntry {
484        let mut warnings = Vec::new();
485        if let Some(w) = self.deferred_warning.take() {
486            warnings.push(w);
487        }
488        LogEntry {
489            uuid,
490            timestamp,
491            message,
492            kind,
493            message_kind,
494            level: None,
495            idle_pct: None,
496            source: None,
497            block: None,
498            attached: AttachedLines::new(),
499            line_number: self.line_number,
500            warnings,
501        }
502    }
503}
504
505/// mod_logfile's `snprintf` buffer size for UUID-prefixed lines.
506/// Lines exceeding this in the formatted output lose their trailing newline,
507/// causing the next queue entry to collide on the same physical line.
508const MOD_LOGFILE_BUF_SIZE: usize = 2048;
509
510/// Effective maximum payload per line (buffer minus the UUID prefix
511/// `mod_logfile` prepends, minus the trailing newline).
512const MAX_LINE_PAYLOAD: usize = MOD_LOGFILE_BUF_SIZE - UUID_PREFIX_LEN - 1;
513
514/// Tolerance around the expected truncation boundary when scanning oversize
515/// lines for Format E collisions. The boundary is deterministic
516/// (`MAX_LINE_PAYLOAD` from the start of the truncated chunk) but a few bytes
517/// of slack covers minor variation in `snprintf` accounting and any future
518/// drift in the prepend format.
519const COLLISION_SCAN_SLACK: usize = 64;
520
521impl<I: Iterator<Item = String>> LogStream<I> {
522    /// Detect same-line collisions where multiple log entries were concatenated
523    /// without a newline separator.
524    ///
525    /// Two collision mechanisms exist in production:
526    ///
527    /// 1. **Buffer truncation** (Format E): `mod_logfile`'s 2048-byte `snprintf`
528    ///    buffer truncates a long line, losing the trailing `\n`. The next entry
529    ///    from the log queue collides on the same physical line. These lines
530    ///    always exceed `MAX_LINE_PAYLOAD`.
531    ///
532    /// 2. **Write contention**: multiple threads writing to the log file can
533    ///    interleave output, producing concatenated entries at any line length.
534    ///    Common with system lines (Format B) that lack UUID prefixes.
535    ///
536    /// Returns the (possibly truncated) line. If a collision is detected,
537    /// the suffix is stored in `split_pending` for processing in the next
538    /// iteration. Recursive: split suffixes pass through this function again.
539    fn detect_collision(&mut self, line: String) -> String {
540        if line.len() > MAX_LINE_PAYLOAD {
541            let warning = format!(
542                "line exceeds mod_logfile 2048-byte buffer ({} bytes), data may be truncated",
543                line.len() + 38,
544            );
545            if let Some(ref mut pending) = self.pending {
546                pending.warnings.push(warning);
547            } else {
548                self.deferred_warning = Some(warning);
549            }
550        }
551
552        // Skip past the line's own header to avoid matching itself.
553        let bytes = line.as_bytes();
554        let min_scan = if is_uuid_at(bytes, 0) {
555            if bytes.len() > UUID_PREFIX_LEN && bytes[UUID_PREFIX_LEN].is_ascii_digit() {
556                64 // Full line: UUID + timestamp
557            } else {
558                UUID_PREFIX_LEN // UUID continuation
559            }
560        } else if is_date_at(bytes, 0) {
561            27 // System line: skip own timestamp
562        } else {
563            0
564        };
565
566        let end = bytes.len().saturating_sub(28);
567        let oversize = bytes.len() > MAX_LINE_PAYLOAD;
568
569        // Single linear pass collecting every split point. Two collision
570        // mechanisms handled in one walk:
571        //
572        //   * `is_log_header_at`: timestamp header (Format B write
573        //     contention, Full/System line collisions). Fast-fails after
574        //     one byte for non-digit input, so the per-offset cost stays
575        //     low even on hundreds-of-KB lines.
576        //
577        //   * `is_uuid_at` within a ±64-byte window around the next
578        //     expected mod_logfile truncation boundary (Format E). The
579        //     boundary is `MAX_LINE_PAYLOAD` bytes past the start of the
580        //     current chunk; we advance it as splits are found. Bounding
581        //     this check is what kept the previous optimization fast on
582        //     60 KB embedded-SDP lines — a 36-byte hex pattern check at
583        //     every offset would dominate the scan.
584        //
585        // Collecting all splits in one pass (rather than splitting,
586        // re-feeding the suffix, and re-scanning from scratch) is the
587        // structural fix for the prior O(n²) behavior.
588        let mut splits: Vec<usize> = Vec::new();
589        let mut chunk_start = 0usize;
590        let mut offset = min_scan;
591        while offset <= end {
592            if is_log_header_at(bytes, offset) {
593                let split_at = if offset >= chunk_start + UUID_PREFIX_LEN
594                    && is_uuid_at(bytes, offset - UUID_PREFIX_LEN)
595                {
596                    offset - UUID_PREFIX_LEN
597                } else {
598                    offset
599                };
600                if split_at > chunk_start {
601                    splits.push(split_at);
602                    chunk_start = split_at;
603                    offset += 27;
604                } else {
605                    // Header at current chunk's own start — already
606                    // accounted for. Step past it without recording a
607                    // split. The max guarantees forward progress when
608                    // the UUID-prefix check rewinds split_at behind us.
609                    offset = (offset + 27).max(offset + 1);
610                }
611                continue;
612            }
613            if oversize {
614                let boundary = chunk_start + MAX_LINE_PAYLOAD;
615                if offset + COLLISION_SCAN_SLACK >= boundary
616                    && offset <= boundary + COLLISION_SCAN_SLACK
617                    && is_uuid_at(bytes, offset)
618                {
619                    splits.push(offset);
620                    chunk_start = offset;
621                    offset += UUID_PREFIX_LEN;
622                    continue;
623                }
624            }
625            offset += 1;
626        }
627
628        if splits.is_empty() {
629            return line;
630        }
631
632        // First chunk returned; the rest queued for subsequent iterations.
633        // Building right-to-left with split_off avoids intermediate copies.
634        let mut tail = line;
635        let mut chunks: Vec<String> = Vec::with_capacity(splits.len());
636        for &at in splits.iter().rev() {
637            chunks.push(tail.split_off(at));
638        }
639        chunks.reverse();
640        self.split_pending.extend(chunks);
641        tail
642    }
643}
644
645impl<I: Iterator<Item = String>> Iterator for LogStream<I> {
646    type Item = LogEntry;
647
648    fn next(&mut self) -> Option<LogEntry> {
649        loop {
650            let line = if let Some(split) = self.split_pending.pop_front() {
651                self.stats.lines_split += 1;
652                // Already split out by a prior detect_collision pass —
653                // skip re-scanning, which would just walk the chunk again
654                // and find nothing.
655                split
656            } else {
657                let Some(line) = self.lines.next() else {
658                    return self.finalize_pending();
659                };
660
661                if line.starts_with('\x00') {
662                    let yielded = self.finalize_pending();
663                    self.last_uuid.clear();
664                    self.last_timestamp.clear();
665                    if yielded.is_some() {
666                        return yielded;
667                    }
668                    continue;
669                }
670
671                self.line_number += 1;
672                self.stats.lines_processed += 1;
673                self.detect_collision(line)
674            };
675
676            let parsed = parse_line(&line);
677
678            match parsed.kind {
679                LineKind::Full | LineKind::System | LineKind::Truncated => {
680                    let uuid = parsed.uuid.unwrap_or("").to_string();
681                    let message_kind = classify_message(parsed.message);
682
683                    // Merge consecutive codec negotiation entries with the same
684                    // UUID *and* media type — a video run following an audio one
685                    // describes a different negotiation and gets its own block.
686                    if let MessageKind::CodecNegotiation { media } = message_kind {
687                        if let (
688                            Some(ref pending),
689                            StreamState::InCodecNegotiation {
690                                media: open_media, ..
691                            },
692                        ) = (&self.pending, &self.state)
693                        {
694                            if uuid == pending.uuid && media == *open_media {
695                                let warning = self.accumulate_codec_entry(parsed.message);
696                                if let Some(ref mut p) = self.pending {
697                                    p.attached.push(&line);
698                                    p.warnings.extend(warning);
699                                }
700                                continue;
701                            }
702                        }
703                    }
704
705                    let yielded = self.finalize_pending();
706
707                    let timestamp = parsed
708                        .timestamp
709                        .map(|t| t.to_string())
710                        .unwrap_or_else(|| self.last_timestamp.clone());
711
712                    if !uuid.is_empty() {
713                        self.last_uuid = uuid.clone();
714                    }
715                    if parsed.timestamp.is_some() {
716                        self.last_timestamp = timestamp.clone();
717                    }
718
719                    self.start_block_for_message(&message_kind);
720                    // The entry this line opens does not exist yet, so its
721                    // warning is carried across rather than pushed onto the
722                    // pending entry the way a merged line's is.
723                    let opening_warning =
724                        if matches!(message_kind, MessageKind::CodecNegotiation { .. }) {
725                            self.accumulate_codec_entry(parsed.message)
726                        } else {
727                            None
728                        };
729
730                    let mut entry = self.new_entry(
731                        uuid,
732                        timestamp,
733                        parsed.message.to_string(),
734                        parsed.kind,
735                        message_kind,
736                    );
737                    entry.level = parsed.level;
738                    entry.idle_pct = parsed.idle_pct.map(|s| s.to_string());
739                    entry.source = parsed.source.map(|s| s.to_string());
740                    entry.warnings.extend(opening_warning);
741                    self.pending = Some(entry);
742
743                    if yielded.is_some() {
744                        return yielded;
745                    }
746                }
747
748                LineKind::UuidContinuation => {
749                    let uuid = parsed.uuid.unwrap_or("").to_string();
750                    let is_primary = parsed.message.starts_with("EXECUTE ");
751
752                    if let Some(ref pending) = self.pending {
753                        if !is_primary && uuid == pending.uuid {
754                            self.accumulate_continuation(parsed.message, &line);
755                        } else {
756                            let yielded = self.finalize_pending();
757                            let message_kind = classify_message(parsed.message);
758
759                            if !uuid.is_empty() {
760                                self.last_uuid = uuid.clone();
761                            }
762
763                            self.start_block_for_message(&message_kind);
764                            self.pending = Some(self.new_entry(
765                                uuid,
766                                self.last_timestamp.clone(),
767                                parsed.message.to_string(),
768                                parsed.kind,
769                                message_kind,
770                            ));
771
772                            return yielded;
773                        }
774                    } else {
775                        let message_kind = classify_message(parsed.message);
776
777                        if !uuid.is_empty() {
778                            self.last_uuid = uuid.clone();
779                        }
780
781                        self.start_block_for_message(&message_kind);
782                        self.pending = Some(self.new_entry(
783                            uuid,
784                            self.last_timestamp.clone(),
785                            parsed.message.to_string(),
786                            parsed.kind,
787                            message_kind,
788                        ));
789                    }
790                }
791
792                LineKind::BareContinuation => {
793                    if self.pending.is_some() {
794                        self.accumulate_continuation(parsed.message, &line);
795                    } else {
796                        self.record_unclassified(
797                            UnclassifiedReason::OrphanContinuation,
798                            Some(&line),
799                        );
800                        let message_kind = classify_message(parsed.message);
801                        self.pending = Some(self.new_entry(
802                            self.last_uuid.clone(),
803                            self.last_timestamp.clone(),
804                            parsed.message.to_string(),
805                            parsed.kind,
806                            message_kind,
807                        ));
808                    }
809                }
810
811                LineKind::Empty => {
812                    if let Some(ref mut pending) = self.pending {
813                        pending.attached.push(&line);
814                    } else {
815                        self.stats.lines_empty_orphan += 1;
816                    }
817                }
818            }
819        }
820    }
821}
822
823#[cfg(test)]
824mod tests {
825    use super::*;
826
827    const UUID1: &str = "a1b2c3d4-e5f6-7890-abcd-ef1234567890";
828    const UUID2: &str = "b2c3d4e5-f6a7-8901-bcde-f12345678901";
829
830    fn full_line(uuid: &str, ts: &str, msg: &str) -> String {
831        format!("{uuid} {ts} 95.97% [DEBUG] sofia.c:100 {msg}")
832    }
833
834    const TS1: &str = "2025-01-15 10:30:45.123456";
835    const TS2: &str = "2025-01-15 10:30:46.234567";
836
837    // --- Existing behavior tests (preserved) ---
838
839    #[test]
840    fn inherits_uuid_for_bare_continuation() {
841        let lines = vec![
842            full_line(UUID1, TS1, "CHANNEL_DATA:"),
843            "variable_foo: [bar]".to_string(),
844            "variable_baz: [qux]".to_string(),
845        ];
846        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
847        assert_eq!(entries.len(), 1);
848        assert_eq!(entries[0].uuid, UUID1);
849        assert_eq!(entries[0].attached.len(), 2);
850        assert_eq!(entries[0].attached.get(0), Some("variable_foo: [bar]"));
851        assert_eq!(entries[0].attached.get(1), Some("variable_baz: [qux]"));
852    }
853
854    #[test]
855    fn inherits_timestamp_for_uuid_continuation() {
856        let lines = vec![
857            full_line(UUID1, TS1, "First"),
858            format!("{UUID2} Channel-State: [CS_EXECUTE]"),
859        ];
860        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
861        assert_eq!(entries.len(), 2);
862        assert_eq!(entries[0].timestamp, TS1);
863        assert_eq!(entries[1].uuid, UUID2);
864        assert_eq!(entries[1].timestamp, TS1);
865    }
866
867    #[test]
868    fn new_full_line_yields_previous() {
869        let lines = vec![
870            full_line(UUID1, TS1, "First"),
871            full_line(UUID2, TS2, "Second"),
872        ];
873        let mut stream = LogStream::new(lines.into_iter());
874        let first = stream.next().unwrap();
875        assert_eq!(first.uuid, UUID1);
876        assert_eq!(first.message, "First");
877        let second = stream.next().unwrap();
878        assert_eq!(second.uuid, UUID2);
879        assert_eq!(second.message, "Second");
880        assert!(stream.next().is_none());
881    }
882
883    #[test]
884    fn channel_data_collected_as_attached() {
885        let lines = vec![
886            full_line(UUID1, TS1, "CHANNEL_DATA:"),
887            format!("{UUID1} Channel-Name: [sofia/internal/+15550001234@192.0.2.1]"),
888            format!("{UUID1} Unique-ID: [{UUID1}]"),
889            "variable_sip_call_id: [test123@192.0.2.1]".to_string(),
890        ];
891        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
892        assert_eq!(entries.len(), 1);
893        assert_eq!(entries[0].message, "CHANNEL_DATA:");
894        assert_eq!(entries[0].attached.len(), 3);
895    }
896
897    #[test]
898    fn sdp_body_collected_as_attached() {
899        let lines = vec![
900            full_line(UUID1, TS1, "Local SDP:"),
901            "v=0".to_string(),
902            "o=- 1234 5678 IN IP4 192.0.2.1".to_string(),
903            "s=-".to_string(),
904            "c=IN IP4 192.0.2.1".to_string(),
905            "m=audio 10000 RTP/AVP 0".to_string(),
906        ];
907        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
908        assert_eq!(entries.len(), 1);
909        assert_eq!(entries[0].attached.len(), 5);
910    }
911
912    #[test]
913    fn truncated_starts_new_entry() {
914        let lines = vec![
915            full_line(UUID1, TS1, "First"),
916            format!(
917                "varia{UUID2} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 set(x=y)"
918            ),
919        ];
920        let mut stream = LogStream::new(lines.into_iter());
921        let first = stream.next().unwrap();
922        assert_eq!(first.uuid, UUID1);
923        assert_eq!(first.message, "First");
924        let second = stream.next().unwrap();
925        assert_eq!(second.uuid, UUID2);
926        assert_eq!(second.kind, LineKind::Truncated);
927    }
928
929    #[test]
930    fn empty_lines_in_attached() {
931        let lines = vec![
932            full_line(UUID1, TS1, "First"),
933            String::new(),
934            "continuation".to_string(),
935        ];
936        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
937        assert_eq!(entries.len(), 1);
938        assert_eq!(entries[0].attached.len(), 2);
939        assert_eq!(entries[0].attached.get(0), Some(""));
940        assert_eq!(entries[0].attached.get(1), Some("continuation"));
941    }
942
943    #[test]
944    fn system_line_no_uuid() {
945        let lines = vec![format!(
946            "{TS1} 95.97% [INFO] mod_event_socket.c:1772 Event Socket command"
947        )];
948        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
949        assert_eq!(entries.len(), 1);
950        assert_eq!(entries[0].uuid, "");
951        assert_eq!(entries[0].kind, LineKind::System);
952    }
953
954    #[test]
955    fn final_entry_on_exhaustion() {
956        let lines = vec![full_line(UUID1, TS1, "Only entry")];
957        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
958        assert_eq!(entries.len(), 1);
959        assert_eq!(entries[0].message, "Only entry");
960    }
961
962    #[test]
963    fn consecutive_full_lines() {
964        let lines = vec![
965            full_line(UUID1, TS1, "First"),
966            full_line(UUID1, TS2, "Second"),
967            full_line(UUID2, TS1, "Third"),
968        ];
969        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
970        assert_eq!(entries.len(), 3);
971        for entry in &entries {
972            assert!(entry.attached.is_empty());
973        }
974    }
975
976    #[test]
977    fn execute_after_channel_data_same_uuid() {
978        let lines = vec![
979            full_line(UUID1, TS1, "CHANNEL_DATA:"),
980            format!("{UUID1} Channel-State: [CS_EXECUTE]"),
981            format!("{UUID1} variable_sip_call_id: [test@192.0.2.1]"),
982            "variable_foo: [bar]".to_string(),
983            String::new(),
984            String::new(),
985            format!("{UUID1} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 export(originate_timeout=3600)"),
986            full_line(UUID1, TS2, "EXPORT (export_vars) [originate_timeout]=[3600]"),
987        ];
988        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
989        assert_eq!(entries.len(), 3);
990        assert_eq!(entries[0].message, "CHANNEL_DATA:");
991        assert_eq!(entries[0].attached.len(), 5);
992        assert_eq!(entries[1].message, "EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 export(originate_timeout=3600)");
993        assert_eq!(entries[1].kind, LineKind::UuidContinuation);
994        assert_eq!(
995            entries[2].message,
996            "EXPORT (export_vars) [originate_timeout]=[3600]"
997        );
998    }
999
1000    #[test]
1001    fn execute_between_full_lines_same_uuid() {
1002        let lines = vec![
1003            full_line(UUID1, TS1, "CoreSession::setVariable(X-C911P-City, ST GEORGES)"),
1004            format!("{UUID1} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 db(insert/ng_{UUID1}/city/ST GEORGES)"),
1005            full_line(UUID1, TS2, "CoreSession::setVariable(X-C911P-Region, SGS)"),
1006        ];
1007        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1008        assert_eq!(entries.len(), 3);
1009        assert_eq!(
1010            entries[0].message,
1011            "CoreSession::setVariable(X-C911P-City, ST GEORGES)"
1012        );
1013        assert!(entries[0].attached.is_empty());
1014        assert!(entries[1].message.starts_with("EXECUTE "));
1015        assert_eq!(entries[1].kind, LineKind::UuidContinuation);
1016        assert_eq!(
1017            entries[2].message,
1018            "CoreSession::setVariable(X-C911P-Region, SGS)"
1019        );
1020    }
1021
1022    #[test]
1023    fn multiple_execute_between_full_lines() {
1024        let lines = vec![
1025            full_line(UUID1, TS1, "CoreSession::setVariable(ngcs_call_id, urn:emergency:uid:callid:test)"),
1026            format!("{UUID1} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 db(insert/ng_{UUID1}/call_id/urn:emergency:uid:callid:test)"),
1027            format!("{UUID1} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 db(insert/callid_codecs/urn:emergency:uid:callid:test/PCMU@8000h)"),
1028            full_line(UUID1, TS2, "CoreSession::setVariable(ngcs_short_call_id, test)"),
1029        ];
1030        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1031        assert_eq!(entries.len(), 4);
1032        assert!(entries[0].attached.is_empty());
1033        assert!(entries[1].message.contains("call_id"));
1034        assert!(entries[2].message.contains("callid_codecs"));
1035        assert_eq!(
1036            entries[3].message,
1037            "CoreSession::setVariable(ngcs_short_call_id, test)"
1038        );
1039    }
1040
1041    #[test]
1042    fn uuid_continuation_different_uuid_yields() {
1043        let lines = vec![
1044            full_line(UUID1, TS1, "First"),
1045            format!("{UUID1} Channel-State: [CS_EXECUTE]"),
1046            format!("{UUID2} Dialplan: sofia/internal/+15550001234@192.0.2.1 parsing [public]"),
1047        ];
1048        let mut stream = LogStream::new(lines.into_iter());
1049        let first = stream.next().unwrap();
1050        assert_eq!(first.uuid, UUID1);
1051        assert_eq!(first.attached.len(), 1);
1052        let second = stream.next().unwrap();
1053        assert_eq!(second.uuid, UUID2);
1054        assert_eq!(
1055            second.message,
1056            "Dialplan: sofia/internal/+15550001234@192.0.2.1 parsing [public]"
1057        );
1058    }
1059
1060    // --- New: Block detection tests ---
1061
1062    #[test]
1063    fn channel_data_block_fields_and_variables() {
1064        let lines = vec![
1065            full_line(UUID1, TS1, "CHANNEL_DATA:"),
1066            format!("{UUID1} Channel-Name: [sofia/internal/+15550001234@192.0.2.1]"),
1067            format!("{UUID1} Channel-State: [CS_EXECUTE]"),
1068            format!("{UUID1} Unique-ID: [{UUID1}]"),
1069            "variable_sip_call_id: [test123@192.0.2.1]".to_string(),
1070            "variable_direction: [inbound]".to_string(),
1071        ];
1072        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1073        assert_eq!(entries.len(), 1);
1074        assert_eq!(entries[0].message_kind, MessageKind::ChannelData);
1075        let block = entries[0].block.as_ref().expect("should have block");
1076        match block {
1077            Block::ChannelData { fields, variables } => {
1078                assert_eq!(fields.len(), 3);
1079                assert_eq!(
1080                    fields[0],
1081                    (
1082                        "Channel-Name".to_string(),
1083                        "sofia/internal/+15550001234@192.0.2.1".to_string()
1084                    )
1085                );
1086                assert_eq!(
1087                    fields[1],
1088                    ("Channel-State".to_string(), "CS_EXECUTE".to_string())
1089                );
1090                assert_eq!(fields[2], ("Unique-ID".to_string(), UUID1.to_string()));
1091                assert_eq!(variables.len(), 2);
1092                assert_eq!(
1093                    variables[0],
1094                    (
1095                        "variable_sip_call_id".to_string(),
1096                        "test123@192.0.2.1".to_string()
1097                    )
1098                );
1099                assert_eq!(
1100                    variables[1],
1101                    ("variable_direction".to_string(), "inbound".to_string())
1102                );
1103            }
1104            other => panic!("expected ChannelData block, got {other:?}"),
1105        }
1106    }
1107
1108    #[test]
1109    fn channel_data_multiline_variable_reassembly() {
1110        let lines = vec![
1111            full_line(UUID1, TS1, "CHANNEL_DATA:"),
1112            format!("{UUID1} Channel-Name: [sofia/internal/+15550001234@192.0.2.1]"),
1113            "variable_switch_r_sdp: [v=0".to_string(),
1114            "o=- 1234 5678 IN IP4 192.0.2.1".to_string(),
1115            "s=-".to_string(),
1116            "c=IN IP4 192.0.2.1".to_string(),
1117            "m=audio 47758 RTP/AVP 0 101".to_string(),
1118            "a=rtpmap:0 PCMU/8000".to_string(),
1119            "]".to_string(),
1120            "variable_direction: [inbound]".to_string(),
1121        ];
1122        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1123        assert_eq!(entries.len(), 1);
1124        let block = entries[0].block.as_ref().expect("should have block");
1125        match block {
1126            Block::ChannelData { fields, variables } => {
1127                assert_eq!(fields.len(), 1);
1128                assert_eq!(variables.len(), 2);
1129                assert_eq!(variables[0].0, "variable_switch_r_sdp");
1130                assert!(variables[0].1.starts_with("v=0\n"));
1131                assert!(variables[0].1.contains("m=audio 47758 RTP/AVP 0 101"));
1132                assert!(!variables[0].1.ends_with(']'));
1133                assert_eq!(
1134                    variables[1],
1135                    ("variable_direction".to_string(), "inbound".to_string())
1136                );
1137            }
1138            other => panic!("expected ChannelData block, got {other:?}"),
1139        }
1140        assert_eq!(entries[0].attached.len(), 9);
1141    }
1142
1143    #[test]
1144    fn sdp_block_detection() {
1145        let lines = vec![
1146            full_line(UUID1, TS1, "Local SDP:"),
1147            "v=0".to_string(),
1148            "o=- 1234 5678 IN IP4 192.0.2.1".to_string(),
1149            "s=-".to_string(),
1150            "c=IN IP4 192.0.2.1".to_string(),
1151            "m=audio 10000 RTP/AVP 0".to_string(),
1152            "a=rtpmap:0 PCMU/8000".to_string(),
1153        ];
1154        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1155        assert_eq!(entries.len(), 1);
1156        match &entries[0].message_kind {
1157            MessageKind::SdpMarker { direction } => assert_eq!(*direction, SdpDirection::Local),
1158            other => panic!("expected SdpMarker, got {other:?}"),
1159        }
1160        let block = entries[0].block.as_ref().expect("should have block");
1161        match block {
1162            Block::Sdp { direction, body } => {
1163                assert_eq!(*direction, SdpDirection::Local);
1164                assert_eq!(body.len(), 6);
1165                assert_eq!(body[0], "v=0");
1166                assert_eq!(body[5], "a=rtpmap:0 PCMU/8000");
1167            }
1168            other => panic!("expected Sdp block, got {other:?}"),
1169        }
1170    }
1171
1172    #[test]
1173    fn sdp_block_terminated_by_primary_line() {
1174        let lines = vec![
1175            full_line(UUID1, TS1, "Remote SDP:"),
1176            "v=0".to_string(),
1177            "m=audio 10000 RTP/AVP 0".to_string(),
1178            full_line(UUID1, TS2, "Next event"),
1179        ];
1180        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1181        assert_eq!(entries.len(), 2);
1182        let block = entries[0].block.as_ref().expect("should have block");
1183        match block {
1184            Block::Sdp { direction, body } => {
1185                assert_eq!(*direction, SdpDirection::Remote);
1186                assert_eq!(body.len(), 2);
1187            }
1188            other => panic!("expected Sdp block, got {other:?}"),
1189        }
1190        assert!(entries[1].block.is_none());
1191    }
1192
1193    #[test]
1194    fn sdp_from_uuid_continuation() {
1195        let lines = vec![
1196            format!("{UUID1} Local SDP:"),
1197            format!("{UUID1} v=0"),
1198            format!("{UUID1} o=FreeSWITCH 1234 5678 IN IP4 192.0.2.1"),
1199            format!("{UUID1} s=FreeSWITCH"),
1200            format!("{UUID1} c=IN IP4 192.0.2.1"),
1201        ];
1202        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1203        assert_eq!(entries.len(), 1);
1204        let block = entries[0].block.as_ref().expect("should have block");
1205        match block {
1206            Block::Sdp { direction, body } => {
1207                assert_eq!(*direction, SdpDirection::Local);
1208                assert_eq!(body.len(), 4);
1209                assert_eq!(body[0], "v=0");
1210            }
1211            other => panic!("expected Sdp block, got {other:?}"),
1212        }
1213    }
1214
1215    #[test]
1216    fn channel_data_interrupted_by_different_uuid() {
1217        let lines = vec![
1218            full_line(UUID1, TS1, "CHANNEL_DATA:"),
1219            format!("{UUID1} Channel-Name: [sofia/internal/+15550001234@192.0.2.1]"),
1220            format!("{UUID2} Dialplan: sofia/internal/+15559999999@192.0.2.1 parsing [public]"),
1221        ];
1222        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1223        assert_eq!(entries.len(), 2);
1224        let block = entries[0].block.as_ref().expect("should have block");
1225        match block {
1226            Block::ChannelData { fields, .. } => {
1227                assert_eq!(fields.len(), 1);
1228            }
1229            other => panic!("expected ChannelData, got {other:?}"),
1230        }
1231    }
1232
1233    #[test]
1234    fn no_block_for_non_block_message() {
1235        let lines = vec![full_line(UUID1, TS1, "some random freeswitch log message")];
1236        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1237        assert_eq!(entries.len(), 1);
1238        assert!(entries[0].block.is_none());
1239        assert_eq!(entries[0].message_kind, MessageKind::General);
1240    }
1241
1242    #[test]
1243    fn message_kind_on_execute() {
1244        let lines = vec![
1245            full_line(UUID1, TS1, "First"),
1246            format!("{UUID1} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 set(foo=bar)"),
1247        ];
1248        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1249        assert_eq!(entries.len(), 2);
1250        match &entries[1].message_kind {
1251            MessageKind::Execute {
1252                application,
1253                arguments,
1254                ..
1255            } => {
1256                assert_eq!(application, "set");
1257                assert_eq!(arguments, "foo=bar");
1258            }
1259            other => panic!("expected Execute, got {other:?}"),
1260        }
1261    }
1262
1263    // --- New: ParseStats tests ---
1264
1265    #[test]
1266    fn stats_lines_processed() {
1267        let lines = vec![
1268            full_line(UUID1, TS1, "First"),
1269            full_line(UUID1, TS2, "Second"),
1270            format!("{UUID1} Channel-State: [CS_EXECUTE]"),
1271        ];
1272        let mut stream = LogStream::new(lines.into_iter());
1273        let _: Vec<_> = stream.by_ref().collect();
1274        assert_eq!(stream.stats().lines_processed, 3);
1275    }
1276
1277    #[test]
1278    fn stats_unclassified_orphan() {
1279        let lines = vec![
1280            "variable_foo: [bar]".to_string(),
1281            full_line(UUID1, TS1, "After orphan"),
1282        ];
1283        let mut stream = LogStream::new(lines.into_iter())
1284            .unclassified_tracking(UnclassifiedTracking::TrackLines);
1285        let _: Vec<_> = stream.by_ref().collect();
1286        assert_eq!(stream.stats().lines_unclassified, 1);
1287        assert_eq!(stream.stats().unclassified_lines.len(), 1);
1288        assert_eq!(
1289            stream.stats().unclassified_lines[0].reason,
1290            UnclassifiedReason::OrphanContinuation,
1291        );
1292    }
1293
1294    #[test]
1295    fn stats_capture_data() {
1296        let lines = vec!["orphan line".to_string(), full_line(UUID1, TS1, "After")];
1297        let mut stream = LogStream::new(lines.into_iter())
1298            .unclassified_tracking(UnclassifiedTracking::CaptureData);
1299        let _: Vec<_> = stream.by_ref().collect();
1300        assert_eq!(stream.stats().unclassified_lines.len(), 1);
1301        assert_eq!(
1302            stream.stats().unclassified_lines[0].data.as_deref(),
1303            Some("orphan line"),
1304        );
1305    }
1306
1307    #[test]
1308    fn stats_count_only_no_allocation() {
1309        let lines = vec!["orphan line".to_string(), full_line(UUID1, TS1, "After")];
1310        let mut stream = LogStream::new(lines.into_iter());
1311        let _: Vec<_> = stream.by_ref().collect();
1312        assert_eq!(stream.stats().lines_unclassified, 1);
1313        assert!(stream.stats().unclassified_lines.is_empty());
1314    }
1315
1316    #[test]
1317    fn line_number_tracking() {
1318        let lines = vec![
1319            full_line(UUID1, TS1, "First"),
1320            format!("{UUID1} Channel-State: [CS_EXECUTE]"),
1321            full_line(UUID2, TS2, "Third"),
1322        ];
1323        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1324        assert_eq!(entries[0].line_number, 1);
1325        assert_eq!(entries[1].line_number, 3);
1326    }
1327
1328    #[test]
1329    fn drain_unclassified() {
1330        let lines = vec![
1331            "orphan1".to_string(),
1332            "orphan2".to_string(),
1333            full_line(UUID1, TS1, "After"),
1334        ];
1335        let mut stream = LogStream::new(lines.into_iter())
1336            .unclassified_tracking(UnclassifiedTracking::TrackLines);
1337        let _: Vec<_> = stream.by_ref().collect();
1338        let drained = stream.drain_unclassified();
1339        assert_eq!(drained.len(), 1);
1340        assert!(stream.stats().unclassified_lines.is_empty());
1341        assert_eq!(stream.stats().lines_unclassified, 1);
1342    }
1343
1344    // BUG 1: When LogStream processes a TrackedChain of multiple file segments,
1345    // last_timestamp from the previous segment bleeds into continuation lines
1346    // at the start of the next segment. This causes entries to get timestamps
1347    // from a completely different file (potentially hours earlier).
1348    //
1349    // Reproduces: f2cb66d4 getting timestamp 23:58:03 from the rotated file
1350    // when freeswitch.log starts with its continuation lines.
1351    #[test]
1352    fn continuation_lines_at_file_boundary_must_not_inherit_previous_timestamp() {
1353        use crate::TrackedChain;
1354
1355        let uuid_a = "aaaaaaaa-1111-2222-3333-444444444444";
1356        let uuid_b = "bbbbbbbb-1111-2222-3333-444444444444";
1357        let ts_old = "2025-01-15 23:58:03.000000";
1358        let ts_new = "2025-01-16 08:37:12.000000";
1359
1360        let seg1: Vec<String> = vec![format!(
1361            "{uuid_a} {ts_old} 95.00% [DEBUG] test.c:1 Last line in rotated file"
1362        )];
1363
1364        // Segment 2 starts with UUID-continuation lines (Format C: UUID + message, no timestamp)
1365        // followed by a real timestamped line
1366        let seg2: Vec<String> = vec![
1367            format!("{uuid_b} CHANNEL_DATA:"),
1368            format!("{uuid_b} Channel-State: [CS_EXECUTE]"),
1369            format!("{uuid_b} {ts_new} 95.00% [DEBUG] test.c:1 First timestamped line in new file"),
1370        ];
1371
1372        let segments: Vec<(String, Box<dyn Iterator<Item = String>>)> = vec![
1373            ("rotated.log".to_string(), Box::new(seg1.into_iter())),
1374            ("freeswitch.log".to_string(), Box::new(seg2.into_iter())),
1375        ];
1376
1377        let (chain, _) = TrackedChain::new(segments);
1378        let entries: Vec<_> = LogStream::new(chain).collect();
1379
1380        let b_entry = entries
1381            .iter()
1382            .find(|e| e.uuid == uuid_b)
1383            .expect("should find entry for uuid_b");
1384
1385        // The CHANNEL_DATA entry for uuid_b must NOT have the timestamp from
1386        // segment 1 — it should either have the new file's first real timestamp
1387        // or be empty (indicating unknown).
1388        assert_ne!(
1389            b_entry.timestamp, ts_old,
1390            "continuation lines in a new file segment inherited timestamp \
1391             '{ts_old}' from the previous segment — timestamps must not bleed \
1392             across file boundaries"
1393        );
1394    }
1395
1396    // --- Line accounting tests ---
1397
1398    fn assert_accounting(stream: &LogStream<impl Iterator<Item = String>>) {
1399        let stats = stream.stats();
1400        assert_eq!(
1401            stats.unaccounted_lines(),
1402            0,
1403            "line accounting invariant violated: \
1404             processed={} + split={} != in_entries={} + empty_orphan={}",
1405            stats.lines_processed,
1406            stats.lines_split,
1407            stats.lines_in_entries,
1408            stats.lines_empty_orphan,
1409        );
1410    }
1411
1412    #[test]
1413    fn accounting_full_lines() {
1414        let lines = vec![
1415            full_line(UUID1, TS1, "First"),
1416            full_line(UUID2, TS2, "Second"),
1417        ];
1418        let mut stream = LogStream::new(lines.into_iter());
1419        let entries: Vec<_> = stream.by_ref().collect();
1420        assert_eq!(entries.len(), 2);
1421        assert_eq!(stream.stats().lines_in_entries, 2);
1422        assert_accounting(&stream);
1423    }
1424
1425    #[test]
1426    fn accounting_with_attached() {
1427        let lines = vec![
1428            full_line(UUID1, TS1, "CHANNEL_DATA:"),
1429            format!("{UUID1} Channel-State: [CS_EXECUTE]"),
1430            "variable_foo: [bar]".to_string(),
1431            full_line(UUID2, TS2, "Next"),
1432        ];
1433        let mut stream = LogStream::new(lines.into_iter());
1434        let entries: Vec<_> = stream.by_ref().collect();
1435        assert_eq!(entries.len(), 2);
1436        // Entry 1: 1 primary + 2 attached = 3 lines
1437        // Entry 2: 1 primary = 1 line
1438        assert_eq!(stream.stats().lines_in_entries, 4);
1439        assert_accounting(&stream);
1440    }
1441
1442    #[test]
1443    fn accounting_system_line() {
1444        let lines = vec![format!(
1445            "{TS1} 95.97% [NOTICE] mod_logfile.c:217 New log started."
1446        )];
1447        let mut stream = LogStream::new(lines.into_iter());
1448        let _: Vec<_> = stream.by_ref().collect();
1449        assert_eq!(stream.stats().lines_in_entries, 1);
1450        assert_accounting(&stream);
1451    }
1452
1453    #[test]
1454    fn accounting_empty_orphan() {
1455        let lines = vec![
1456            String::new(),
1457            "   ".to_string(),
1458            full_line(UUID1, TS1, "After"),
1459        ];
1460        let mut stream = LogStream::new(lines.into_iter());
1461        let entries: Vec<_> = stream.by_ref().collect();
1462        assert_eq!(entries.len(), 1);
1463        assert_eq!(stream.stats().lines_empty_orphan, 2);
1464        assert_accounting(&stream);
1465    }
1466
1467    #[test]
1468    fn accounting_empty_attached() {
1469        let lines = vec![
1470            full_line(UUID1, TS1, "First"),
1471            String::new(),
1472            "continuation".to_string(),
1473        ];
1474        let mut stream = LogStream::new(lines.into_iter());
1475        let entries: Vec<_> = stream.by_ref().collect();
1476        assert_eq!(entries.len(), 1);
1477        assert_eq!(entries[0].attached.len(), 2);
1478        assert_eq!(stream.stats().lines_empty_orphan, 0);
1479        assert_eq!(stream.stats().lines_in_entries, 3);
1480        assert_accounting(&stream);
1481    }
1482
1483    #[test]
1484    fn accounting_orphan_continuation() {
1485        let lines = vec!["orphan line".to_string(), full_line(UUID1, TS1, "After")];
1486        let mut stream = LogStream::new(lines.into_iter());
1487        let _: Vec<_> = stream.by_ref().collect();
1488        assert_accounting(&stream);
1489    }
1490
1491    #[test]
1492    fn accounting_codec_merging() {
1493        let lines = vec![
1494            full_line(
1495                UUID1,
1496                TS1,
1497                "Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]",
1498            ),
1499            full_line(
1500                UUID1,
1501                TS1,
1502                "Audio Codec Compare [PCMU:0:8000:20:64000:1] is saved as a match",
1503            ),
1504            full_line(UUID2, TS2, "Next"),
1505        ];
1506        let mut stream = LogStream::new(lines.into_iter());
1507        let _: Vec<_> = stream.by_ref().collect();
1508        assert_accounting(&stream);
1509    }
1510
1511    #[test]
1512    fn accounting_truncated_line() {
1513        let lines = vec![
1514            full_line(UUID1, TS1, "First"),
1515            format!(
1516                "varia{UUID2} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 set(x=y)"
1517            ),
1518        ];
1519        let mut stream = LogStream::new(lines.into_iter());
1520        let _: Vec<_> = stream.by_ref().collect();
1521        assert_accounting(&stream);
1522    }
1523
1524    #[test]
1525    fn accounting_long_line_collision_split() {
1526        // Simulate a long variable value exceeding mod_logfile's 2048-byte buffer,
1527        // followed by a collision UUID on the same physical line.
1528        let long_value = "x".repeat(MAX_LINE_PAYLOAD + 10);
1529        let line = format!(
1530            "variable_sip_multipart: [{long_value}]{UUID2} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 set(foo=bar)"
1531        );
1532        let lines = vec![full_line(UUID1, TS1, "CHANNEL_DATA:"), line];
1533        let mut stream = LogStream::new(lines.into_iter());
1534        let entries: Vec<_> = stream.by_ref().collect();
1535
1536        // The CHANNEL_DATA entry should have the truncated variable as attached
1537        assert_eq!(entries[0].message, "CHANNEL_DATA:");
1538
1539        // The collision should have been split out as a separate entry
1540        let split_entry = entries.iter().find(|e| e.uuid == UUID2);
1541        assert!(
1542            split_entry.is_some(),
1543            "collision UUID should produce a separate entry"
1544        );
1545
1546        assert_eq!(stream.stats().lines_split, 1);
1547        assert_accounting(&stream);
1548    }
1549
1550    #[test]
1551    fn no_split_on_short_lines() {
1552        // Lines within the payload limit should never be split,
1553        // even if they happen to contain a UUID-like pattern.
1554        let line = format!("variable_call_uuid: [{UUID2}]");
1555        let lines = vec![full_line(UUID1, TS1, "CHANNEL_DATA:"), line];
1556        let mut stream = LogStream::new(lines.into_iter());
1557        let entries: Vec<_> = stream.by_ref().collect();
1558        assert_eq!(entries.len(), 1);
1559        assert_eq!(stream.stats().lines_split, 0);
1560        assert_accounting(&stream);
1561    }
1562
1563    #[test]
1564    fn timestamp_collision_splits_system_lines() {
1565        let line = format!(
1566            "{TS1} 98.03% [INFO] mod_event_socket.c:1752 Event Socket Command from ::1:42864: api sofia jsonstatus{TS2} 97.93% [INFO] mod_event_socket.c:1752 Event Socket Command from ::1:42898: api fsctl pause_check"
1567        );
1568        let mut stream = LogStream::new(std::iter::once(line));
1569        let entries: Vec<_> = stream.by_ref().collect();
1570        assert_eq!(entries.len(), 2);
1571        assert_eq!(
1572            entries[0].message,
1573            "Event Socket Command from ::1:42864: api sofia jsonstatus"
1574        );
1575        assert_eq!(
1576            entries[1].message,
1577            "Event Socket Command from ::1:42898: api fsctl pause_check"
1578        );
1579        assert_eq!(stream.stats().lines_split, 1);
1580        assert_accounting(&stream);
1581    }
1582
1583    #[test]
1584    fn timestamp_collision_splits_three_entries() {
1585        let ts3 = "2025-01-15 10:30:47.345678";
1586        let line = format!(
1587            "{TS1} 95.00% [INFO] mod.c:1 first{TS2} 96.00% [INFO] mod.c:1 second{ts3} 97.00% [INFO] mod.c:1 third"
1588        );
1589        let mut stream = LogStream::new(std::iter::once(line));
1590        let entries: Vec<_> = stream.by_ref().collect();
1591        assert_eq!(entries.len(), 3);
1592        assert_eq!(entries[0].message, "first");
1593        assert_eq!(entries[1].message, "second");
1594        assert_eq!(entries[2].message, "third");
1595        assert_eq!(stream.stats().lines_split, 2);
1596        assert_accounting(&stream);
1597    }
1598
1599    #[test]
1600    fn timestamp_collision_oversize_write_contention() {
1601        // Production case: write contention concatenates dozens of short
1602        // Event Socket entries into a single physical line whose total
1603        // length exceeds MAX_LINE_PAYLOAD. Timestamps appear at offsets
1604        // ~150 bytes apart — none aligned with the 2010-byte buffer
1605        // boundary. All entries must still split out.
1606        let entry = |n: usize| {
1607            format!(
1608                "{TS1} 98.77% [INFO] mod_event_socket.c:1754 Event Socket Command from ::1:42864: api db select/ngcs_sip_call_id/entry-{n:04}"
1609            )
1610        };
1611        let count: u64 = 20;
1612        let line: String = (0..count).map(|n| entry(n as usize)).collect();
1613        assert!(
1614            line.len() > super::MAX_LINE_PAYLOAD,
1615            "test fixture should exceed MAX_LINE_PAYLOAD, got {}",
1616            line.len()
1617        );
1618
1619        let mut stream = LogStream::new(std::iter::once(line));
1620        let entries: Vec<_> = stream.by_ref().collect();
1621        assert_eq!(entries.len() as u64, count);
1622        for (i, e) in entries.iter().enumerate() {
1623            assert_eq!(
1624                e.message,
1625                format!(
1626                    "Event Socket Command from ::1:42864: api db select/ngcs_sip_call_id/entry-{i:04}"
1627                )
1628            );
1629        }
1630        assert_eq!(stream.stats().lines_split, count - 1);
1631        assert_accounting(&stream);
1632    }
1633
1634    #[test]
1635    fn timestamp_collision_with_uuid_prefix() {
1636        // System line collides with Full line (UUID + timestamp)
1637        let line = format!(
1638            "{TS1} 95.00% [INFO] mod.c:1 first{UUID1} {TS2} 96.00% [DEBUG] sofia.c:100 second"
1639        );
1640        let mut stream = LogStream::new(std::iter::once(line));
1641        let entries: Vec<_> = stream.by_ref().collect();
1642        assert_eq!(entries.len(), 2);
1643        assert_eq!(entries[0].message, "first");
1644        assert_eq!(entries[1].uuid, UUID1);
1645        assert_eq!(entries[1].message, "second");
1646        assert_eq!(stream.stats().lines_split, 1);
1647        assert_accounting(&stream);
1648    }
1649
1650    // Headers from older/eSInet FS builds omit the idle percentage:
1651    // "TIMESTAMP [LEVEL] source:line" directly. Collisions still split.
1652
1653    #[test]
1654    fn timestamp_collision_no_idle_pct_system() {
1655        let line = format!(
1656            "{TS1} [WARNING] sofia_presence.c:4546 Session does not exist, aborting REFER.{TS2} [WARNING] sofia_presence.c:4546 Session does not exist, aborting REFER."
1657        );
1658        let mut stream = LogStream::new(std::iter::once(line));
1659        let entries: Vec<_> = stream.by_ref().collect();
1660        assert_eq!(entries.len(), 2);
1661        assert_eq!(
1662            entries[0].message,
1663            "Session does not exist, aborting REFER."
1664        );
1665        assert_eq!(
1666            entries[1].message,
1667            "Session does not exist, aborting REFER."
1668        );
1669        assert_eq!(stream.stats().lines_split, 1);
1670        assert_accounting(&stream);
1671    }
1672
1673    #[test]
1674    fn timestamp_collision_no_idle_pct_uuid_suffix() {
1675        // Fixture shape: no-idle System WARNING whose un-terminated message
1676        // runs directly (no space) into a Full NOTICE line (UUID + timestamp).
1677        let line = format!(
1678            "{TS1} [WARNING] sofia_presence.c:4546 Session does not exist, aborting REFER.{UUID1} {TS2} [NOTICE] sofia.c:1114 Hangup sofia/internal/sos@192.0.2.10:5080 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]"
1679        );
1680        let mut stream = LogStream::new(std::iter::once(line));
1681        let entries: Vec<_> = stream.by_ref().collect();
1682        assert_eq!(entries.len(), 2);
1683        assert_eq!(entries[0].uuid, "");
1684        assert_eq!(
1685            entries[0].message,
1686            "Session does not exist, aborting REFER."
1687        );
1688        assert_eq!(entries[1].uuid, UUID1);
1689        assert_eq!(entries[1].level, Some(LogLevel::Notice));
1690        assert_eq!(
1691            entries[1].message,
1692            "Hangup sofia/internal/sos@192.0.2.10:5080 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]"
1693        );
1694        assert_eq!(stream.stats().lines_split, 1);
1695        assert_accounting(&stream);
1696    }
1697
1698    #[test]
1699    fn timestamp_collision_no_idle_pct_run_on() {
1700        // Dozens of un-terminated REFER warnings pile onto one physical line.
1701        let count: u64 = 15;
1702        let line: String = (0..count)
1703            .map(|n| {
1704                format!(
1705                    "2024-04-02 10:31:{:02}.945614 [WARNING] sofia_presence.c:4546 Session does not exist, aborting REFER.",
1706                    n + 10
1707                )
1708            })
1709            .collect();
1710        let mut stream = LogStream::new(std::iter::once(line));
1711        let entries: Vec<_> = stream.by_ref().collect();
1712        assert_eq!(entries.len() as u64, count);
1713        for e in &entries {
1714            assert_eq!(e.message, "Session does not exist, aborting REFER.");
1715        }
1716        assert_eq!(stream.stats().lines_split, count - 1);
1717        assert_accounting(&stream);
1718    }
1719
1720    #[test]
1721    fn channel_data_multiline_variable_spans_many_lines() {
1722        let lines = vec![
1723            full_line(UUID1, TS1, "CHANNEL_DATA:"),
1724            format!("{UUID1} Channel-Name: [sofia/internal/+15550001234@192.0.2.1]"),
1725            "variable_switch_r_sdp: [v=0".to_string(),
1726            "o=- 1234 5678 IN IP4 192.0.2.1".to_string(),
1727            "s=-".to_string(),
1728            "c=IN IP4 192.0.2.1".to_string(),
1729            "t=0 0".to_string(),
1730            "m=audio 47758 RTP/AVP 0 8 101".to_string(),
1731            "a=rtpmap:0 PCMU/8000".to_string(),
1732            "a=rtpmap:8 PCMA/8000".to_string(),
1733            "a=rtpmap:101 telephone-event/8000".to_string(),
1734            "a=fmtp:101 0-16".to_string(),
1735            "]".to_string(),
1736            "variable_direction: [inbound]".to_string(),
1737        ];
1738        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1739        assert_eq!(entries.len(), 1);
1740        let block = entries[0].block.as_ref().expect("should have block");
1741        match block {
1742            Block::ChannelData { fields, variables } => {
1743                assert_eq!(fields.len(), 1);
1744                assert_eq!(variables.len(), 2);
1745                assert_eq!(variables[0].0, "variable_switch_r_sdp");
1746                let sdp = &variables[0].1;
1747                assert!(sdp.starts_with("v=0\n"));
1748                assert!(sdp.contains("a=fmtp:101 0-16"));
1749                assert!(!sdp.ends_with(']'));
1750                assert_eq!(variables[1].0, "variable_direction");
1751            }
1752            other => panic!("expected ChannelData block, got {other:?}"),
1753        }
1754    }
1755
1756    #[test]
1757    fn sdp_from_verto_update_media() {
1758        let lines = vec![
1759            full_line(UUID1, TS1, "updateMedia: Local SDP"),
1760            "v=0".to_string(),
1761            "o=- 1234 5678 IN IP4 192.0.2.1".to_string(),
1762            "m=audio 10000 RTP/AVP 0".to_string(),
1763        ];
1764        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1765        assert_eq!(entries.len(), 1);
1766        match &entries[0].message_kind {
1767            MessageKind::SdpMarker { direction } => assert_eq!(*direction, SdpDirection::Local),
1768            other => panic!("expected SdpMarker, got {other:?}"),
1769        }
1770        let block = entries[0].block.as_ref().expect("should have block");
1771        match block {
1772            Block::Sdp { direction, body } => {
1773                assert_eq!(*direction, SdpDirection::Local);
1774                assert_eq!(body.len(), 3);
1775            }
1776            other => panic!("expected Sdp block, got {other:?}"),
1777        }
1778    }
1779
1780    #[test]
1781    fn duplicate_sdp_marker() {
1782        let lines = vec![
1783            full_line(UUID1, TS1, "Duplicate SDP"),
1784            "v=0".to_string(),
1785            "m=audio 10000 RTP/AVP 0".to_string(),
1786        ];
1787        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1788        assert_eq!(entries.len(), 1);
1789        match &entries[0].message_kind {
1790            MessageKind::SdpMarker { direction } => assert_eq!(*direction, SdpDirection::Unknown),
1791            other => panic!("expected SdpMarker, got {other:?}"),
1792        }
1793        assert!(entries[0].block.is_some());
1794    }
1795
1796    #[test]
1797    fn warning_on_unclosed_multiline_variable() {
1798        let lines = vec![
1799            full_line(UUID1, TS1, "CHANNEL_DATA:"),
1800            "variable_switch_r_sdp: [v=0".to_string(),
1801            "o=- 1234 5678 IN IP4 192.0.2.1".to_string(),
1802            full_line(UUID2, TS2, "Next entry"),
1803        ];
1804        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1805        assert_eq!(entries.len(), 2);
1806        assert!(
1807            entries[0]
1808                .warnings
1809                .iter()
1810                .any(|w| w.contains("unclosed multi-line variable")),
1811            "expected unclosed variable warning, got: {:?}",
1812            entries[0].warnings
1813        );
1814    }
1815
1816    #[test]
1817    fn warning_on_unparseable_channel_data_line() {
1818        let lines = vec![
1819            full_line(UUID1, TS1, "CHANNEL_DATA:"),
1820            format!("{UUID1} Channel-Name: [sofia/internal/+15550001234@192.0.2.1]"),
1821            format!("{UUID1} this is not a valid field line"),
1822        ];
1823        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1824        assert_eq!(entries.len(), 1);
1825        assert!(
1826            entries[0]
1827                .warnings
1828                .iter()
1829                .any(|w| w.contains("unparseable CHANNEL_DATA")),
1830            "expected unparseable warning, got: {:?}",
1831            entries[0].warnings
1832        );
1833    }
1834
1835    #[test]
1836    fn warning_on_unexpected_codec_continuation() {
1837        let lines = vec![
1838            full_line(
1839                UUID1,
1840                TS1,
1841                "Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]",
1842            ),
1843            format!("{UUID1} some unexpected continuation line"),
1844        ];
1845        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1846        assert_eq!(entries.len(), 1);
1847        assert!(
1848            entries[0]
1849                .warnings
1850                .iter()
1851                .any(|w| w.contains("unexpected codec negotiation")),
1852            "expected codec warning, got: {:?}",
1853            entries[0].warnings
1854        );
1855    }
1856
1857    fn codec_block(entry: &LogEntry) -> (&CodecMedia, &Vec<CodecOffer>, &Vec<CodecOffer>) {
1858        match &entry.block {
1859            Some(Block::CodecNegotiation {
1860                media,
1861                matched,
1862                near_matched,
1863                ..
1864            }) => (media, matched, near_matched),
1865            other => panic!("expected a codec block, got {other:?}"),
1866        }
1867    }
1868
1869    #[cfg(feature = "sdp")]
1870    #[test]
1871    fn sdp_body_parses_into_typed_codecs() {
1872        // Shaped like sofia.c:7634's output, RFC 5737/3849 addresses. The body
1873        // keeps the CRLF that reaches the log, which the parser must tolerate.
1874        let lines = vec![
1875            full_line(UUID1, TS1, "Remote SDP:"),
1876            format!("{UUID1} v=0\r"),
1877            format!("{UUID1} o=FreeSWITCH 1 1 IN IP4 192.0.2.10\r"),
1878            format!("{UUID1} s=FreeSWITCH\r"),
1879            format!("{UUID1} c=IN IP4 192.0.2.10\r"),
1880            format!("{UUID1} t=0 0\r"),
1881            format!("{UUID1} m=audio 9938 RTP/AVP 102 101\r"),
1882            format!("{UUID1} a=rtpmap:102 opus/48000/2\r"),
1883            format!("{UUID1} a=rtpmap:101 telephone-event/48000\r"),
1884            format!("{UUID1} a=ptime:20\r"),
1885            full_line(UUID2, TS2, "Next"),
1886        ];
1887        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1888        let codecs = entries[0]
1889            .block
1890            .as_ref()
1891            .expect("sdp block")
1892            .sdp_codecs()
1893            .expect("an sdp block yields Some")
1894            .expect("body parses");
1895
1896        let audio: Vec<&str> = codecs.audio().map(|c| c.name()).collect();
1897        assert_eq!(audio, ["opus"], "telephone-event is surfaced separately");
1898        assert_eq!(codecs.telephone_event_rates(), [48000]);
1899        let opus = codecs.audio().next().unwrap();
1900        assert_eq!(opus.payload_type(), 102);
1901        assert_eq!(opus.clock_rate(), 48000);
1902        assert_eq!(opus.channels(), Some(2));
1903        assert_eq!(opus.ptime(), Some(20));
1904    }
1905
1906    #[cfg(feature = "sdp")]
1907    #[test]
1908    fn only_sdp_blocks_yield_codecs() {
1909        let lines = vec![
1910            full_line(
1911                UUID1,
1912                TS1,
1913                "Audio Codec Compare [opus:116:16000:20:0:1]/[opus:116:16000:20:0:1]",
1914            ),
1915            full_line(UUID2, TS2, "Next"),
1916        ];
1917        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1918        assert!(entries[0].block.as_ref().unwrap().sdp_codecs().is_none());
1919    }
1920
1921    #[test]
1922    fn video_negotiation_has_its_own_arity() {
1923        let lines = vec![
1924            full_line(UUID1, TS1, "Video Codec Compare [H263:34]/[H264:97]"),
1925            full_line(
1926                UUID1,
1927                TS1,
1928                "Video Codec Compare [H263:34] +++ is saved as a match",
1929            ),
1930            full_line(UUID2, TS2, "Next"),
1931        ];
1932        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1933        let (media, matched, _) = codec_block(&entries[0]);
1934        assert_eq!(*media, CodecMedia::Video);
1935        assert_eq!(matched.len(), 1);
1936        assert_eq!(matched[0].name, "H263");
1937        assert_eq!(matched[0].payload_type, 34);
1938        assert_eq!(matched[0].clock_rate, None);
1939        assert!(entries[0].warnings.is_empty(), "{:?}", entries[0].warnings);
1940    }
1941
1942    #[test]
1943    fn audio_and_video_runs_do_not_merge() {
1944        let lines = vec![
1945            full_line(
1946                UUID1,
1947                TS1,
1948                "Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]",
1949            ),
1950            full_line(UUID1, TS1, "Video Codec Compare [H263:34]/[H264:97]"),
1951            full_line(UUID2, TS2, "Next"),
1952        ];
1953        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1954        assert_eq!(entries.len(), 3, "same UUID, different media, two blocks");
1955        assert_eq!(*codec_block(&entries[0]).0, CodecMedia::Audio);
1956        assert_eq!(*codec_block(&entries[1]).0, CodecMedia::Video);
1957    }
1958
1959    #[test]
1960    fn near_match_verdicts_are_data_not_warnings() {
1961        let lines = vec![
1962            full_line(
1963                UUID1,
1964                TS1,
1965                "Audio Codec Compare [opus:116:48000:20:0:1]/[opus:116:48000:20:0:1]",
1966            ),
1967            full_line(
1968                UUID1,
1969                TS1,
1970                "Audio Codec Compare [opus:116:48000:20:0:1] is saved as a near-match",
1971            ),
1972            // switch_core_media.c:5575 — seven fields, and the codec is dropped.
1973            full_line(
1974                UUID1,
1975                TS1,
1976                "Audio Codec Compare [PCMU:0:8000:8000:20:64000:1] was not saved as a near-match. Too many. Ignoring.",
1977            ),
1978            full_line(UUID2, TS2, "Next"),
1979        ];
1980        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1981        let (_, matched, near_matched) = codec_block(&entries[0]);
1982        assert!(matched.is_empty());
1983        assert_eq!(near_matched.len(), 1, "the dropped one is not kept");
1984        assert_eq!(near_matched[0].name, "opus");
1985        assert!(entries[0].warnings.is_empty(), "{:?}", entries[0].warnings);
1986    }
1987
1988    #[test]
1989    fn a_malformed_codec_token_still_warns() {
1990        let lines = vec![
1991            full_line(
1992                UUID1,
1993                TS1,
1994                "Audio Codec Compare [PCMU:0:8000:20:64000:1]/[nope]",
1995            ),
1996            full_line(UUID2, TS2, "Next"),
1997        ];
1998        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1999        assert!(
2000            entries[0]
2001                .warnings
2002                .iter()
2003                .any(|w| w.contains("unrecognized codec negotiation")),
2004            "got: {:?}",
2005            entries[0].warnings
2006        );
2007    }
2008
2009    #[test]
2010    fn system_line_uuid_continuation_not_absorbed() {
2011        // After the bug fix, a UUID continuation should NOT be absorbed
2012        // by a pending system line (empty UUID).
2013        let lines = vec![
2014            format!("{TS1} 95.97% [INFO] mod_event_socket.c:1772 Event Socket command"),
2015            format!("{UUID1} Channel-State: [CS_EXECUTE]"),
2016        ];
2017        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
2018        assert_eq!(
2019            entries.len(),
2020            2,
2021            "UUID continuation should not be absorbed by system entry"
2022        );
2023        assert_eq!(entries[0].uuid, "");
2024        assert_eq!(entries[1].uuid, UUID1);
2025    }
2026
2027    #[test]
2028    fn truncated_collision_in_channel_data_variable() {
2029        // A CHANNEL_DATA block where a variable value exceeds the 2048-byte
2030        // mod_logfile buffer, causing a truncated collision (Format E).
2031        // The variable_long_xml value opens with [ but the buffer truncation
2032        // causes a UUID+EXECUTE to collide on the same physical line before
2033        // the closing ].
2034        let padding = "x".repeat(2000);
2035        let collision_line = format!(
2036            "{UUID1} variable_long_xml: [{padding}{UUID1} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 export(foo=bar)"
2037        );
2038        assert!(
2039            collision_line.len() > super::MAX_LINE_PAYLOAD,
2040            "test line must exceed buffer limit, got {}",
2041            collision_line.len()
2042        );
2043
2044        let lines = vec![
2045            full_line(UUID1, TS1, "CHANNEL_DATA:"),
2046            format!("{UUID1} Channel-Name: [sofia/internal/+15550001234@192.0.2.1]"),
2047            format!("{UUID1} variable_direction: [inbound]"),
2048            collision_line,
2049            full_line(UUID1, TS2, "Next log entry"),
2050        ];
2051
2052        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
2053
2054        // Entry 0: CHANNEL_DATA with the variables
2055        assert_eq!(entries[0].message, "CHANNEL_DATA:");
2056        let block = entries[0].block.as_ref().expect("should have block");
2057        match block {
2058            Block::ChannelData { fields, variables } => {
2059                assert_eq!(fields.len(), 1, "should have Channel-Name field");
2060                assert_eq!(fields[0].0, "Channel-Name");
2061                assert_eq!(
2062                    variables.len(),
2063                    2,
2064                    "should have direction + unclosed long_xml"
2065                );
2066                assert_eq!(variables[0].0, "variable_direction");
2067                assert_eq!(variables[0].1, "inbound");
2068                assert_eq!(variables[1].0, "variable_long_xml");
2069            }
2070            other => panic!("expected ChannelData block, got {other:?}"),
2071        }
2072        assert!(
2073            entries[0]
2074                .warnings
2075                .iter()
2076                .any(|w| w.contains("line exceeds mod_logfile 2048-byte buffer")),
2077            "expected buffer overflow warning, got: {:?}",
2078            entries[0].warnings
2079        );
2080        assert!(
2081            entries[0]
2082                .warnings
2083                .iter()
2084                .any(|w| w.contains("unclosed multi-line variable")),
2085            "expected unclosed variable warning, got: {:?}",
2086            entries[0].warnings
2087        );
2088
2089        // Entry 1: the split EXECUTE line
2090        assert_eq!(entries[1].uuid, UUID1);
2091        assert!(
2092            entries[1].message.starts_with("EXECUTE "),
2093            "split entry should be EXECUTE, got: {}",
2094            entries[1].message
2095        );
2096
2097        // Entry 2: the next full log line
2098        assert_eq!(entries.len(), 3);
2099        assert_eq!(entries[2].message, "Next log entry");
2100    }
2101
2102    #[test]
2103    fn channel_data_uuid_drops_mid_block() {
2104        // Production scenario: mod_logfile stops prepending the UUID mid-way
2105        // through a CHANNEL_DATA dump. The first few variable lines carry the
2106        // UUID prefix (UuidContinuation), then the remaining lines arrive as
2107        // bare continuations. All should be accumulated into the same block.
2108        let lines = vec![
2109            full_line(UUID1, TS1, "CHANNEL_DATA:"),
2110            format!("{UUID1} variable_max_forwards: [69]"),
2111            format!("{UUID1} variable_presence_id: [1251@[2001:db8::10]]"),
2112            format!("{UUID1} variable_sip_h_X-Custom-ID: [c4da84eb-88a7-40b2-b90d-e5bc2a0f634e]"),
2113            // UUID drops — bare continuations for the rest
2114            "variable_sip_h_X-Call-Info: [<urn:test:callid:20260316>;purpose=emergency-CallId]"
2115                .to_string(),
2116            "variable_ep_codec_string: [mod_opus.opus@48000h@20i@2c]".to_string(),
2117            "variable_remote_media_ip: [2001:db8::10]".to_string(),
2118            "variable_remote_media_port: [9952]".to_string(),
2119            "variable_rtp_use_codec_name: [opus]".to_string(),
2120            full_line(UUID1, TS2, "Next entry"),
2121        ];
2122
2123        let mut stream = LogStream::new(lines.into_iter());
2124        let entries: Vec<_> = stream.by_ref().collect();
2125
2126        assert_eq!(entries.len(), 2);
2127        assert_eq!(entries[0].message, "CHANNEL_DATA:");
2128        let block = entries[0].block.as_ref().expect("should have block");
2129        match block {
2130            Block::ChannelData { fields, variables } => {
2131                assert_eq!(fields.len(), 0);
2132                assert_eq!(variables.len(), 8);
2133                // UUID-prefixed variables
2134                assert_eq!(variables[0].0, "variable_max_forwards");
2135                assert_eq!(variables[0].1, "69");
2136                assert_eq!(variables[1].0, "variable_presence_id");
2137                assert_eq!(variables[1].1, "1251@[2001:db8::10]");
2138                assert_eq!(variables[2].0, "variable_sip_h_X-Custom-ID");
2139                // Bare variables (UUID dropped)
2140                assert_eq!(variables[3].0, "variable_sip_h_X-Call-Info");
2141                assert!(variables[3].1.contains("emergency-CallId"));
2142                assert_eq!(variables[4].0, "variable_ep_codec_string");
2143                assert_eq!(variables[7].0, "variable_rtp_use_codec_name");
2144                assert_eq!(variables[7].1, "opus");
2145            }
2146            other => panic!("expected ChannelData block, got {other:?}"),
2147        }
2148        assert_eq!(entries[0].attached.len(), 8);
2149        assert_eq!(entries[1].message, "Next entry");
2150        assert_accounting(&stream);
2151    }
2152
2153    #[test]
2154    fn channel_data_uuid_drops_with_multiline_variable() {
2155        // UUID drops mid-block AND a multi-line variable (SDP body embedded
2156        // in variable_switch_r_sdp) spans many bare continuation lines.
2157        // The \r characters are real — SDP uses \r\n per RFC 4566, and
2158        // mod_logfile splits on \n leaving \r in the content.
2159        let lines = vec![
2160            full_line(UUID1, TS1, "CHANNEL_DATA:"),
2161            format!("{UUID1} variable_max_forwards: [69]"),
2162            format!("{UUID1} variable_sip_h_X-Custom-ID: [c4da84eb-88a7-40b2-b90d-e5bc2a0f634e]"),
2163            // UUID drops
2164            "variable_switch_r_sdp: [v=0\r".to_string(),
2165            "o=FreeSWITCH 1773663549 1773663550 IN IP6 2001:db8::10\r".to_string(),
2166            "s=FreeSWITCH\r".to_string(),
2167            "c=IN IP6 2001:db8::10\r".to_string(),
2168            "t=0 0\r".to_string(),
2169            "m=audio 9952 RTP/AVP 102 101 13\r".to_string(),
2170            "a=rtpmap:102 opus/48000/2\r".to_string(),
2171            "a=ptime:20\r".to_string(),
2172            "]".to_string(),
2173            "variable_ep_codec_string: [mod_opus.opus@48000h@20i@2c]".to_string(),
2174            "variable_direction: [inbound]".to_string(),
2175            full_line(UUID1, TS2, "Next entry"),
2176        ];
2177
2178        let mut stream = LogStream::new(lines.into_iter());
2179        let entries: Vec<_> = stream.by_ref().collect();
2180
2181        assert_eq!(entries.len(), 2);
2182        let block = entries[0].block.as_ref().expect("should have block");
2183        match block {
2184            Block::ChannelData { fields, variables } => {
2185                assert_eq!(fields.len(), 0);
2186                assert_eq!(variables.len(), 5);
2187                assert_eq!(variables[0].0, "variable_max_forwards");
2188                assert_eq!(variables[1].0, "variable_sip_h_X-Custom-ID");
2189                // Multi-line SDP variable reassembled from bare continuations
2190                assert_eq!(variables[2].0, "variable_switch_r_sdp");
2191                let sdp = &variables[2].1;
2192                assert!(
2193                    sdp.starts_with("v=0\r\n"),
2194                    "SDP should start with v=0\\r\\n, got: {sdp:?}"
2195                );
2196                assert!(sdp.contains("m=audio 9952 RTP/AVP 102 101 13\r"));
2197                assert!(sdp.contains("a=ptime:20\r"));
2198                assert!(!sdp.ends_with(']'), "closing bracket should be stripped");
2199                // Post-SDP bare variables
2200                assert_eq!(variables[3].0, "variable_ep_codec_string");
2201                assert_eq!(variables[4].0, "variable_direction");
2202                assert_eq!(variables[4].1, "inbound");
2203            }
2204            other => panic!("expected ChannelData block, got {other:?}"),
2205        }
2206        // 2 UUID continuations + 9 SDP lines (open + 7 content + close) + 2 bare = 13
2207        assert_eq!(entries[0].attached.len(), 13);
2208        assert_accounting(&stream);
2209    }
2210
2211    #[test]
2212    fn channel_data_bare_variable_collision_with_execute() {
2213        // Production collision: bare variable_call_uuid line on same physical
2214        // line as a UUID EXECUTE. The UUID appears at byte 20 ("variable_call_uuid: "
2215        // is 20 chars), within find_uuid_in's 50-byte scan window, so Layer 1
2216        // classifies it as Truncated — extracting the UUID and EXECUTE message.
2217        // The CHANNEL_DATA block loses variable_call_uuid (eaten as truncation
2218        // prefix) but correctly recovers the EXECUTE as a separate entry.
2219        let collision = format!(
2220            "variable_call_uuid: {UUID1} EXECUTE [depth=0] \
2221             sofia/internal-v6/1251@[2001:db8::10] export(nolocal:test_var=value)"
2222        );
2223
2224        let lines = vec![
2225            full_line(UUID1, TS1, "CHANNEL_DATA:"),
2226            format!("{UUID1} variable_max_forwards: [69]"),
2227            // UUID drops — bare continuations
2228            "variable_DP_MATCH: [ARRAY::create_conference|:create_conference]".to_string(),
2229            collision,
2230            // Full line resumes normal logging
2231            full_line(
2232                UUID1,
2233                TS2,
2234                "EXPORT (export_vars) (REMOTE ONLY) [test_var]=[value]",
2235            ),
2236        ];
2237
2238        let mut stream = LogStream::new(lines.into_iter());
2239        let entries: Vec<_> = stream.by_ref().collect();
2240
2241        // Entry 0: CHANNEL_DATA — variable_call_uuid lost to truncation prefix
2242        assert_eq!(entries.len(), 3);
2243        let block = entries[0].block.as_ref().expect("should have block");
2244        match block {
2245            Block::ChannelData { fields, variables } => {
2246                assert_eq!(fields.len(), 0);
2247                assert_eq!(variables.len(), 2);
2248                assert_eq!(variables[0].0, "variable_max_forwards");
2249                assert_eq!(variables[1].0, "variable_DP_MATCH");
2250            }
2251            other => panic!("expected ChannelData block, got {other:?}"),
2252        }
2253
2254        // Entry 1: EXECUTE recovered from the Truncated classification
2255        assert_eq!(entries[1].uuid, UUID1);
2256        assert_eq!(entries[1].kind, LineKind::Truncated);
2257        assert!(
2258            entries[1].message.starts_with("EXECUTE "),
2259            "truncated line should yield EXECUTE, got: {}",
2260            entries[1].message
2261        );
2262
2263        // Entry 2: normal EXPORT line
2264        assert_eq!(entries[2].message_kind.label(), "variable");
2265        assert_accounting(&stream);
2266    }
2267
2268    // --- Multi-byte content straddling the 80-byte warning truncation ---
2269
2270    #[test]
2271    fn multibyte_at_warning_truncation_unrecognized_codec() {
2272        // 'é' occupies bytes 79-80 of the message: truncating at 80 splits it.
2273        let msg = format!(
2274            "Audio Codec Compare {}é tail beyond eighty bytes",
2275            "x".repeat(59)
2276        );
2277        assert!(!msg.is_char_boundary(80));
2278        let lines = vec![
2279            full_line(
2280                UUID1,
2281                TS1,
2282                "Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]",
2283            ),
2284            full_line(UUID1, TS1, &msg),
2285        ];
2286        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
2287        assert_eq!(entries.len(), 1);
2288        assert!(
2289            entries[0]
2290                .warnings
2291                .iter()
2292                .any(|w| w.contains("unrecognized codec negotiation")),
2293            "expected codec warning, got: {:?}",
2294            entries[0].warnings
2295        );
2296    }
2297
2298    #[test]
2299    fn multibyte_at_warning_truncation_channel_data() {
2300        let bare = format!(
2301            "{}é tail beyond eighty bytes with no field separator",
2302            "x".repeat(79)
2303        );
2304        assert!(!bare.is_char_boundary(80));
2305        let lines = vec![full_line(UUID1, TS1, "CHANNEL_DATA:"), bare];
2306        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
2307        assert_eq!(entries.len(), 1);
2308        assert!(
2309            entries[0]
2310                .warnings
2311                .iter()
2312                .any(|w| w.contains("unparseable CHANNEL_DATA")),
2313            "expected unparseable warning, got: {:?}",
2314            entries[0].warnings
2315        );
2316    }
2317
2318    #[test]
2319    fn multibyte_at_warning_truncation_codec_continuation() {
2320        let cont = format!("{}é tail beyond eighty bytes", "x".repeat(79));
2321        assert!(!cont.is_char_boundary(80));
2322        let lines = vec![
2323            full_line(
2324                UUID1,
2325                TS1,
2326                "Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]",
2327            ),
2328            format!("{UUID1} {cont}"),
2329        ];
2330        let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
2331        assert_eq!(entries.len(), 1);
2332        assert!(
2333            entries[0]
2334                .warnings
2335                .iter()
2336                .any(|w| w.contains("unexpected codec negotiation")),
2337            "expected codec continuation warning, got: {:?}",
2338            entries[0].warnings
2339        );
2340    }
2341
2342    #[test]
2343    fn system_line_with_embedded_uuid_gets_entry_uuid() {
2344        // System lines (Format B) where switch_cpp.cpp logs the UUID at the
2345        // start of the message body should produce entries with the correct UUID.
2346        let lines = vec![
2347            format!(
2348                "{TS1} 95.97% [DEBUG] switch_cpp.cpp:1466 {UUID1} DAA-LOG WaveManager originate"
2349            ),
2350            format!(
2351                "{TS1} 95.97% [WARNING] switch_cpp.cpp:1466 {UUID1} DAA-LOG Failed to create session"
2352            ),
2353            full_line(UUID1, TS2, "State Change CS_EXECUTE -> CS_HIBERNATE"),
2354        ];
2355
2356        let mut stream = LogStream::new(lines.into_iter());
2357        let entries: Vec<_> = stream.by_ref().collect();
2358
2359        assert_eq!(entries.len(), 3);
2360        // Both System lines should have the UUID extracted from the message
2361        assert_eq!(entries[0].uuid, UUID1);
2362        assert_eq!(entries[0].kind, LineKind::System);
2363        assert_eq!(entries[0].message, "DAA-LOG WaveManager originate");
2364
2365        assert_eq!(entries[1].uuid, UUID1);
2366        assert_eq!(entries[1].kind, LineKind::System);
2367        assert_eq!(entries[1].message, "DAA-LOG Failed to create session");
2368
2369        // Full line still works normally
2370        assert_eq!(entries[2].uuid, UUID1);
2371        assert_eq!(entries[2].kind, LineKind::Full);
2372        assert_accounting(&stream);
2373    }
2374}