1use crate::attached::AttachedLines;
2use crate::codec::{CodecMedia, CodecOffer};
3use crate::decode::truncate_at_char_boundary;
4use crate::level::LogLevel;
5use crate::line::{
6 is_date_at, is_log_header_at, is_uuid_at, parse_line, LineKind, UUID_PREFIX_LEN,
7};
8use crate::message::{classify_message, MessageKind, SdpDirection};
9use std::collections::VecDeque;
10
11#[derive(Debug, Clone, PartialEq, Eq)]
16#[non_exhaustive]
17pub enum Block {
18 ChannelData {
21 fields: Vec<(String, String)>,
22 variables: Vec<(String, String)>,
23 },
24 Sdp {
26 direction: SdpDirection,
27 body: Vec<String>,
28 },
29 CodecNegotiation {
32 media: CodecMedia,
33 comparisons: Vec<(CodecOffer, CodecOffer)>,
35 matched: Vec<CodecOffer>,
36 near_matched: Vec<CodecOffer>,
38 },
39}
40
41#[cfg(feature = "sdp")]
42impl Block {
43 pub fn sdp_codecs(
55 &self,
56 ) -> Option<Result<freeswitch_types::sdp::SdpCodecs, freeswitch_types::sdp::SdpCodecError>>
57 {
58 let Block::Sdp { body, .. } = self else {
59 return None;
60 };
61 let text = body.join("\n");
62 if text.trim().is_empty() {
63 return None;
64 }
65 Some(freeswitch_types::sdp::SdpCodecs::parse(&text))
66 }
67}
68
69#[derive(Debug, Clone, Copy, PartialEq, Eq)]
73pub enum UnclassifiedTracking {
74 CountOnly,
76 TrackLines,
78 CaptureData,
80}
81
82#[derive(Debug, Clone, PartialEq, Eq)]
84#[non_exhaustive]
85pub enum UnclassifiedReason {
86 OrphanContinuation,
88 UnknownMessageFormat,
90 TruncatedField,
92}
93
94#[derive(Debug, Clone, PartialEq, Eq)]
96pub struct UnclassifiedLine {
97 pub line_number: u64,
98 pub reason: UnclassifiedReason,
99 pub data: Option<String>,
101}
102
103#[derive(Debug, Clone, Default)]
105pub struct ParseStats {
106 pub lines_processed: u64,
107 pub lines_unclassified: u64,
108 pub lines_in_entries: u64,
110 pub lines_empty_orphan: u64,
112 pub lines_split: u64,
115 pub unclassified_lines: Vec<UnclassifiedLine>,
117}
118
119impl ParseStats {
120 pub fn unaccounted_lines(&self) -> u64 {
127 let expected = self.lines_in_entries + self.lines_empty_orphan;
128 let actual = self.lines_processed + self.lines_split;
129 actual.saturating_sub(expected)
130 }
131}
132
133#[derive(Debug)]
139pub struct LogEntry {
140 pub uuid: String,
142 pub timestamp: String,
144 pub level: Option<LogLevel>,
146 pub idle_pct: Option<String>,
148 pub source: Option<String>,
150 pub message: String,
152 pub kind: LineKind,
154 pub message_kind: MessageKind,
156 pub block: Option<Block>,
158 pub attached: AttachedLines,
160 pub line_number: u64,
162 pub warnings: Vec<String>,
164}
165
166fn parse_field_line(msg: &str) -> Option<(String, String)> {
167 let colon = msg.find(": ")?;
168 let name = &msg[..colon];
169 if name.contains(' ') || name.is_empty() {
170 return None;
171 }
172 let value_part = &msg[colon + 2..];
173 let value = if let Some(inner) = value_part.strip_prefix('[') {
174 inner.strip_suffix(']').unwrap_or(inner)
175 } else {
176 value_part
177 };
178 Some((name.to_string(), value.to_string()))
179}
180
181enum StreamState {
182 Idle,
183 InChannelData {
184 fields: Vec<(String, String)>,
185 variables: Vec<(String, String)>,
186 open_var: Option<(String, String)>,
189 },
190 InSdp {
191 direction: SdpDirection,
192 body: Vec<String>,
193 },
194 InCodecNegotiation {
195 media: CodecMedia,
196 comparisons: Vec<(CodecOffer, CodecOffer)>,
197 matched: Vec<CodecOffer>,
198 near_matched: Vec<CodecOffer>,
199 },
200}
201
202impl StreamState {
203 fn take_idle(&mut self) -> StreamState {
204 std::mem::replace(self, StreamState::Idle)
205 }
206}
207
208pub struct LogStream<I> {
218 lines: I,
219 last_uuid: String,
220 last_timestamp: String,
221 pending: Option<LogEntry>,
222 state: StreamState,
223 stats: ParseStats,
224 tracking: UnclassifiedTracking,
225 line_number: u64,
226 split_pending: VecDeque<String>,
227 deferred_warning: Option<String>,
228}
229
230impl<I: Iterator<Item = String>> LogStream<I> {
231 pub fn new(lines: I) -> Self {
233 LogStream {
234 lines,
235 last_uuid: String::new(),
236 last_timestamp: String::new(),
237 pending: None,
238 state: StreamState::Idle,
239 stats: ParseStats::default(),
240 tracking: UnclassifiedTracking::CountOnly,
241 line_number: 0,
242 split_pending: VecDeque::new(),
243 deferred_warning: None,
244 }
245 }
246
247 pub fn unclassified_tracking(mut self, level: UnclassifiedTracking) -> Self {
249 self.tracking = level;
250 self
251 }
252
253 pub fn stats(&self) -> &ParseStats {
255 &self.stats
256 }
257
258 pub fn drain_unclassified(&mut self) -> Vec<UnclassifiedLine> {
262 std::mem::take(&mut self.stats.unclassified_lines)
263 }
264
265 fn record_unclassified(&mut self, reason: UnclassifiedReason, data: Option<&str>) {
266 self.stats.lines_unclassified += 1;
267 match self.tracking {
268 UnclassifiedTracking::CountOnly => {}
269 UnclassifiedTracking::TrackLines => {
270 self.stats.unclassified_lines.push(UnclassifiedLine {
271 line_number: self.line_number,
272 reason,
273 data: None,
274 });
275 }
276 UnclassifiedTracking::CaptureData => {
277 self.stats.unclassified_lines.push(UnclassifiedLine {
278 line_number: self.line_number,
279 reason,
280 data: data.map(|s| s.to_string()),
281 });
282 }
283 }
284 }
285
286 fn finalize_block(&mut self) -> (Option<Block>, Vec<String>) {
287 let mut warnings = Vec::new();
288 match self.state.take_idle() {
289 StreamState::Idle => (None, warnings),
290 StreamState::InChannelData {
291 fields,
292 mut variables,
293 open_var,
294 } => {
295 if let Some((name, value)) = open_var {
296 warnings.push(format!("unclosed multi-line variable: {name}"));
297 variables.push((name, value));
298 }
299 (Some(Block::ChannelData { fields, variables }), warnings)
300 }
301 StreamState::InSdp { direction, body } => {
302 (Some(Block::Sdp { direction, body }), warnings)
303 }
304 StreamState::InCodecNegotiation {
305 media,
306 comparisons,
307 matched,
308 near_matched,
309 } => (
310 Some(Block::CodecNegotiation {
311 media,
312 comparisons,
313 matched,
314 near_matched,
315 }),
316 warnings,
317 ),
318 }
319 }
320
321 fn finalize_pending(&mut self) -> Option<LogEntry> {
322 let (block, warnings) = self.finalize_block();
323 if let Some(ref mut p) = self.pending {
324 p.block = block;
325 p.warnings.extend(warnings);
326 self.stats.lines_in_entries += 1 + p.attached.len() as u64;
327 }
328 self.pending.take()
329 }
330
331 fn start_block_for_message(&mut self, message_kind: &MessageKind) {
332 self.state = match message_kind {
333 MessageKind::ChannelData => StreamState::InChannelData {
334 fields: Vec::new(),
335 variables: Vec::new(),
336 open_var: None,
337 },
338 MessageKind::SdpMarker { direction } => StreamState::InSdp {
339 direction: direction.clone(),
340 body: Vec::new(),
341 },
342 MessageKind::CodecNegotiation { media } => StreamState::InCodecNegotiation {
343 media: *media,
344 comparisons: Vec::new(),
345 matched: Vec::new(),
346 near_matched: Vec::new(),
347 },
348 _ => StreamState::Idle,
349 };
350 }
351
352 #[must_use]
356 fn accumulate_codec_entry(&mut self, msg: &str) -> Option<String> {
357 let mut warning = None;
358 if let StreamState::InCodecNegotiation {
359 media,
360 comparisons,
361 matched,
362 near_matched,
363 } = &mut self.state
364 {
365 let media = *media;
366 let parse = |token: &str| {
367 CodecOffer::parse(media, token).map_err(|e| {
368 format!(
369 "unrecognized codec negotiation line ({e}): {}",
370 truncate_at_char_boundary(msg, 80)
371 )
372 })
373 };
374
375 let rest = msg
379 .strip_prefix("Audio Codec Compare ")
380 .or_else(|| msg.strip_prefix("Video Codec Compare "))
381 .unwrap_or(msg);
382
383 let result = if let Some(slash) = rest.find("]/[") {
384 let offered = &rest[1..slash];
385 let local = rest[slash + 3..].trim_end_matches(']');
386 parse(offered).and_then(|o| parse(local).map(|l| comparisons.push((o, l))))
387 } else if let Some(end) = rest.find(']') {
388 let token = &rest[1..end];
389 let verdict = &rest[end + 1..];
390 if verdict.contains("was not saved") {
391 parse(token).map(|_| ())
394 } else if verdict.contains("near-match") {
395 parse(token).map(|c| near_matched.push(c))
396 } else if verdict.contains("is saved as a match") {
397 parse(token).map(|c| matched.push(c))
398 } else {
399 Err(format!(
400 "unrecognized codec negotiation line: {}",
401 truncate_at_char_boundary(msg, 80)
402 ))
403 }
404 } else {
405 Err(format!(
406 "unrecognized codec negotiation line: {}",
407 truncate_at_char_boundary(msg, 80)
408 ))
409 };
410 warning = result.err();
411 }
412 warning
413 }
414
415 fn accumulate_continuation(&mut self, msg: &str, line: &str) {
416 let msg_kind = classify_message(msg);
417 let mut warning = None;
418 match &mut self.state {
419 StreamState::InChannelData {
420 fields,
421 variables,
422 open_var,
423 } => {
424 if let Some((_, val)) = open_var {
425 val.push('\n');
426 val.push_str(msg);
427 if msg.ends_with(']') {
428 if let Some((name, val)) = open_var.take() {
429 variables.push((name, val.trim_end_matches(']').to_string()));
430 }
431 }
432 } else {
433 match &msg_kind {
434 MessageKind::ChannelField { name, value } => {
435 fields.push((name.clone(), value.clone()));
436 }
437 MessageKind::Variable { name, value } => {
438 if !msg.ends_with(']') && msg.contains(": [") {
439 *open_var = Some((name.clone(), value.clone()));
440 } else {
441 variables.push((name.clone(), value.clone()));
442 }
443 }
444 _ => {
445 if let Some((name, value)) = parse_field_line(msg) {
446 fields.push((name, value));
447 } else {
448 warning = Some(format!(
449 "unparseable CHANNEL_DATA line: {}",
450 truncate_at_char_boundary(msg, 80)
451 ));
452 }
453 }
454 }
455 }
456 }
457 StreamState::InSdp { body, .. } => {
458 body.push(msg.to_string());
459 }
460 StreamState::InCodecNegotiation { .. } => {
461 warning = Some(format!(
462 "unexpected codec negotiation continuation: {}",
463 truncate_at_char_boundary(msg, 80)
464 ));
465 }
466 StreamState::Idle => {}
467 }
468 if let Some(ref mut pending) = self.pending {
469 if let Some(w) = warning {
470 pending.warnings.push(w);
471 }
472 pending.attached.push(line);
473 }
474 }
475
476 fn new_entry(
477 &mut self,
478 uuid: String,
479 timestamp: String,
480 message: String,
481 kind: LineKind,
482 message_kind: MessageKind,
483 ) -> LogEntry {
484 let mut warnings = Vec::new();
485 if let Some(w) = self.deferred_warning.take() {
486 warnings.push(w);
487 }
488 LogEntry {
489 uuid,
490 timestamp,
491 message,
492 kind,
493 message_kind,
494 level: None,
495 idle_pct: None,
496 source: None,
497 block: None,
498 attached: AttachedLines::new(),
499 line_number: self.line_number,
500 warnings,
501 }
502 }
503}
504
505const MOD_LOGFILE_BUF_SIZE: usize = 2048;
509
510const MAX_LINE_PAYLOAD: usize = MOD_LOGFILE_BUF_SIZE - UUID_PREFIX_LEN - 1;
513
514const COLLISION_SCAN_SLACK: usize = 64;
520
521impl<I: Iterator<Item = String>> LogStream<I> {
522 fn detect_collision(&mut self, line: String) -> String {
540 if line.len() > MAX_LINE_PAYLOAD {
541 let warning = format!(
542 "line exceeds mod_logfile 2048-byte buffer ({} bytes), data may be truncated",
543 line.len() + 38,
544 );
545 if let Some(ref mut pending) = self.pending {
546 pending.warnings.push(warning);
547 } else {
548 self.deferred_warning = Some(warning);
549 }
550 }
551
552 let bytes = line.as_bytes();
554 let min_scan = if is_uuid_at(bytes, 0) {
555 if bytes.len() > UUID_PREFIX_LEN && bytes[UUID_PREFIX_LEN].is_ascii_digit() {
556 64 } else {
558 UUID_PREFIX_LEN }
560 } else if is_date_at(bytes, 0) {
561 27 } else {
563 0
564 };
565
566 let end = bytes.len().saturating_sub(28);
567 let oversize = bytes.len() > MAX_LINE_PAYLOAD;
568
569 let mut splits: Vec<usize> = Vec::new();
589 let mut chunk_start = 0usize;
590 let mut offset = min_scan;
591 while offset <= end {
592 if is_log_header_at(bytes, offset) {
593 let split_at = if offset >= chunk_start + UUID_PREFIX_LEN
594 && is_uuid_at(bytes, offset - UUID_PREFIX_LEN)
595 {
596 offset - UUID_PREFIX_LEN
597 } else {
598 offset
599 };
600 if split_at > chunk_start {
601 splits.push(split_at);
602 chunk_start = split_at;
603 offset += 27;
604 } else {
605 offset = (offset + 27).max(offset + 1);
610 }
611 continue;
612 }
613 if oversize {
614 let boundary = chunk_start + MAX_LINE_PAYLOAD;
615 if offset + COLLISION_SCAN_SLACK >= boundary
616 && offset <= boundary + COLLISION_SCAN_SLACK
617 && is_uuid_at(bytes, offset)
618 {
619 splits.push(offset);
620 chunk_start = offset;
621 offset += UUID_PREFIX_LEN;
622 continue;
623 }
624 }
625 offset += 1;
626 }
627
628 if splits.is_empty() {
629 return line;
630 }
631
632 let mut tail = line;
635 let mut chunks: Vec<String> = Vec::with_capacity(splits.len());
636 for &at in splits.iter().rev() {
637 chunks.push(tail.split_off(at));
638 }
639 chunks.reverse();
640 self.split_pending.extend(chunks);
641 tail
642 }
643}
644
645impl<I: Iterator<Item = String>> Iterator for LogStream<I> {
646 type Item = LogEntry;
647
648 fn next(&mut self) -> Option<LogEntry> {
649 loop {
650 let line = if let Some(split) = self.split_pending.pop_front() {
651 self.stats.lines_split += 1;
652 split
656 } else {
657 let Some(line) = self.lines.next() else {
658 return self.finalize_pending();
659 };
660
661 if line.starts_with('\x00') {
662 let yielded = self.finalize_pending();
663 self.last_uuid.clear();
664 self.last_timestamp.clear();
665 if yielded.is_some() {
666 return yielded;
667 }
668 continue;
669 }
670
671 self.line_number += 1;
672 self.stats.lines_processed += 1;
673 self.detect_collision(line)
674 };
675
676 let parsed = parse_line(&line);
677
678 match parsed.kind {
679 LineKind::Full | LineKind::System | LineKind::Truncated => {
680 let uuid = parsed.uuid.unwrap_or("").to_string();
681 let message_kind = classify_message(parsed.message);
682
683 if let MessageKind::CodecNegotiation { media } = message_kind {
687 if let (
688 Some(ref pending),
689 StreamState::InCodecNegotiation {
690 media: open_media, ..
691 },
692 ) = (&self.pending, &self.state)
693 {
694 if uuid == pending.uuid && media == *open_media {
695 let warning = self.accumulate_codec_entry(parsed.message);
696 if let Some(ref mut p) = self.pending {
697 p.attached.push(&line);
698 p.warnings.extend(warning);
699 }
700 continue;
701 }
702 }
703 }
704
705 let yielded = self.finalize_pending();
706
707 let timestamp = parsed
708 .timestamp
709 .map(|t| t.to_string())
710 .unwrap_or_else(|| self.last_timestamp.clone());
711
712 if !uuid.is_empty() {
713 self.last_uuid = uuid.clone();
714 }
715 if parsed.timestamp.is_some() {
716 self.last_timestamp = timestamp.clone();
717 }
718
719 self.start_block_for_message(&message_kind);
720 let opening_warning =
724 if matches!(message_kind, MessageKind::CodecNegotiation { .. }) {
725 self.accumulate_codec_entry(parsed.message)
726 } else {
727 None
728 };
729
730 let mut entry = self.new_entry(
731 uuid,
732 timestamp,
733 parsed.message.to_string(),
734 parsed.kind,
735 message_kind,
736 );
737 entry.level = parsed.level;
738 entry.idle_pct = parsed.idle_pct.map(|s| s.to_string());
739 entry.source = parsed.source.map(|s| s.to_string());
740 entry.warnings.extend(opening_warning);
741 self.pending = Some(entry);
742
743 if yielded.is_some() {
744 return yielded;
745 }
746 }
747
748 LineKind::UuidContinuation => {
749 let uuid = parsed.uuid.unwrap_or("").to_string();
750 let is_primary = parsed.message.starts_with("EXECUTE ");
751
752 if let Some(ref pending) = self.pending {
753 if !is_primary && uuid == pending.uuid {
754 self.accumulate_continuation(parsed.message, &line);
755 } else {
756 let yielded = self.finalize_pending();
757 let message_kind = classify_message(parsed.message);
758
759 if !uuid.is_empty() {
760 self.last_uuid = uuid.clone();
761 }
762
763 self.start_block_for_message(&message_kind);
764 self.pending = Some(self.new_entry(
765 uuid,
766 self.last_timestamp.clone(),
767 parsed.message.to_string(),
768 parsed.kind,
769 message_kind,
770 ));
771
772 return yielded;
773 }
774 } else {
775 let message_kind = classify_message(parsed.message);
776
777 if !uuid.is_empty() {
778 self.last_uuid = uuid.clone();
779 }
780
781 self.start_block_for_message(&message_kind);
782 self.pending = Some(self.new_entry(
783 uuid,
784 self.last_timestamp.clone(),
785 parsed.message.to_string(),
786 parsed.kind,
787 message_kind,
788 ));
789 }
790 }
791
792 LineKind::BareContinuation => {
793 if self.pending.is_some() {
794 self.accumulate_continuation(parsed.message, &line);
795 } else {
796 self.record_unclassified(
797 UnclassifiedReason::OrphanContinuation,
798 Some(&line),
799 );
800 let message_kind = classify_message(parsed.message);
801 self.pending = Some(self.new_entry(
802 self.last_uuid.clone(),
803 self.last_timestamp.clone(),
804 parsed.message.to_string(),
805 parsed.kind,
806 message_kind,
807 ));
808 }
809 }
810
811 LineKind::Empty => {
812 if let Some(ref mut pending) = self.pending {
813 pending.attached.push(&line);
814 } else {
815 self.stats.lines_empty_orphan += 1;
816 }
817 }
818 }
819 }
820 }
821}
822
823#[cfg(test)]
824mod tests {
825 use super::*;
826
827 const UUID1: &str = "a1b2c3d4-e5f6-7890-abcd-ef1234567890";
828 const UUID2: &str = "b2c3d4e5-f6a7-8901-bcde-f12345678901";
829
830 fn full_line(uuid: &str, ts: &str, msg: &str) -> String {
831 format!("{uuid} {ts} 95.97% [DEBUG] sofia.c:100 {msg}")
832 }
833
834 const TS1: &str = "2025-01-15 10:30:45.123456";
835 const TS2: &str = "2025-01-15 10:30:46.234567";
836
837 #[test]
840 fn inherits_uuid_for_bare_continuation() {
841 let lines = vec![
842 full_line(UUID1, TS1, "CHANNEL_DATA:"),
843 "variable_foo: [bar]".to_string(),
844 "variable_baz: [qux]".to_string(),
845 ];
846 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
847 assert_eq!(entries.len(), 1);
848 assert_eq!(entries[0].uuid, UUID1);
849 assert_eq!(entries[0].attached.len(), 2);
850 assert_eq!(entries[0].attached.get(0), Some("variable_foo: [bar]"));
851 assert_eq!(entries[0].attached.get(1), Some("variable_baz: [qux]"));
852 }
853
854 #[test]
855 fn inherits_timestamp_for_uuid_continuation() {
856 let lines = vec![
857 full_line(UUID1, TS1, "First"),
858 format!("{UUID2} Channel-State: [CS_EXECUTE]"),
859 ];
860 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
861 assert_eq!(entries.len(), 2);
862 assert_eq!(entries[0].timestamp, TS1);
863 assert_eq!(entries[1].uuid, UUID2);
864 assert_eq!(entries[1].timestamp, TS1);
865 }
866
867 #[test]
868 fn new_full_line_yields_previous() {
869 let lines = vec![
870 full_line(UUID1, TS1, "First"),
871 full_line(UUID2, TS2, "Second"),
872 ];
873 let mut stream = LogStream::new(lines.into_iter());
874 let first = stream.next().unwrap();
875 assert_eq!(first.uuid, UUID1);
876 assert_eq!(first.message, "First");
877 let second = stream.next().unwrap();
878 assert_eq!(second.uuid, UUID2);
879 assert_eq!(second.message, "Second");
880 assert!(stream.next().is_none());
881 }
882
883 #[test]
884 fn channel_data_collected_as_attached() {
885 let lines = vec![
886 full_line(UUID1, TS1, "CHANNEL_DATA:"),
887 format!("{UUID1} Channel-Name: [sofia/internal/+15550001234@192.0.2.1]"),
888 format!("{UUID1} Unique-ID: [{UUID1}]"),
889 "variable_sip_call_id: [test123@192.0.2.1]".to_string(),
890 ];
891 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
892 assert_eq!(entries.len(), 1);
893 assert_eq!(entries[0].message, "CHANNEL_DATA:");
894 assert_eq!(entries[0].attached.len(), 3);
895 }
896
897 #[test]
898 fn sdp_body_collected_as_attached() {
899 let lines = vec![
900 full_line(UUID1, TS1, "Local SDP:"),
901 "v=0".to_string(),
902 "o=- 1234 5678 IN IP4 192.0.2.1".to_string(),
903 "s=-".to_string(),
904 "c=IN IP4 192.0.2.1".to_string(),
905 "m=audio 10000 RTP/AVP 0".to_string(),
906 ];
907 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
908 assert_eq!(entries.len(), 1);
909 assert_eq!(entries[0].attached.len(), 5);
910 }
911
912 #[test]
913 fn truncated_starts_new_entry() {
914 let lines = vec![
915 full_line(UUID1, TS1, "First"),
916 format!(
917 "varia{UUID2} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 set(x=y)"
918 ),
919 ];
920 let mut stream = LogStream::new(lines.into_iter());
921 let first = stream.next().unwrap();
922 assert_eq!(first.uuid, UUID1);
923 assert_eq!(first.message, "First");
924 let second = stream.next().unwrap();
925 assert_eq!(second.uuid, UUID2);
926 assert_eq!(second.kind, LineKind::Truncated);
927 }
928
929 #[test]
930 fn empty_lines_in_attached() {
931 let lines = vec![
932 full_line(UUID1, TS1, "First"),
933 String::new(),
934 "continuation".to_string(),
935 ];
936 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
937 assert_eq!(entries.len(), 1);
938 assert_eq!(entries[0].attached.len(), 2);
939 assert_eq!(entries[0].attached.get(0), Some(""));
940 assert_eq!(entries[0].attached.get(1), Some("continuation"));
941 }
942
943 #[test]
944 fn system_line_no_uuid() {
945 let lines = vec![format!(
946 "{TS1} 95.97% [INFO] mod_event_socket.c:1772 Event Socket command"
947 )];
948 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
949 assert_eq!(entries.len(), 1);
950 assert_eq!(entries[0].uuid, "");
951 assert_eq!(entries[0].kind, LineKind::System);
952 }
953
954 #[test]
955 fn final_entry_on_exhaustion() {
956 let lines = vec![full_line(UUID1, TS1, "Only entry")];
957 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
958 assert_eq!(entries.len(), 1);
959 assert_eq!(entries[0].message, "Only entry");
960 }
961
962 #[test]
963 fn consecutive_full_lines() {
964 let lines = vec![
965 full_line(UUID1, TS1, "First"),
966 full_line(UUID1, TS2, "Second"),
967 full_line(UUID2, TS1, "Third"),
968 ];
969 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
970 assert_eq!(entries.len(), 3);
971 for entry in &entries {
972 assert!(entry.attached.is_empty());
973 }
974 }
975
976 #[test]
977 fn execute_after_channel_data_same_uuid() {
978 let lines = vec![
979 full_line(UUID1, TS1, "CHANNEL_DATA:"),
980 format!("{UUID1} Channel-State: [CS_EXECUTE]"),
981 format!("{UUID1} variable_sip_call_id: [test@192.0.2.1]"),
982 "variable_foo: [bar]".to_string(),
983 String::new(),
984 String::new(),
985 format!("{UUID1} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 export(originate_timeout=3600)"),
986 full_line(UUID1, TS2, "EXPORT (export_vars) [originate_timeout]=[3600]"),
987 ];
988 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
989 assert_eq!(entries.len(), 3);
990 assert_eq!(entries[0].message, "CHANNEL_DATA:");
991 assert_eq!(entries[0].attached.len(), 5);
992 assert_eq!(entries[1].message, "EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 export(originate_timeout=3600)");
993 assert_eq!(entries[1].kind, LineKind::UuidContinuation);
994 assert_eq!(
995 entries[2].message,
996 "EXPORT (export_vars) [originate_timeout]=[3600]"
997 );
998 }
999
1000 #[test]
1001 fn execute_between_full_lines_same_uuid() {
1002 let lines = vec![
1003 full_line(UUID1, TS1, "CoreSession::setVariable(X-C911P-City, ST GEORGES)"),
1004 format!("{UUID1} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 db(insert/ng_{UUID1}/city/ST GEORGES)"),
1005 full_line(UUID1, TS2, "CoreSession::setVariable(X-C911P-Region, SGS)"),
1006 ];
1007 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1008 assert_eq!(entries.len(), 3);
1009 assert_eq!(
1010 entries[0].message,
1011 "CoreSession::setVariable(X-C911P-City, ST GEORGES)"
1012 );
1013 assert!(entries[0].attached.is_empty());
1014 assert!(entries[1].message.starts_with("EXECUTE "));
1015 assert_eq!(entries[1].kind, LineKind::UuidContinuation);
1016 assert_eq!(
1017 entries[2].message,
1018 "CoreSession::setVariable(X-C911P-Region, SGS)"
1019 );
1020 }
1021
1022 #[test]
1023 fn multiple_execute_between_full_lines() {
1024 let lines = vec![
1025 full_line(UUID1, TS1, "CoreSession::setVariable(ngcs_call_id, urn:emergency:uid:callid:test)"),
1026 format!("{UUID1} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 db(insert/ng_{UUID1}/call_id/urn:emergency:uid:callid:test)"),
1027 format!("{UUID1} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 db(insert/callid_codecs/urn:emergency:uid:callid:test/PCMU@8000h)"),
1028 full_line(UUID1, TS2, "CoreSession::setVariable(ngcs_short_call_id, test)"),
1029 ];
1030 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1031 assert_eq!(entries.len(), 4);
1032 assert!(entries[0].attached.is_empty());
1033 assert!(entries[1].message.contains("call_id"));
1034 assert!(entries[2].message.contains("callid_codecs"));
1035 assert_eq!(
1036 entries[3].message,
1037 "CoreSession::setVariable(ngcs_short_call_id, test)"
1038 );
1039 }
1040
1041 #[test]
1042 fn uuid_continuation_different_uuid_yields() {
1043 let lines = vec![
1044 full_line(UUID1, TS1, "First"),
1045 format!("{UUID1} Channel-State: [CS_EXECUTE]"),
1046 format!("{UUID2} Dialplan: sofia/internal/+15550001234@192.0.2.1 parsing [public]"),
1047 ];
1048 let mut stream = LogStream::new(lines.into_iter());
1049 let first = stream.next().unwrap();
1050 assert_eq!(first.uuid, UUID1);
1051 assert_eq!(first.attached.len(), 1);
1052 let second = stream.next().unwrap();
1053 assert_eq!(second.uuid, UUID2);
1054 assert_eq!(
1055 second.message,
1056 "Dialplan: sofia/internal/+15550001234@192.0.2.1 parsing [public]"
1057 );
1058 }
1059
1060 #[test]
1063 fn channel_data_block_fields_and_variables() {
1064 let lines = vec![
1065 full_line(UUID1, TS1, "CHANNEL_DATA:"),
1066 format!("{UUID1} Channel-Name: [sofia/internal/+15550001234@192.0.2.1]"),
1067 format!("{UUID1} Channel-State: [CS_EXECUTE]"),
1068 format!("{UUID1} Unique-ID: [{UUID1}]"),
1069 "variable_sip_call_id: [test123@192.0.2.1]".to_string(),
1070 "variable_direction: [inbound]".to_string(),
1071 ];
1072 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1073 assert_eq!(entries.len(), 1);
1074 assert_eq!(entries[0].message_kind, MessageKind::ChannelData);
1075 let block = entries[0].block.as_ref().expect("should have block");
1076 match block {
1077 Block::ChannelData { fields, variables } => {
1078 assert_eq!(fields.len(), 3);
1079 assert_eq!(
1080 fields[0],
1081 (
1082 "Channel-Name".to_string(),
1083 "sofia/internal/+15550001234@192.0.2.1".to_string()
1084 )
1085 );
1086 assert_eq!(
1087 fields[1],
1088 ("Channel-State".to_string(), "CS_EXECUTE".to_string())
1089 );
1090 assert_eq!(fields[2], ("Unique-ID".to_string(), UUID1.to_string()));
1091 assert_eq!(variables.len(), 2);
1092 assert_eq!(
1093 variables[0],
1094 (
1095 "variable_sip_call_id".to_string(),
1096 "test123@192.0.2.1".to_string()
1097 )
1098 );
1099 assert_eq!(
1100 variables[1],
1101 ("variable_direction".to_string(), "inbound".to_string())
1102 );
1103 }
1104 other => panic!("expected ChannelData block, got {other:?}"),
1105 }
1106 }
1107
1108 #[test]
1109 fn channel_data_multiline_variable_reassembly() {
1110 let lines = vec![
1111 full_line(UUID1, TS1, "CHANNEL_DATA:"),
1112 format!("{UUID1} Channel-Name: [sofia/internal/+15550001234@192.0.2.1]"),
1113 "variable_switch_r_sdp: [v=0".to_string(),
1114 "o=- 1234 5678 IN IP4 192.0.2.1".to_string(),
1115 "s=-".to_string(),
1116 "c=IN IP4 192.0.2.1".to_string(),
1117 "m=audio 47758 RTP/AVP 0 101".to_string(),
1118 "a=rtpmap:0 PCMU/8000".to_string(),
1119 "]".to_string(),
1120 "variable_direction: [inbound]".to_string(),
1121 ];
1122 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1123 assert_eq!(entries.len(), 1);
1124 let block = entries[0].block.as_ref().expect("should have block");
1125 match block {
1126 Block::ChannelData { fields, variables } => {
1127 assert_eq!(fields.len(), 1);
1128 assert_eq!(variables.len(), 2);
1129 assert_eq!(variables[0].0, "variable_switch_r_sdp");
1130 assert!(variables[0].1.starts_with("v=0\n"));
1131 assert!(variables[0].1.contains("m=audio 47758 RTP/AVP 0 101"));
1132 assert!(!variables[0].1.ends_with(']'));
1133 assert_eq!(
1134 variables[1],
1135 ("variable_direction".to_string(), "inbound".to_string())
1136 );
1137 }
1138 other => panic!("expected ChannelData block, got {other:?}"),
1139 }
1140 assert_eq!(entries[0].attached.len(), 9);
1141 }
1142
1143 #[test]
1144 fn sdp_block_detection() {
1145 let lines = vec![
1146 full_line(UUID1, TS1, "Local SDP:"),
1147 "v=0".to_string(),
1148 "o=- 1234 5678 IN IP4 192.0.2.1".to_string(),
1149 "s=-".to_string(),
1150 "c=IN IP4 192.0.2.1".to_string(),
1151 "m=audio 10000 RTP/AVP 0".to_string(),
1152 "a=rtpmap:0 PCMU/8000".to_string(),
1153 ];
1154 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1155 assert_eq!(entries.len(), 1);
1156 match &entries[0].message_kind {
1157 MessageKind::SdpMarker { direction } => assert_eq!(*direction, SdpDirection::Local),
1158 other => panic!("expected SdpMarker, got {other:?}"),
1159 }
1160 let block = entries[0].block.as_ref().expect("should have block");
1161 match block {
1162 Block::Sdp { direction, body } => {
1163 assert_eq!(*direction, SdpDirection::Local);
1164 assert_eq!(body.len(), 6);
1165 assert_eq!(body[0], "v=0");
1166 assert_eq!(body[5], "a=rtpmap:0 PCMU/8000");
1167 }
1168 other => panic!("expected Sdp block, got {other:?}"),
1169 }
1170 }
1171
1172 #[test]
1173 fn sdp_block_terminated_by_primary_line() {
1174 let lines = vec![
1175 full_line(UUID1, TS1, "Remote SDP:"),
1176 "v=0".to_string(),
1177 "m=audio 10000 RTP/AVP 0".to_string(),
1178 full_line(UUID1, TS2, "Next event"),
1179 ];
1180 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1181 assert_eq!(entries.len(), 2);
1182 let block = entries[0].block.as_ref().expect("should have block");
1183 match block {
1184 Block::Sdp { direction, body } => {
1185 assert_eq!(*direction, SdpDirection::Remote);
1186 assert_eq!(body.len(), 2);
1187 }
1188 other => panic!("expected Sdp block, got {other:?}"),
1189 }
1190 assert!(entries[1].block.is_none());
1191 }
1192
1193 #[test]
1194 fn sdp_from_uuid_continuation() {
1195 let lines = vec![
1196 format!("{UUID1} Local SDP:"),
1197 format!("{UUID1} v=0"),
1198 format!("{UUID1} o=FreeSWITCH 1234 5678 IN IP4 192.0.2.1"),
1199 format!("{UUID1} s=FreeSWITCH"),
1200 format!("{UUID1} c=IN IP4 192.0.2.1"),
1201 ];
1202 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1203 assert_eq!(entries.len(), 1);
1204 let block = entries[0].block.as_ref().expect("should have block");
1205 match block {
1206 Block::Sdp { direction, body } => {
1207 assert_eq!(*direction, SdpDirection::Local);
1208 assert_eq!(body.len(), 4);
1209 assert_eq!(body[0], "v=0");
1210 }
1211 other => panic!("expected Sdp block, got {other:?}"),
1212 }
1213 }
1214
1215 #[test]
1216 fn channel_data_interrupted_by_different_uuid() {
1217 let lines = vec![
1218 full_line(UUID1, TS1, "CHANNEL_DATA:"),
1219 format!("{UUID1} Channel-Name: [sofia/internal/+15550001234@192.0.2.1]"),
1220 format!("{UUID2} Dialplan: sofia/internal/+15559999999@192.0.2.1 parsing [public]"),
1221 ];
1222 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1223 assert_eq!(entries.len(), 2);
1224 let block = entries[0].block.as_ref().expect("should have block");
1225 match block {
1226 Block::ChannelData { fields, .. } => {
1227 assert_eq!(fields.len(), 1);
1228 }
1229 other => panic!("expected ChannelData, got {other:?}"),
1230 }
1231 }
1232
1233 #[test]
1234 fn no_block_for_non_block_message() {
1235 let lines = vec![full_line(UUID1, TS1, "some random freeswitch log message")];
1236 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1237 assert_eq!(entries.len(), 1);
1238 assert!(entries[0].block.is_none());
1239 assert_eq!(entries[0].message_kind, MessageKind::General);
1240 }
1241
1242 #[test]
1243 fn message_kind_on_execute() {
1244 let lines = vec![
1245 full_line(UUID1, TS1, "First"),
1246 format!("{UUID1} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 set(foo=bar)"),
1247 ];
1248 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1249 assert_eq!(entries.len(), 2);
1250 match &entries[1].message_kind {
1251 MessageKind::Execute {
1252 application,
1253 arguments,
1254 ..
1255 } => {
1256 assert_eq!(application, "set");
1257 assert_eq!(arguments, "foo=bar");
1258 }
1259 other => panic!("expected Execute, got {other:?}"),
1260 }
1261 }
1262
1263 #[test]
1266 fn stats_lines_processed() {
1267 let lines = vec![
1268 full_line(UUID1, TS1, "First"),
1269 full_line(UUID1, TS2, "Second"),
1270 format!("{UUID1} Channel-State: [CS_EXECUTE]"),
1271 ];
1272 let mut stream = LogStream::new(lines.into_iter());
1273 let _: Vec<_> = stream.by_ref().collect();
1274 assert_eq!(stream.stats().lines_processed, 3);
1275 }
1276
1277 #[test]
1278 fn stats_unclassified_orphan() {
1279 let lines = vec![
1280 "variable_foo: [bar]".to_string(),
1281 full_line(UUID1, TS1, "After orphan"),
1282 ];
1283 let mut stream = LogStream::new(lines.into_iter())
1284 .unclassified_tracking(UnclassifiedTracking::TrackLines);
1285 let _: Vec<_> = stream.by_ref().collect();
1286 assert_eq!(stream.stats().lines_unclassified, 1);
1287 assert_eq!(stream.stats().unclassified_lines.len(), 1);
1288 assert_eq!(
1289 stream.stats().unclassified_lines[0].reason,
1290 UnclassifiedReason::OrphanContinuation,
1291 );
1292 }
1293
1294 #[test]
1295 fn stats_capture_data() {
1296 let lines = vec!["orphan line".to_string(), full_line(UUID1, TS1, "After")];
1297 let mut stream = LogStream::new(lines.into_iter())
1298 .unclassified_tracking(UnclassifiedTracking::CaptureData);
1299 let _: Vec<_> = stream.by_ref().collect();
1300 assert_eq!(stream.stats().unclassified_lines.len(), 1);
1301 assert_eq!(
1302 stream.stats().unclassified_lines[0].data.as_deref(),
1303 Some("orphan line"),
1304 );
1305 }
1306
1307 #[test]
1308 fn stats_count_only_no_allocation() {
1309 let lines = vec!["orphan line".to_string(), full_line(UUID1, TS1, "After")];
1310 let mut stream = LogStream::new(lines.into_iter());
1311 let _: Vec<_> = stream.by_ref().collect();
1312 assert_eq!(stream.stats().lines_unclassified, 1);
1313 assert!(stream.stats().unclassified_lines.is_empty());
1314 }
1315
1316 #[test]
1317 fn line_number_tracking() {
1318 let lines = vec![
1319 full_line(UUID1, TS1, "First"),
1320 format!("{UUID1} Channel-State: [CS_EXECUTE]"),
1321 full_line(UUID2, TS2, "Third"),
1322 ];
1323 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1324 assert_eq!(entries[0].line_number, 1);
1325 assert_eq!(entries[1].line_number, 3);
1326 }
1327
1328 #[test]
1329 fn drain_unclassified() {
1330 let lines = vec![
1331 "orphan1".to_string(),
1332 "orphan2".to_string(),
1333 full_line(UUID1, TS1, "After"),
1334 ];
1335 let mut stream = LogStream::new(lines.into_iter())
1336 .unclassified_tracking(UnclassifiedTracking::TrackLines);
1337 let _: Vec<_> = stream.by_ref().collect();
1338 let drained = stream.drain_unclassified();
1339 assert_eq!(drained.len(), 1);
1340 assert!(stream.stats().unclassified_lines.is_empty());
1341 assert_eq!(stream.stats().lines_unclassified, 1);
1342 }
1343
1344 #[test]
1352 fn continuation_lines_at_file_boundary_must_not_inherit_previous_timestamp() {
1353 use crate::TrackedChain;
1354
1355 let uuid_a = "aaaaaaaa-1111-2222-3333-444444444444";
1356 let uuid_b = "bbbbbbbb-1111-2222-3333-444444444444";
1357 let ts_old = "2025-01-15 23:58:03.000000";
1358 let ts_new = "2025-01-16 08:37:12.000000";
1359
1360 let seg1: Vec<String> = vec![format!(
1361 "{uuid_a} {ts_old} 95.00% [DEBUG] test.c:1 Last line in rotated file"
1362 )];
1363
1364 let seg2: Vec<String> = vec![
1367 format!("{uuid_b} CHANNEL_DATA:"),
1368 format!("{uuid_b} Channel-State: [CS_EXECUTE]"),
1369 format!("{uuid_b} {ts_new} 95.00% [DEBUG] test.c:1 First timestamped line in new file"),
1370 ];
1371
1372 let segments: Vec<(String, Box<dyn Iterator<Item = String>>)> = vec![
1373 ("rotated.log".to_string(), Box::new(seg1.into_iter())),
1374 ("freeswitch.log".to_string(), Box::new(seg2.into_iter())),
1375 ];
1376
1377 let (chain, _) = TrackedChain::new(segments);
1378 let entries: Vec<_> = LogStream::new(chain).collect();
1379
1380 let b_entry = entries
1381 .iter()
1382 .find(|e| e.uuid == uuid_b)
1383 .expect("should find entry for uuid_b");
1384
1385 assert_ne!(
1389 b_entry.timestamp, ts_old,
1390 "continuation lines in a new file segment inherited timestamp \
1391 '{ts_old}' from the previous segment — timestamps must not bleed \
1392 across file boundaries"
1393 );
1394 }
1395
1396 fn assert_accounting(stream: &LogStream<impl Iterator<Item = String>>) {
1399 let stats = stream.stats();
1400 assert_eq!(
1401 stats.unaccounted_lines(),
1402 0,
1403 "line accounting invariant violated: \
1404 processed={} + split={} != in_entries={} + empty_orphan={}",
1405 stats.lines_processed,
1406 stats.lines_split,
1407 stats.lines_in_entries,
1408 stats.lines_empty_orphan,
1409 );
1410 }
1411
1412 #[test]
1413 fn accounting_full_lines() {
1414 let lines = vec![
1415 full_line(UUID1, TS1, "First"),
1416 full_line(UUID2, TS2, "Second"),
1417 ];
1418 let mut stream = LogStream::new(lines.into_iter());
1419 let entries: Vec<_> = stream.by_ref().collect();
1420 assert_eq!(entries.len(), 2);
1421 assert_eq!(stream.stats().lines_in_entries, 2);
1422 assert_accounting(&stream);
1423 }
1424
1425 #[test]
1426 fn accounting_with_attached() {
1427 let lines = vec![
1428 full_line(UUID1, TS1, "CHANNEL_DATA:"),
1429 format!("{UUID1} Channel-State: [CS_EXECUTE]"),
1430 "variable_foo: [bar]".to_string(),
1431 full_line(UUID2, TS2, "Next"),
1432 ];
1433 let mut stream = LogStream::new(lines.into_iter());
1434 let entries: Vec<_> = stream.by_ref().collect();
1435 assert_eq!(entries.len(), 2);
1436 assert_eq!(stream.stats().lines_in_entries, 4);
1439 assert_accounting(&stream);
1440 }
1441
1442 #[test]
1443 fn accounting_system_line() {
1444 let lines = vec![format!(
1445 "{TS1} 95.97% [NOTICE] mod_logfile.c:217 New log started."
1446 )];
1447 let mut stream = LogStream::new(lines.into_iter());
1448 let _: Vec<_> = stream.by_ref().collect();
1449 assert_eq!(stream.stats().lines_in_entries, 1);
1450 assert_accounting(&stream);
1451 }
1452
1453 #[test]
1454 fn accounting_empty_orphan() {
1455 let lines = vec![
1456 String::new(),
1457 " ".to_string(),
1458 full_line(UUID1, TS1, "After"),
1459 ];
1460 let mut stream = LogStream::new(lines.into_iter());
1461 let entries: Vec<_> = stream.by_ref().collect();
1462 assert_eq!(entries.len(), 1);
1463 assert_eq!(stream.stats().lines_empty_orphan, 2);
1464 assert_accounting(&stream);
1465 }
1466
1467 #[test]
1468 fn accounting_empty_attached() {
1469 let lines = vec![
1470 full_line(UUID1, TS1, "First"),
1471 String::new(),
1472 "continuation".to_string(),
1473 ];
1474 let mut stream = LogStream::new(lines.into_iter());
1475 let entries: Vec<_> = stream.by_ref().collect();
1476 assert_eq!(entries.len(), 1);
1477 assert_eq!(entries[0].attached.len(), 2);
1478 assert_eq!(stream.stats().lines_empty_orphan, 0);
1479 assert_eq!(stream.stats().lines_in_entries, 3);
1480 assert_accounting(&stream);
1481 }
1482
1483 #[test]
1484 fn accounting_orphan_continuation() {
1485 let lines = vec!["orphan line".to_string(), full_line(UUID1, TS1, "After")];
1486 let mut stream = LogStream::new(lines.into_iter());
1487 let _: Vec<_> = stream.by_ref().collect();
1488 assert_accounting(&stream);
1489 }
1490
1491 #[test]
1492 fn accounting_codec_merging() {
1493 let lines = vec![
1494 full_line(
1495 UUID1,
1496 TS1,
1497 "Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]",
1498 ),
1499 full_line(
1500 UUID1,
1501 TS1,
1502 "Audio Codec Compare [PCMU:0:8000:20:64000:1] is saved as a match",
1503 ),
1504 full_line(UUID2, TS2, "Next"),
1505 ];
1506 let mut stream = LogStream::new(lines.into_iter());
1507 let _: Vec<_> = stream.by_ref().collect();
1508 assert_accounting(&stream);
1509 }
1510
1511 #[test]
1512 fn accounting_truncated_line() {
1513 let lines = vec![
1514 full_line(UUID1, TS1, "First"),
1515 format!(
1516 "varia{UUID2} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 set(x=y)"
1517 ),
1518 ];
1519 let mut stream = LogStream::new(lines.into_iter());
1520 let _: Vec<_> = stream.by_ref().collect();
1521 assert_accounting(&stream);
1522 }
1523
1524 #[test]
1525 fn accounting_long_line_collision_split() {
1526 let long_value = "x".repeat(MAX_LINE_PAYLOAD + 10);
1529 let line = format!(
1530 "variable_sip_multipart: [{long_value}]{UUID2} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 set(foo=bar)"
1531 );
1532 let lines = vec![full_line(UUID1, TS1, "CHANNEL_DATA:"), line];
1533 let mut stream = LogStream::new(lines.into_iter());
1534 let entries: Vec<_> = stream.by_ref().collect();
1535
1536 assert_eq!(entries[0].message, "CHANNEL_DATA:");
1538
1539 let split_entry = entries.iter().find(|e| e.uuid == UUID2);
1541 assert!(
1542 split_entry.is_some(),
1543 "collision UUID should produce a separate entry"
1544 );
1545
1546 assert_eq!(stream.stats().lines_split, 1);
1547 assert_accounting(&stream);
1548 }
1549
1550 #[test]
1551 fn no_split_on_short_lines() {
1552 let line = format!("variable_call_uuid: [{UUID2}]");
1555 let lines = vec![full_line(UUID1, TS1, "CHANNEL_DATA:"), line];
1556 let mut stream = LogStream::new(lines.into_iter());
1557 let entries: Vec<_> = stream.by_ref().collect();
1558 assert_eq!(entries.len(), 1);
1559 assert_eq!(stream.stats().lines_split, 0);
1560 assert_accounting(&stream);
1561 }
1562
1563 #[test]
1564 fn timestamp_collision_splits_system_lines() {
1565 let line = format!(
1566 "{TS1} 98.03% [INFO] mod_event_socket.c:1752 Event Socket Command from ::1:42864: api sofia jsonstatus{TS2} 97.93% [INFO] mod_event_socket.c:1752 Event Socket Command from ::1:42898: api fsctl pause_check"
1567 );
1568 let mut stream = LogStream::new(std::iter::once(line));
1569 let entries: Vec<_> = stream.by_ref().collect();
1570 assert_eq!(entries.len(), 2);
1571 assert_eq!(
1572 entries[0].message,
1573 "Event Socket Command from ::1:42864: api sofia jsonstatus"
1574 );
1575 assert_eq!(
1576 entries[1].message,
1577 "Event Socket Command from ::1:42898: api fsctl pause_check"
1578 );
1579 assert_eq!(stream.stats().lines_split, 1);
1580 assert_accounting(&stream);
1581 }
1582
1583 #[test]
1584 fn timestamp_collision_splits_three_entries() {
1585 let ts3 = "2025-01-15 10:30:47.345678";
1586 let line = format!(
1587 "{TS1} 95.00% [INFO] mod.c:1 first{TS2} 96.00% [INFO] mod.c:1 second{ts3} 97.00% [INFO] mod.c:1 third"
1588 );
1589 let mut stream = LogStream::new(std::iter::once(line));
1590 let entries: Vec<_> = stream.by_ref().collect();
1591 assert_eq!(entries.len(), 3);
1592 assert_eq!(entries[0].message, "first");
1593 assert_eq!(entries[1].message, "second");
1594 assert_eq!(entries[2].message, "third");
1595 assert_eq!(stream.stats().lines_split, 2);
1596 assert_accounting(&stream);
1597 }
1598
1599 #[test]
1600 fn timestamp_collision_oversize_write_contention() {
1601 let entry = |n: usize| {
1607 format!(
1608 "{TS1} 98.77% [INFO] mod_event_socket.c:1754 Event Socket Command from ::1:42864: api db select/ngcs_sip_call_id/entry-{n:04}"
1609 )
1610 };
1611 let count: u64 = 20;
1612 let line: String = (0..count).map(|n| entry(n as usize)).collect();
1613 assert!(
1614 line.len() > super::MAX_LINE_PAYLOAD,
1615 "test fixture should exceed MAX_LINE_PAYLOAD, got {}",
1616 line.len()
1617 );
1618
1619 let mut stream = LogStream::new(std::iter::once(line));
1620 let entries: Vec<_> = stream.by_ref().collect();
1621 assert_eq!(entries.len() as u64, count);
1622 for (i, e) in entries.iter().enumerate() {
1623 assert_eq!(
1624 e.message,
1625 format!(
1626 "Event Socket Command from ::1:42864: api db select/ngcs_sip_call_id/entry-{i:04}"
1627 )
1628 );
1629 }
1630 assert_eq!(stream.stats().lines_split, count - 1);
1631 assert_accounting(&stream);
1632 }
1633
1634 #[test]
1635 fn timestamp_collision_with_uuid_prefix() {
1636 let line = format!(
1638 "{TS1} 95.00% [INFO] mod.c:1 first{UUID1} {TS2} 96.00% [DEBUG] sofia.c:100 second"
1639 );
1640 let mut stream = LogStream::new(std::iter::once(line));
1641 let entries: Vec<_> = stream.by_ref().collect();
1642 assert_eq!(entries.len(), 2);
1643 assert_eq!(entries[0].message, "first");
1644 assert_eq!(entries[1].uuid, UUID1);
1645 assert_eq!(entries[1].message, "second");
1646 assert_eq!(stream.stats().lines_split, 1);
1647 assert_accounting(&stream);
1648 }
1649
1650 #[test]
1654 fn timestamp_collision_no_idle_pct_system() {
1655 let line = format!(
1656 "{TS1} [WARNING] sofia_presence.c:4546 Session does not exist, aborting REFER.{TS2} [WARNING] sofia_presence.c:4546 Session does not exist, aborting REFER."
1657 );
1658 let mut stream = LogStream::new(std::iter::once(line));
1659 let entries: Vec<_> = stream.by_ref().collect();
1660 assert_eq!(entries.len(), 2);
1661 assert_eq!(
1662 entries[0].message,
1663 "Session does not exist, aborting REFER."
1664 );
1665 assert_eq!(
1666 entries[1].message,
1667 "Session does not exist, aborting REFER."
1668 );
1669 assert_eq!(stream.stats().lines_split, 1);
1670 assert_accounting(&stream);
1671 }
1672
1673 #[test]
1674 fn timestamp_collision_no_idle_pct_uuid_suffix() {
1675 let line = format!(
1678 "{TS1} [WARNING] sofia_presence.c:4546 Session does not exist, aborting REFER.{UUID1} {TS2} [NOTICE] sofia.c:1114 Hangup sofia/internal/sos@192.0.2.10:5080 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]"
1679 );
1680 let mut stream = LogStream::new(std::iter::once(line));
1681 let entries: Vec<_> = stream.by_ref().collect();
1682 assert_eq!(entries.len(), 2);
1683 assert_eq!(entries[0].uuid, "");
1684 assert_eq!(
1685 entries[0].message,
1686 "Session does not exist, aborting REFER."
1687 );
1688 assert_eq!(entries[1].uuid, UUID1);
1689 assert_eq!(entries[1].level, Some(LogLevel::Notice));
1690 assert_eq!(
1691 entries[1].message,
1692 "Hangup sofia/internal/sos@192.0.2.10:5080 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING]"
1693 );
1694 assert_eq!(stream.stats().lines_split, 1);
1695 assert_accounting(&stream);
1696 }
1697
1698 #[test]
1699 fn timestamp_collision_no_idle_pct_run_on() {
1700 let count: u64 = 15;
1702 let line: String = (0..count)
1703 .map(|n| {
1704 format!(
1705 "2024-04-02 10:31:{:02}.945614 [WARNING] sofia_presence.c:4546 Session does not exist, aborting REFER.",
1706 n + 10
1707 )
1708 })
1709 .collect();
1710 let mut stream = LogStream::new(std::iter::once(line));
1711 let entries: Vec<_> = stream.by_ref().collect();
1712 assert_eq!(entries.len() as u64, count);
1713 for e in &entries {
1714 assert_eq!(e.message, "Session does not exist, aborting REFER.");
1715 }
1716 assert_eq!(stream.stats().lines_split, count - 1);
1717 assert_accounting(&stream);
1718 }
1719
1720 #[test]
1721 fn channel_data_multiline_variable_spans_many_lines() {
1722 let lines = vec![
1723 full_line(UUID1, TS1, "CHANNEL_DATA:"),
1724 format!("{UUID1} Channel-Name: [sofia/internal/+15550001234@192.0.2.1]"),
1725 "variable_switch_r_sdp: [v=0".to_string(),
1726 "o=- 1234 5678 IN IP4 192.0.2.1".to_string(),
1727 "s=-".to_string(),
1728 "c=IN IP4 192.0.2.1".to_string(),
1729 "t=0 0".to_string(),
1730 "m=audio 47758 RTP/AVP 0 8 101".to_string(),
1731 "a=rtpmap:0 PCMU/8000".to_string(),
1732 "a=rtpmap:8 PCMA/8000".to_string(),
1733 "a=rtpmap:101 telephone-event/8000".to_string(),
1734 "a=fmtp:101 0-16".to_string(),
1735 "]".to_string(),
1736 "variable_direction: [inbound]".to_string(),
1737 ];
1738 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1739 assert_eq!(entries.len(), 1);
1740 let block = entries[0].block.as_ref().expect("should have block");
1741 match block {
1742 Block::ChannelData { fields, variables } => {
1743 assert_eq!(fields.len(), 1);
1744 assert_eq!(variables.len(), 2);
1745 assert_eq!(variables[0].0, "variable_switch_r_sdp");
1746 let sdp = &variables[0].1;
1747 assert!(sdp.starts_with("v=0\n"));
1748 assert!(sdp.contains("a=fmtp:101 0-16"));
1749 assert!(!sdp.ends_with(']'));
1750 assert_eq!(variables[1].0, "variable_direction");
1751 }
1752 other => panic!("expected ChannelData block, got {other:?}"),
1753 }
1754 }
1755
1756 #[test]
1757 fn sdp_from_verto_update_media() {
1758 let lines = vec![
1759 full_line(UUID1, TS1, "updateMedia: Local SDP"),
1760 "v=0".to_string(),
1761 "o=- 1234 5678 IN IP4 192.0.2.1".to_string(),
1762 "m=audio 10000 RTP/AVP 0".to_string(),
1763 ];
1764 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1765 assert_eq!(entries.len(), 1);
1766 match &entries[0].message_kind {
1767 MessageKind::SdpMarker { direction } => assert_eq!(*direction, SdpDirection::Local),
1768 other => panic!("expected SdpMarker, got {other:?}"),
1769 }
1770 let block = entries[0].block.as_ref().expect("should have block");
1771 match block {
1772 Block::Sdp { direction, body } => {
1773 assert_eq!(*direction, SdpDirection::Local);
1774 assert_eq!(body.len(), 3);
1775 }
1776 other => panic!("expected Sdp block, got {other:?}"),
1777 }
1778 }
1779
1780 #[test]
1781 fn duplicate_sdp_marker() {
1782 let lines = vec![
1783 full_line(UUID1, TS1, "Duplicate SDP"),
1784 "v=0".to_string(),
1785 "m=audio 10000 RTP/AVP 0".to_string(),
1786 ];
1787 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1788 assert_eq!(entries.len(), 1);
1789 match &entries[0].message_kind {
1790 MessageKind::SdpMarker { direction } => assert_eq!(*direction, SdpDirection::Unknown),
1791 other => panic!("expected SdpMarker, got {other:?}"),
1792 }
1793 assert!(entries[0].block.is_some());
1794 }
1795
1796 #[test]
1797 fn warning_on_unclosed_multiline_variable() {
1798 let lines = vec![
1799 full_line(UUID1, TS1, "CHANNEL_DATA:"),
1800 "variable_switch_r_sdp: [v=0".to_string(),
1801 "o=- 1234 5678 IN IP4 192.0.2.1".to_string(),
1802 full_line(UUID2, TS2, "Next entry"),
1803 ];
1804 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1805 assert_eq!(entries.len(), 2);
1806 assert!(
1807 entries[0]
1808 .warnings
1809 .iter()
1810 .any(|w| w.contains("unclosed multi-line variable")),
1811 "expected unclosed variable warning, got: {:?}",
1812 entries[0].warnings
1813 );
1814 }
1815
1816 #[test]
1817 fn warning_on_unparseable_channel_data_line() {
1818 let lines = vec![
1819 full_line(UUID1, TS1, "CHANNEL_DATA:"),
1820 format!("{UUID1} Channel-Name: [sofia/internal/+15550001234@192.0.2.1]"),
1821 format!("{UUID1} this is not a valid field line"),
1822 ];
1823 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1824 assert_eq!(entries.len(), 1);
1825 assert!(
1826 entries[0]
1827 .warnings
1828 .iter()
1829 .any(|w| w.contains("unparseable CHANNEL_DATA")),
1830 "expected unparseable warning, got: {:?}",
1831 entries[0].warnings
1832 );
1833 }
1834
1835 #[test]
1836 fn warning_on_unexpected_codec_continuation() {
1837 let lines = vec![
1838 full_line(
1839 UUID1,
1840 TS1,
1841 "Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]",
1842 ),
1843 format!("{UUID1} some unexpected continuation line"),
1844 ];
1845 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1846 assert_eq!(entries.len(), 1);
1847 assert!(
1848 entries[0]
1849 .warnings
1850 .iter()
1851 .any(|w| w.contains("unexpected codec negotiation")),
1852 "expected codec warning, got: {:?}",
1853 entries[0].warnings
1854 );
1855 }
1856
1857 fn codec_block(entry: &LogEntry) -> (&CodecMedia, &Vec<CodecOffer>, &Vec<CodecOffer>) {
1858 match &entry.block {
1859 Some(Block::CodecNegotiation {
1860 media,
1861 matched,
1862 near_matched,
1863 ..
1864 }) => (media, matched, near_matched),
1865 other => panic!("expected a codec block, got {other:?}"),
1866 }
1867 }
1868
1869 #[cfg(feature = "sdp")]
1870 #[test]
1871 fn sdp_body_parses_into_typed_codecs() {
1872 let lines = vec![
1875 full_line(UUID1, TS1, "Remote SDP:"),
1876 format!("{UUID1} v=0\r"),
1877 format!("{UUID1} o=FreeSWITCH 1 1 IN IP4 192.0.2.10\r"),
1878 format!("{UUID1} s=FreeSWITCH\r"),
1879 format!("{UUID1} c=IN IP4 192.0.2.10\r"),
1880 format!("{UUID1} t=0 0\r"),
1881 format!("{UUID1} m=audio 9938 RTP/AVP 102 101\r"),
1882 format!("{UUID1} a=rtpmap:102 opus/48000/2\r"),
1883 format!("{UUID1} a=rtpmap:101 telephone-event/48000\r"),
1884 format!("{UUID1} a=ptime:20\r"),
1885 full_line(UUID2, TS2, "Next"),
1886 ];
1887 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1888 let codecs = entries[0]
1889 .block
1890 .as_ref()
1891 .expect("sdp block")
1892 .sdp_codecs()
1893 .expect("an sdp block yields Some")
1894 .expect("body parses");
1895
1896 let audio: Vec<&str> = codecs.audio().map(|c| c.name()).collect();
1897 assert_eq!(audio, ["opus"], "telephone-event is surfaced separately");
1898 assert_eq!(codecs.telephone_event_rates(), [48000]);
1899 let opus = codecs.audio().next().unwrap();
1900 assert_eq!(opus.payload_type(), 102);
1901 assert_eq!(opus.clock_rate(), 48000);
1902 assert_eq!(opus.channels(), Some(2));
1903 assert_eq!(opus.ptime(), Some(20));
1904 }
1905
1906 #[cfg(feature = "sdp")]
1907 #[test]
1908 fn only_sdp_blocks_yield_codecs() {
1909 let lines = vec![
1910 full_line(
1911 UUID1,
1912 TS1,
1913 "Audio Codec Compare [opus:116:16000:20:0:1]/[opus:116:16000:20:0:1]",
1914 ),
1915 full_line(UUID2, TS2, "Next"),
1916 ];
1917 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1918 assert!(entries[0].block.as_ref().unwrap().sdp_codecs().is_none());
1919 }
1920
1921 #[test]
1922 fn video_negotiation_has_its_own_arity() {
1923 let lines = vec![
1924 full_line(UUID1, TS1, "Video Codec Compare [H263:34]/[H264:97]"),
1925 full_line(
1926 UUID1,
1927 TS1,
1928 "Video Codec Compare [H263:34] +++ is saved as a match",
1929 ),
1930 full_line(UUID2, TS2, "Next"),
1931 ];
1932 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1933 let (media, matched, _) = codec_block(&entries[0]);
1934 assert_eq!(*media, CodecMedia::Video);
1935 assert_eq!(matched.len(), 1);
1936 assert_eq!(matched[0].name, "H263");
1937 assert_eq!(matched[0].payload_type, 34);
1938 assert_eq!(matched[0].clock_rate, None);
1939 assert!(entries[0].warnings.is_empty(), "{:?}", entries[0].warnings);
1940 }
1941
1942 #[test]
1943 fn audio_and_video_runs_do_not_merge() {
1944 let lines = vec![
1945 full_line(
1946 UUID1,
1947 TS1,
1948 "Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]",
1949 ),
1950 full_line(UUID1, TS1, "Video Codec Compare [H263:34]/[H264:97]"),
1951 full_line(UUID2, TS2, "Next"),
1952 ];
1953 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1954 assert_eq!(entries.len(), 3, "same UUID, different media, two blocks");
1955 assert_eq!(*codec_block(&entries[0]).0, CodecMedia::Audio);
1956 assert_eq!(*codec_block(&entries[1]).0, CodecMedia::Video);
1957 }
1958
1959 #[test]
1960 fn near_match_verdicts_are_data_not_warnings() {
1961 let lines = vec![
1962 full_line(
1963 UUID1,
1964 TS1,
1965 "Audio Codec Compare [opus:116:48000:20:0:1]/[opus:116:48000:20:0:1]",
1966 ),
1967 full_line(
1968 UUID1,
1969 TS1,
1970 "Audio Codec Compare [opus:116:48000:20:0:1] is saved as a near-match",
1971 ),
1972 full_line(
1974 UUID1,
1975 TS1,
1976 "Audio Codec Compare [PCMU:0:8000:8000:20:64000:1] was not saved as a near-match. Too many. Ignoring.",
1977 ),
1978 full_line(UUID2, TS2, "Next"),
1979 ];
1980 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1981 let (_, matched, near_matched) = codec_block(&entries[0]);
1982 assert!(matched.is_empty());
1983 assert_eq!(near_matched.len(), 1, "the dropped one is not kept");
1984 assert_eq!(near_matched[0].name, "opus");
1985 assert!(entries[0].warnings.is_empty(), "{:?}", entries[0].warnings);
1986 }
1987
1988 #[test]
1989 fn a_malformed_codec_token_still_warns() {
1990 let lines = vec![
1991 full_line(
1992 UUID1,
1993 TS1,
1994 "Audio Codec Compare [PCMU:0:8000:20:64000:1]/[nope]",
1995 ),
1996 full_line(UUID2, TS2, "Next"),
1997 ];
1998 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
1999 assert!(
2000 entries[0]
2001 .warnings
2002 .iter()
2003 .any(|w| w.contains("unrecognized codec negotiation")),
2004 "got: {:?}",
2005 entries[0].warnings
2006 );
2007 }
2008
2009 #[test]
2010 fn system_line_uuid_continuation_not_absorbed() {
2011 let lines = vec![
2014 format!("{TS1} 95.97% [INFO] mod_event_socket.c:1772 Event Socket command"),
2015 format!("{UUID1} Channel-State: [CS_EXECUTE]"),
2016 ];
2017 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
2018 assert_eq!(
2019 entries.len(),
2020 2,
2021 "UUID continuation should not be absorbed by system entry"
2022 );
2023 assert_eq!(entries[0].uuid, "");
2024 assert_eq!(entries[1].uuid, UUID1);
2025 }
2026
2027 #[test]
2028 fn truncated_collision_in_channel_data_variable() {
2029 let padding = "x".repeat(2000);
2035 let collision_line = format!(
2036 "{UUID1} variable_long_xml: [{padding}{UUID1} EXECUTE [depth=0] sofia/internal/+15550001234@192.0.2.1 export(foo=bar)"
2037 );
2038 assert!(
2039 collision_line.len() > super::MAX_LINE_PAYLOAD,
2040 "test line must exceed buffer limit, got {}",
2041 collision_line.len()
2042 );
2043
2044 let lines = vec![
2045 full_line(UUID1, TS1, "CHANNEL_DATA:"),
2046 format!("{UUID1} Channel-Name: [sofia/internal/+15550001234@192.0.2.1]"),
2047 format!("{UUID1} variable_direction: [inbound]"),
2048 collision_line,
2049 full_line(UUID1, TS2, "Next log entry"),
2050 ];
2051
2052 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
2053
2054 assert_eq!(entries[0].message, "CHANNEL_DATA:");
2056 let block = entries[0].block.as_ref().expect("should have block");
2057 match block {
2058 Block::ChannelData { fields, variables } => {
2059 assert_eq!(fields.len(), 1, "should have Channel-Name field");
2060 assert_eq!(fields[0].0, "Channel-Name");
2061 assert_eq!(
2062 variables.len(),
2063 2,
2064 "should have direction + unclosed long_xml"
2065 );
2066 assert_eq!(variables[0].0, "variable_direction");
2067 assert_eq!(variables[0].1, "inbound");
2068 assert_eq!(variables[1].0, "variable_long_xml");
2069 }
2070 other => panic!("expected ChannelData block, got {other:?}"),
2071 }
2072 assert!(
2073 entries[0]
2074 .warnings
2075 .iter()
2076 .any(|w| w.contains("line exceeds mod_logfile 2048-byte buffer")),
2077 "expected buffer overflow warning, got: {:?}",
2078 entries[0].warnings
2079 );
2080 assert!(
2081 entries[0]
2082 .warnings
2083 .iter()
2084 .any(|w| w.contains("unclosed multi-line variable")),
2085 "expected unclosed variable warning, got: {:?}",
2086 entries[0].warnings
2087 );
2088
2089 assert_eq!(entries[1].uuid, UUID1);
2091 assert!(
2092 entries[1].message.starts_with("EXECUTE "),
2093 "split entry should be EXECUTE, got: {}",
2094 entries[1].message
2095 );
2096
2097 assert_eq!(entries.len(), 3);
2099 assert_eq!(entries[2].message, "Next log entry");
2100 }
2101
2102 #[test]
2103 fn channel_data_uuid_drops_mid_block() {
2104 let lines = vec![
2109 full_line(UUID1, TS1, "CHANNEL_DATA:"),
2110 format!("{UUID1} variable_max_forwards: [69]"),
2111 format!("{UUID1} variable_presence_id: [1251@[2001:db8::10]]"),
2112 format!("{UUID1} variable_sip_h_X-Custom-ID: [c4da84eb-88a7-40b2-b90d-e5bc2a0f634e]"),
2113 "variable_sip_h_X-Call-Info: [<urn:test:callid:20260316>;purpose=emergency-CallId]"
2115 .to_string(),
2116 "variable_ep_codec_string: [mod_opus.opus@48000h@20i@2c]".to_string(),
2117 "variable_remote_media_ip: [2001:db8::10]".to_string(),
2118 "variable_remote_media_port: [9952]".to_string(),
2119 "variable_rtp_use_codec_name: [opus]".to_string(),
2120 full_line(UUID1, TS2, "Next entry"),
2121 ];
2122
2123 let mut stream = LogStream::new(lines.into_iter());
2124 let entries: Vec<_> = stream.by_ref().collect();
2125
2126 assert_eq!(entries.len(), 2);
2127 assert_eq!(entries[0].message, "CHANNEL_DATA:");
2128 let block = entries[0].block.as_ref().expect("should have block");
2129 match block {
2130 Block::ChannelData { fields, variables } => {
2131 assert_eq!(fields.len(), 0);
2132 assert_eq!(variables.len(), 8);
2133 assert_eq!(variables[0].0, "variable_max_forwards");
2135 assert_eq!(variables[0].1, "69");
2136 assert_eq!(variables[1].0, "variable_presence_id");
2137 assert_eq!(variables[1].1, "1251@[2001:db8::10]");
2138 assert_eq!(variables[2].0, "variable_sip_h_X-Custom-ID");
2139 assert_eq!(variables[3].0, "variable_sip_h_X-Call-Info");
2141 assert!(variables[3].1.contains("emergency-CallId"));
2142 assert_eq!(variables[4].0, "variable_ep_codec_string");
2143 assert_eq!(variables[7].0, "variable_rtp_use_codec_name");
2144 assert_eq!(variables[7].1, "opus");
2145 }
2146 other => panic!("expected ChannelData block, got {other:?}"),
2147 }
2148 assert_eq!(entries[0].attached.len(), 8);
2149 assert_eq!(entries[1].message, "Next entry");
2150 assert_accounting(&stream);
2151 }
2152
2153 #[test]
2154 fn channel_data_uuid_drops_with_multiline_variable() {
2155 let lines = vec![
2160 full_line(UUID1, TS1, "CHANNEL_DATA:"),
2161 format!("{UUID1} variable_max_forwards: [69]"),
2162 format!("{UUID1} variable_sip_h_X-Custom-ID: [c4da84eb-88a7-40b2-b90d-e5bc2a0f634e]"),
2163 "variable_switch_r_sdp: [v=0\r".to_string(),
2165 "o=FreeSWITCH 1773663549 1773663550 IN IP6 2001:db8::10\r".to_string(),
2166 "s=FreeSWITCH\r".to_string(),
2167 "c=IN IP6 2001:db8::10\r".to_string(),
2168 "t=0 0\r".to_string(),
2169 "m=audio 9952 RTP/AVP 102 101 13\r".to_string(),
2170 "a=rtpmap:102 opus/48000/2\r".to_string(),
2171 "a=ptime:20\r".to_string(),
2172 "]".to_string(),
2173 "variable_ep_codec_string: [mod_opus.opus@48000h@20i@2c]".to_string(),
2174 "variable_direction: [inbound]".to_string(),
2175 full_line(UUID1, TS2, "Next entry"),
2176 ];
2177
2178 let mut stream = LogStream::new(lines.into_iter());
2179 let entries: Vec<_> = stream.by_ref().collect();
2180
2181 assert_eq!(entries.len(), 2);
2182 let block = entries[0].block.as_ref().expect("should have block");
2183 match block {
2184 Block::ChannelData { fields, variables } => {
2185 assert_eq!(fields.len(), 0);
2186 assert_eq!(variables.len(), 5);
2187 assert_eq!(variables[0].0, "variable_max_forwards");
2188 assert_eq!(variables[1].0, "variable_sip_h_X-Custom-ID");
2189 assert_eq!(variables[2].0, "variable_switch_r_sdp");
2191 let sdp = &variables[2].1;
2192 assert!(
2193 sdp.starts_with("v=0\r\n"),
2194 "SDP should start with v=0\\r\\n, got: {sdp:?}"
2195 );
2196 assert!(sdp.contains("m=audio 9952 RTP/AVP 102 101 13\r"));
2197 assert!(sdp.contains("a=ptime:20\r"));
2198 assert!(!sdp.ends_with(']'), "closing bracket should be stripped");
2199 assert_eq!(variables[3].0, "variable_ep_codec_string");
2201 assert_eq!(variables[4].0, "variable_direction");
2202 assert_eq!(variables[4].1, "inbound");
2203 }
2204 other => panic!("expected ChannelData block, got {other:?}"),
2205 }
2206 assert_eq!(entries[0].attached.len(), 13);
2208 assert_accounting(&stream);
2209 }
2210
2211 #[test]
2212 fn channel_data_bare_variable_collision_with_execute() {
2213 let collision = format!(
2220 "variable_call_uuid: {UUID1} EXECUTE [depth=0] \
2221 sofia/internal-v6/1251@[2001:db8::10] export(nolocal:test_var=value)"
2222 );
2223
2224 let lines = vec![
2225 full_line(UUID1, TS1, "CHANNEL_DATA:"),
2226 format!("{UUID1} variable_max_forwards: [69]"),
2227 "variable_DP_MATCH: [ARRAY::create_conference|:create_conference]".to_string(),
2229 collision,
2230 full_line(
2232 UUID1,
2233 TS2,
2234 "EXPORT (export_vars) (REMOTE ONLY) [test_var]=[value]",
2235 ),
2236 ];
2237
2238 let mut stream = LogStream::new(lines.into_iter());
2239 let entries: Vec<_> = stream.by_ref().collect();
2240
2241 assert_eq!(entries.len(), 3);
2243 let block = entries[0].block.as_ref().expect("should have block");
2244 match block {
2245 Block::ChannelData { fields, variables } => {
2246 assert_eq!(fields.len(), 0);
2247 assert_eq!(variables.len(), 2);
2248 assert_eq!(variables[0].0, "variable_max_forwards");
2249 assert_eq!(variables[1].0, "variable_DP_MATCH");
2250 }
2251 other => panic!("expected ChannelData block, got {other:?}"),
2252 }
2253
2254 assert_eq!(entries[1].uuid, UUID1);
2256 assert_eq!(entries[1].kind, LineKind::Truncated);
2257 assert!(
2258 entries[1].message.starts_with("EXECUTE "),
2259 "truncated line should yield EXECUTE, got: {}",
2260 entries[1].message
2261 );
2262
2263 assert_eq!(entries[2].message_kind.label(), "variable");
2265 assert_accounting(&stream);
2266 }
2267
2268 #[test]
2271 fn multibyte_at_warning_truncation_unrecognized_codec() {
2272 let msg = format!(
2274 "Audio Codec Compare {}é tail beyond eighty bytes",
2275 "x".repeat(59)
2276 );
2277 assert!(!msg.is_char_boundary(80));
2278 let lines = vec![
2279 full_line(
2280 UUID1,
2281 TS1,
2282 "Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]",
2283 ),
2284 full_line(UUID1, TS1, &msg),
2285 ];
2286 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
2287 assert_eq!(entries.len(), 1);
2288 assert!(
2289 entries[0]
2290 .warnings
2291 .iter()
2292 .any(|w| w.contains("unrecognized codec negotiation")),
2293 "expected codec warning, got: {:?}",
2294 entries[0].warnings
2295 );
2296 }
2297
2298 #[test]
2299 fn multibyte_at_warning_truncation_channel_data() {
2300 let bare = format!(
2301 "{}é tail beyond eighty bytes with no field separator",
2302 "x".repeat(79)
2303 );
2304 assert!(!bare.is_char_boundary(80));
2305 let lines = vec![full_line(UUID1, TS1, "CHANNEL_DATA:"), bare];
2306 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
2307 assert_eq!(entries.len(), 1);
2308 assert!(
2309 entries[0]
2310 .warnings
2311 .iter()
2312 .any(|w| w.contains("unparseable CHANNEL_DATA")),
2313 "expected unparseable warning, got: {:?}",
2314 entries[0].warnings
2315 );
2316 }
2317
2318 #[test]
2319 fn multibyte_at_warning_truncation_codec_continuation() {
2320 let cont = format!("{}é tail beyond eighty bytes", "x".repeat(79));
2321 assert!(!cont.is_char_boundary(80));
2322 let lines = vec![
2323 full_line(
2324 UUID1,
2325 TS1,
2326 "Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]",
2327 ),
2328 format!("{UUID1} {cont}"),
2329 ];
2330 let entries: Vec<_> = LogStream::new(lines.into_iter()).collect();
2331 assert_eq!(entries.len(), 1);
2332 assert!(
2333 entries[0]
2334 .warnings
2335 .iter()
2336 .any(|w| w.contains("unexpected codec negotiation")),
2337 "expected codec continuation warning, got: {:?}",
2338 entries[0].warnings
2339 );
2340 }
2341
2342 #[test]
2343 fn system_line_with_embedded_uuid_gets_entry_uuid() {
2344 let lines = vec![
2347 format!(
2348 "{TS1} 95.97% [DEBUG] switch_cpp.cpp:1466 {UUID1} DAA-LOG WaveManager originate"
2349 ),
2350 format!(
2351 "{TS1} 95.97% [WARNING] switch_cpp.cpp:1466 {UUID1} DAA-LOG Failed to create session"
2352 ),
2353 full_line(UUID1, TS2, "State Change CS_EXECUTE -> CS_HIBERNATE"),
2354 ];
2355
2356 let mut stream = LogStream::new(lines.into_iter());
2357 let entries: Vec<_> = stream.by_ref().collect();
2358
2359 assert_eq!(entries.len(), 3);
2360 assert_eq!(entries[0].uuid, UUID1);
2362 assert_eq!(entries[0].kind, LineKind::System);
2363 assert_eq!(entries[0].message, "DAA-LOG WaveManager originate");
2364
2365 assert_eq!(entries[1].uuid, UUID1);
2366 assert_eq!(entries[1].kind, LineKind::System);
2367 assert_eq!(entries[1].message, "DAA-LOG Failed to create session");
2368
2369 assert_eq!(entries[2].uuid, UUID1);
2371 assert_eq!(entries[2].kind, LineKind::Full);
2372 assert_accounting(&stream);
2373 }
2374}