ant_quic/
structured_events.rs

1//! Structured event logging for observability
2//!
3//! Provides consistent, structured event logging throughout ant-quic.
4//! Events are categorized by component and severity for easy filtering
5//! and analysis.
6
7use std::fmt;
8use std::net::SocketAddr;
9use std::sync::atomic::{AtomicU64, Ordering};
10use std::time::{Duration, Instant};
11
12use crate::nat_traversal_api::PeerId;
13
14/// Event severity levels
15#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash)]
16pub enum EventSeverity {
17    /// Trace-level debugging information
18    Trace,
19    /// Debug information
20    Debug,
21    /// Informational messages
22    Info,
23    /// Warning conditions
24    Warn,
25    /// Error conditions
26    Error,
27}
28
29impl fmt::Display for EventSeverity {
30    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
31        match self {
32            Self::Trace => write!(f, "TRACE"),
33            Self::Debug => write!(f, "DEBUG"),
34            Self::Info => write!(f, "INFO"),
35            Self::Warn => write!(f, "WARN"),
36            Self::Error => write!(f, "ERROR"),
37        }
38    }
39}
40
41/// Component that generated the event
42#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
43pub enum EventComponent {
44    /// NAT traversal subsystem
45    NatTraversal,
46    /// Connection management
47    Connection,
48    /// Discovery subsystem
49    Discovery,
50    /// Transport layer
51    Transport,
52    /// Path selection
53    PathSelection,
54    /// Shutdown coordinator
55    Shutdown,
56    /// Relay subsystem
57    Relay,
58    /// Crypto operations
59    Crypto,
60    /// Endpoint operations
61    Endpoint,
62}
63
64impl fmt::Display for EventComponent {
65    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
66        match self {
67            Self::NatTraversal => write!(f, "nat_traversal"),
68            Self::Connection => write!(f, "connection"),
69            Self::Discovery => write!(f, "discovery"),
70            Self::Transport => write!(f, "transport"),
71            Self::PathSelection => write!(f, "path_selection"),
72            Self::Shutdown => write!(f, "shutdown"),
73            Self::Relay => write!(f, "relay"),
74            Self::Crypto => write!(f, "crypto"),
75            Self::Endpoint => write!(f, "endpoint"),
76        }
77    }
78}
79
80/// A structured event with typed fields
81#[derive(Debug, Clone)]
82pub struct StructuredEvent {
83    /// Event severity
84    pub severity: EventSeverity,
85    /// Component that generated the event
86    pub component: EventComponent,
87    /// Event kind/type
88    pub kind: EventKind,
89    /// Event message
90    pub message: String,
91    /// Timestamp when event occurred
92    pub timestamp: Instant,
93    /// Optional peer ID associated with event
94    pub peer_id: Option<PeerId>,
95    /// Optional address associated with event
96    pub addr: Option<SocketAddr>,
97    /// Optional duration associated with event
98    pub duration: Option<Duration>,
99    /// Optional count/value associated with event
100    pub count: Option<u64>,
101}
102
103/// Kinds of events that can be logged
104#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash)]
105pub enum EventKind {
106    // Connection events
107    /// Connection established
108    ConnectionEstablished,
109    /// Connection closed
110    ConnectionClosed,
111    /// Connection failed
112    ConnectionFailed,
113    /// Connection migrated to new path
114    ConnectionMigrated,
115
116    // NAT traversal events
117    /// Candidate discovered
118    CandidateDiscovered,
119    /// Candidate validated
120    CandidateValidated,
121    /// Candidate failed validation
122    CandidateFailed,
123    /// Hole punch initiated
124    HolePunchStarted,
125    /// Hole punch succeeded
126    HolePunchSucceeded,
127    /// Hole punch failed
128    HolePunchFailed,
129
130    // Path events
131    /// Path selected
132    PathSelected,
133    /// Path changed
134    PathChanged,
135    /// Path closed
136    PathClosed,
137    /// Path RTT updated
138    PathRttUpdated,
139
140    // Transport events
141    /// Packet sent
142    PacketSent,
143    /// Packet received
144    PacketReceived,
145    /// Transport error
146    TransportError,
147
148    // Discovery events
149    /// Discovery started
150    DiscoveryStarted,
151    /// Address discovered
152    AddressDiscovered,
153    /// Discovery completed
154    DiscoveryCompleted,
155
156    // Lifecycle events
157    /// Endpoint started
158    EndpointStarted,
159    /// Endpoint shutdown initiated
160    ShutdownInitiated,
161    /// Endpoint shutdown completed
162    ShutdownCompleted,
163
164    // Performance events
165    /// Actor tick completed
166    ActorTick,
167    /// Cleanup performed
168    CleanupPerformed,
169}
170
171impl fmt::Display for EventKind {
172    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
173        match self {
174            Self::ConnectionEstablished => write!(f, "connection_established"),
175            Self::ConnectionClosed => write!(f, "connection_closed"),
176            Self::ConnectionFailed => write!(f, "connection_failed"),
177            Self::ConnectionMigrated => write!(f, "connection_migrated"),
178            Self::CandidateDiscovered => write!(f, "candidate_discovered"),
179            Self::CandidateValidated => write!(f, "candidate_validated"),
180            Self::CandidateFailed => write!(f, "candidate_failed"),
181            Self::HolePunchStarted => write!(f, "hole_punch_started"),
182            Self::HolePunchSucceeded => write!(f, "hole_punch_succeeded"),
183            Self::HolePunchFailed => write!(f, "hole_punch_failed"),
184            Self::PathSelected => write!(f, "path_selected"),
185            Self::PathChanged => write!(f, "path_changed"),
186            Self::PathClosed => write!(f, "path_closed"),
187            Self::PathRttUpdated => write!(f, "path_rtt_updated"),
188            Self::PacketSent => write!(f, "packet_sent"),
189            Self::PacketReceived => write!(f, "packet_received"),
190            Self::TransportError => write!(f, "transport_error"),
191            Self::DiscoveryStarted => write!(f, "discovery_started"),
192            Self::AddressDiscovered => write!(f, "address_discovered"),
193            Self::DiscoveryCompleted => write!(f, "discovery_completed"),
194            Self::EndpointStarted => write!(f, "endpoint_started"),
195            Self::ShutdownInitiated => write!(f, "shutdown_initiated"),
196            Self::ShutdownCompleted => write!(f, "shutdown_completed"),
197            Self::ActorTick => write!(f, "actor_tick"),
198            Self::CleanupPerformed => write!(f, "cleanup_performed"),
199        }
200    }
201}
202
203impl StructuredEvent {
204    /// Create a new event builder
205    pub fn builder(component: EventComponent, kind: EventKind) -> StructuredEventBuilder {
206        StructuredEventBuilder::new(component, kind)
207    }
208
209    /// Log this event using tracing
210    pub fn log(&self) {
211        match self.severity {
212            EventSeverity::Trace => {
213                tracing::trace!(
214                    component = %self.component,
215                    kind = %self.kind,
216                    peer_id = ?self.peer_id,
217                    addr = ?self.addr,
218                    duration_ms = ?self.duration.map(|d| d.as_millis()),
219                    count = ?self.count,
220                    "{}",
221                    self.message
222                );
223            }
224            EventSeverity::Debug => {
225                tracing::debug!(
226                    component = %self.component,
227                    kind = %self.kind,
228                    peer_id = ?self.peer_id,
229                    addr = ?self.addr,
230                    duration_ms = ?self.duration.map(|d| d.as_millis()),
231                    count = ?self.count,
232                    "{}",
233                    self.message
234                );
235            }
236            EventSeverity::Info => {
237                tracing::info!(
238                    component = %self.component,
239                    kind = %self.kind,
240                    peer_id = ?self.peer_id,
241                    addr = ?self.addr,
242                    duration_ms = ?self.duration.map(|d| d.as_millis()),
243                    count = ?self.count,
244                    "{}",
245                    self.message
246                );
247            }
248            EventSeverity::Warn => {
249                tracing::warn!(
250                    component = %self.component,
251                    kind = %self.kind,
252                    peer_id = ?self.peer_id,
253                    addr = ?self.addr,
254                    duration_ms = ?self.duration.map(|d| d.as_millis()),
255                    count = ?self.count,
256                    "{}",
257                    self.message
258                );
259            }
260            EventSeverity::Error => {
261                tracing::error!(
262                    component = %self.component,
263                    kind = %self.kind,
264                    peer_id = ?self.peer_id,
265                    addr = ?self.addr,
266                    duration_ms = ?self.duration.map(|d| d.as_millis()),
267                    count = ?self.count,
268                    "{}",
269                    self.message
270                );
271            }
272        }
273    }
274}
275
276/// Builder for structured events
277#[derive(Debug)]
278pub struct StructuredEventBuilder {
279    component: EventComponent,
280    kind: EventKind,
281    severity: EventSeverity,
282    message: Option<String>,
283    peer_id: Option<PeerId>,
284    addr: Option<SocketAddr>,
285    duration: Option<Duration>,
286    count: Option<u64>,
287}
288
289impl StructuredEventBuilder {
290    /// Create a new builder
291    pub fn new(component: EventComponent, kind: EventKind) -> Self {
292        Self {
293            component,
294            kind,
295            severity: EventSeverity::Info,
296            message: None,
297            peer_id: None,
298            addr: None,
299            duration: None,
300            count: None,
301        }
302    }
303
304    /// Set event severity
305    pub fn severity(mut self, severity: EventSeverity) -> Self {
306        self.severity = severity;
307        self
308    }
309
310    /// Set event message
311    pub fn message(mut self, message: impl Into<String>) -> Self {
312        self.message = Some(message.into());
313        self
314    }
315
316    /// Set associated peer ID
317    pub fn peer_id(mut self, peer_id: PeerId) -> Self {
318        self.peer_id = Some(peer_id);
319        self
320    }
321
322    /// Set associated address
323    pub fn addr(mut self, addr: SocketAddr) -> Self {
324        self.addr = Some(addr);
325        self
326    }
327
328    /// Set associated duration
329    pub fn duration(mut self, duration: Duration) -> Self {
330        self.duration = Some(duration);
331        self
332    }
333
334    /// Set associated count
335    pub fn count(mut self, count: u64) -> Self {
336        self.count = Some(count);
337        self
338    }
339
340    /// Build the event
341    pub fn build(self) -> StructuredEvent {
342        StructuredEvent {
343            severity: self.severity,
344            component: self.component,
345            kind: self.kind,
346            message: self.message.unwrap_or_else(|| format!("{}", self.kind)),
347            timestamp: Instant::now(),
348            peer_id: self.peer_id,
349            addr: self.addr,
350            duration: self.duration,
351            count: self.count,
352        }
353    }
354
355    /// Build and log the event
356    pub fn log(self) {
357        self.build().log();
358    }
359}
360
361/// Actor tick metrics for monitoring loop fairness
362#[derive(Debug)]
363pub struct ActorTickMetrics {
364    /// Name of the actor
365    name: &'static str,
366    /// Total number of ticks
367    tick_count: AtomicU64,
368    /// Total processing time in nanoseconds
369    total_time_ns: AtomicU64,
370    /// Maximum tick duration in nanoseconds
371    max_tick_ns: AtomicU64,
372}
373
374impl ActorTickMetrics {
375    /// Create new actor tick metrics
376    pub fn new(name: &'static str) -> Self {
377        Self {
378            name,
379            tick_count: AtomicU64::new(0),
380            total_time_ns: AtomicU64::new(0),
381            max_tick_ns: AtomicU64::new(0),
382        }
383    }
384
385    /// Record a tick with the given duration
386    pub fn record_tick(&self, duration: Duration) {
387        let ns = duration.as_nanos() as u64;
388
389        self.tick_count.fetch_add(1, Ordering::Relaxed);
390        self.total_time_ns.fetch_add(ns, Ordering::Relaxed);
391
392        // Update max (relaxed ordering is fine for metrics)
393        let mut current_max = self.max_tick_ns.load(Ordering::Relaxed);
394        while ns > current_max {
395            match self.max_tick_ns.compare_exchange_weak(
396                current_max,
397                ns,
398                Ordering::Relaxed,
399                Ordering::Relaxed,
400            ) {
401                Ok(_) => break,
402                Err(new_max) => current_max = new_max,
403            }
404        }
405    }
406
407    /// Start timing a tick, returns a guard that records duration on drop
408    pub fn start_tick(&self) -> TickGuard<'_> {
409        TickGuard {
410            metrics: self,
411            start: Instant::now(),
412        }
413    }
414
415    /// Get the actor name
416    pub fn name(&self) -> &'static str {
417        self.name
418    }
419
420    /// Get total tick count
421    pub fn tick_count(&self) -> u64 {
422        self.tick_count.load(Ordering::Relaxed)
423    }
424
425    /// Get average tick duration
426    pub fn average_tick_duration(&self) -> Duration {
427        let count = self.tick_count.load(Ordering::Relaxed);
428        if count == 0 {
429            return Duration::ZERO;
430        }
431        let total_ns = self.total_time_ns.load(Ordering::Relaxed);
432        Duration::from_nanos(total_ns / count)
433    }
434
435    /// Get maximum tick duration
436    pub fn max_tick_duration(&self) -> Duration {
437        Duration::from_nanos(self.max_tick_ns.load(Ordering::Relaxed))
438    }
439
440    /// Get a snapshot of all metrics
441    pub fn snapshot(&self) -> ActorTickSnapshot {
442        ActorTickSnapshot {
443            name: self.name,
444            tick_count: self.tick_count(),
445            average_duration: self.average_tick_duration(),
446            max_duration: self.max_tick_duration(),
447        }
448    }
449
450    /// Reset all metrics
451    pub fn reset(&self) {
452        self.tick_count.store(0, Ordering::Relaxed);
453        self.total_time_ns.store(0, Ordering::Relaxed);
454        self.max_tick_ns.store(0, Ordering::Relaxed);
455    }
456}
457
458/// Guard that records tick duration on drop
459pub struct TickGuard<'a> {
460    metrics: &'a ActorTickMetrics,
461    start: Instant,
462}
463
464impl<'a> Drop for TickGuard<'a> {
465    fn drop(&mut self) {
466        self.metrics.record_tick(self.start.elapsed());
467    }
468}
469
470/// Snapshot of actor tick metrics
471#[derive(Debug, Clone)]
472pub struct ActorTickSnapshot {
473    /// Actor name
474    pub name: &'static str,
475    /// Total tick count
476    pub tick_count: u64,
477    /// Average tick duration
478    pub average_duration: Duration,
479    /// Maximum tick duration
480    pub max_duration: Duration,
481}
482
483impl fmt::Display for ActorTickSnapshot {
484    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
485        write!(
486            f,
487            "{}: {} ticks, avg={:?}, max={:?}",
488            self.name, self.tick_count, self.average_duration, self.max_duration
489        )
490    }
491}
492
493/// Convenience macros for logging structured events
494#[macro_export]
495macro_rules! log_event {
496    ($component:expr, $kind:expr, $msg:expr) => {
497        $crate::structured_events::StructuredEvent::builder($component, $kind)
498            .message($msg)
499            .log()
500    };
501    ($component:expr, $kind:expr, $msg:expr, severity = $sev:expr) => {
502        $crate::structured_events::StructuredEvent::builder($component, $kind)
503            .message($msg)
504            .severity($sev)
505            .log()
506    };
507    ($component:expr, $kind:expr, $msg:expr, addr = $addr:expr) => {
508        $crate::structured_events::StructuredEvent::builder($component, $kind)
509            .message($msg)
510            .addr($addr)
511            .log()
512    };
513    ($component:expr, $kind:expr, $msg:expr, peer = $peer:expr) => {
514        $crate::structured_events::StructuredEvent::builder($component, $kind)
515            .message($msg)
516            .peer_id($peer)
517            .log()
518    };
519}
520
521#[cfg(test)]
522mod tests {
523    use super::*;
524
525    #[test]
526    fn test_event_severity_ordering() {
527        assert!(EventSeverity::Trace < EventSeverity::Debug);
528        assert!(EventSeverity::Debug < EventSeverity::Info);
529        assert!(EventSeverity::Info < EventSeverity::Warn);
530        assert!(EventSeverity::Warn < EventSeverity::Error);
531    }
532
533    #[test]
534    fn test_event_builder() {
535        let event =
536            StructuredEvent::builder(EventComponent::Connection, EventKind::ConnectionEstablished)
537                .severity(EventSeverity::Info)
538                .message("Connection established")
539                .addr("192.168.1.1:5000".parse().unwrap())
540                .build();
541
542        assert_eq!(event.component, EventComponent::Connection);
543        assert_eq!(event.kind, EventKind::ConnectionEstablished);
544        assert_eq!(event.severity, EventSeverity::Info);
545        assert_eq!(event.message, "Connection established");
546        assert_eq!(event.addr, Some("192.168.1.1:5000".parse().unwrap()));
547    }
548
549    #[test]
550    fn test_event_builder_defaults() {
551        let event =
552            StructuredEvent::builder(EventComponent::Discovery, EventKind::DiscoveryStarted)
553                .build();
554
555        assert_eq!(event.severity, EventSeverity::Info);
556        assert_eq!(event.message, "discovery_started");
557        assert!(event.peer_id.is_none());
558        assert!(event.addr.is_none());
559    }
560
561    #[test]
562    fn test_actor_tick_metrics() {
563        let metrics = ActorTickMetrics::new("test_actor");
564
565        metrics.record_tick(Duration::from_millis(10));
566        metrics.record_tick(Duration::from_millis(20));
567        metrics.record_tick(Duration::from_millis(5));
568
569        assert_eq!(metrics.tick_count(), 3);
570        assert_eq!(metrics.max_tick_duration(), Duration::from_millis(20));
571
572        let avg = metrics.average_tick_duration();
573        // Average should be around 11.66ms
574        assert!(avg.as_millis() >= 10 && avg.as_millis() <= 13);
575    }
576
577    #[test]
578    fn test_actor_tick_guard() {
579        let metrics = ActorTickMetrics::new("test_actor");
580
581        {
582            let _guard = metrics.start_tick();
583            std::thread::sleep(Duration::from_millis(5));
584        }
585
586        assert_eq!(metrics.tick_count(), 1);
587        assert!(metrics.max_tick_duration() >= Duration::from_millis(4));
588    }
589
590    #[test]
591    fn test_actor_tick_reset() {
592        let metrics = ActorTickMetrics::new("test_actor");
593
594        metrics.record_tick(Duration::from_millis(10));
595        assert_eq!(metrics.tick_count(), 1);
596
597        metrics.reset();
598        assert_eq!(metrics.tick_count(), 0);
599        assert_eq!(metrics.max_tick_duration(), Duration::ZERO);
600    }
601
602    #[test]
603    fn test_actor_tick_snapshot() {
604        let metrics = ActorTickMetrics::new("test_actor");
605        metrics.record_tick(Duration::from_millis(10));
606
607        let snapshot = metrics.snapshot();
608        assert_eq!(snapshot.name, "test_actor");
609        assert_eq!(snapshot.tick_count, 1);
610    }
611
612    #[test]
613    fn test_event_component_display() {
614        assert_eq!(format!("{}", EventComponent::NatTraversal), "nat_traversal");
615        assert_eq!(format!("{}", EventComponent::Connection), "connection");
616        assert_eq!(
617            format!("{}", EventComponent::PathSelection),
618            "path_selection"
619        );
620    }
621
622    #[test]
623    fn test_event_kind_display() {
624        assert_eq!(
625            format!("{}", EventKind::ConnectionEstablished),
626            "connection_established"
627        );
628        assert_eq!(
629            format!("{}", EventKind::HolePunchStarted),
630            "hole_punch_started"
631        );
632        assert_eq!(format!("{}", EventKind::PathSelected), "path_selected");
633    }
634
635    #[test]
636    fn test_actor_tick_concurrent() {
637        use std::sync::Arc;
638        use std::thread;
639
640        let metrics = Arc::new(ActorTickMetrics::new("concurrent_actor"));
641        let mut handles = vec![];
642
643        for _ in 0..10 {
644            let m = Arc::clone(&metrics);
645            handles.push(thread::spawn(move || {
646                for _ in 0..100 {
647                    m.record_tick(Duration::from_micros(1));
648                }
649            }));
650        }
651
652        for handle in handles {
653            handle.join().unwrap();
654        }
655
656        assert_eq!(metrics.tick_count(), 1000);
657    }
658
659    #[test]
660    fn test_event_with_duration() {
661        let event =
662            StructuredEvent::builder(EventComponent::PathSelection, EventKind::PathRttUpdated)
663                .duration(Duration::from_millis(42))
664                .build();
665
666        assert_eq!(event.duration, Some(Duration::from_millis(42)));
667    }
668
669    #[test]
670    fn test_event_with_count() {
671        let event =
672            StructuredEvent::builder(EventComponent::NatTraversal, EventKind::CleanupPerformed)
673                .count(5)
674                .message("Cleaned up 5 expired candidates")
675                .build();
676
677        assert_eq!(event.count, Some(5));
678    }
679}
ant_quic/structured_events.rs

ant_quic/
structured_events.rs
