Skip to main content

freeswitch_log_parser/
stream.rs

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