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