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#[derive(Debug, Clone, PartialEq, Eq)]
15#[non_exhaustive]
16pub enum Block {
17 ChannelData {
20 fields: Vec<(String, String)>,
21 variables: Vec<(String, String)>,
22 },
23 Sdp {
25 direction: SdpDirection,
26 body: Vec<String>,
27 },
28 CodecNegotiation {
30 comparisons: Vec<(String, String)>,
31 selected: Vec<String>,
32 },
33}
34
35#[derive(Debug, Clone, Copy, PartialEq, Eq)]
39pub enum UnclassifiedTracking {
40 CountOnly,
42 TrackLines,
44 CaptureData,
46}
47
48#[derive(Debug, Clone, PartialEq, Eq)]
50#[non_exhaustive]
51pub enum UnclassifiedReason {
52 OrphanContinuation,
54 UnknownMessageFormat,
56 TruncatedField,
58}
59
60#[derive(Debug, Clone, PartialEq, Eq)]
62pub struct UnclassifiedLine {
63 pub line_number: u64,
64 pub reason: UnclassifiedReason,
65 pub data: Option<String>,
67}
68
69#[derive(Debug, Clone, Default)]
71pub struct ParseStats {
72 pub lines_processed: u64,
73 pub lines_unclassified: u64,
74 pub lines_in_entries: u64,
76 pub lines_empty_orphan: u64,
78 pub lines_split: u64,
81 pub unclassified_lines: Vec<UnclassifiedLine>,
83}
84
85impl ParseStats {
86 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#[derive(Debug)]
105pub struct LogEntry {
106 pub uuid: String,
108 pub timestamp: String,
110 pub level: Option<LogLevel>,
112 pub idle_pct: Option<String>,
114 pub source: Option<String>,
116 pub message: String,
118 pub kind: LineKind,
120 pub message_kind: MessageKind,
122 pub block: Option<Block>,
124 pub attached: AttachedLines,
126 pub line_number: u64,
128 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: 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
172pub 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 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 pub fn unclassified_tracking(mut self, level: UnclassifiedTracking) -> Self {
213 self.tracking = level;
214 self
215 }
216
217 pub fn stats(&self) -> &ParseStats {
219 &self.stats
220 }
221
222 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
427const MOD_LOGFILE_BUF_SIZE: usize = 2048;
431
432const MAX_LINE_PAYLOAD: usize = MOD_LOGFILE_BUF_SIZE - UUID_PREFIX_LEN - 1;
435
436const COLLISION_SCAN_SLACK: usize = 64;
442
443impl<I: Iterator<Item = String>> LogStream<I> {
444 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 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 } else {
480 UUID_PREFIX_LEN }
482 } else if is_date_at(bytes, 0) {
483 27 } else {
485 0
486 };
487
488 let end = bytes.len().saturating_sub(28);
489 let oversize = bytes.len() > MAX_LINE_PAYLOAD;
490
491 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 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 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 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 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 #[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 #[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 #[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 #[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 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 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 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 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 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 assert_eq!(entries[0].message, "CHANNEL_DATA:");
1446
1447 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 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 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 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 #[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 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 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 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 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 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 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 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 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 "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 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 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 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 "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 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 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 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 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 "variable_DP_MATCH: [ARRAY::create_conference|:create_conference]".to_string(),
1985 collision,
1986 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 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 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 assert_eq!(entries[2].message_kind.label(), "variable");
2021 assert_accounting(&stream);
2022 }
2023
2024 #[test]
2027 fn multibyte_at_warning_truncation_unrecognized_codec() {
2028 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 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 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 assert_eq!(entries[2].uuid, UUID1);
2127 assert_eq!(entries[2].kind, LineKind::Full);
2128 assert_accounting(&stream);
2129 }
2130}