diff --git a/README.md b/README.md index a643d07..f26f3bb 100644 --- a/README.md +++ b/README.md @@ -41,7 +41,7 @@ Reliable control-plane schema shared by the QUIC stream handlers: Shared diagnostics and structured logging vocabulary: -- gateway/relay frame logs with MACs, ethertype, length, peer, and action +- client/gateway/relay frame logs with MACs, ethertype, length, peer, and action - tunnel counters shared by control messages and runtime diagnostics - client connectivity/TAP diagnostics and user-facing status messages @@ -280,7 +280,9 @@ stopping the bridge. Relayed LAN frames are also safety-checked before TAP writes, so switch-control traffic, invalid-source frames, and jumbo frames stay out of the Windows adapter even if they reached the client over QUIC. Misdirected unicast frames not addressed to the client's virtual MAC are also -counted and skipped; TAP device read/write errors still stop the bridge. +counted and skipped; accepted TAP-to-relay and relay-to-TAP frames are logged +with direction, peer id, MACs, ethertype/length, frame length, action, and drop +reason. TAP device read/write errors still stop the bridge. Relay lifecycle events are logged as they arrive, including gateway joins and peer leaves. The client remembers peer identities from join and catch-up events so later leave logs can identify a disconnected LAN gateway or client MAC when diff --git a/TESTING.md b/TESTING.md index 2fb2248..0e63876 100644 --- a/TESTING.md +++ b/TESTING.md @@ -246,6 +246,8 @@ Client health: ```text Relay RTT: 23 ms Broadcast traffic flowing +client frame direction=TapToRelay ... action=Forwarded drop_reason=- +client frame direction=RelayToTap ... action=Forwarded drop_reason=- ``` Drops that can be normal during testing: diff --git a/crates/lanparty-client-win/src/main.rs b/crates/lanparty-client-win/src/main.rs index 12f872d..a337f72 100644 --- a/crates/lanparty-client-win/src/main.rs +++ b/crates/lanparty-client-win/src/main.rs @@ -24,9 +24,10 @@ use lanparty_client_tap::TapAdapterInfo; use lanparty_ctrl::{ControlMessage, PeerInfo, Role, RoomCode}; use lanparty_net::RelayEndpoint; use lanparty_obs::{ - ClientDiagnostics, RelayDiagnostics, TapDiagnostics, UserDiagnostic, UserDiagnosticLevel, + ClientDiagnostics, DropReason, FrameAction, FrameDirection, FrameLog, RelayDiagnostics, + TapDiagnostics, UserDiagnostic, UserDiagnosticLevel, }; -use lanparty_proto::MacAddr; +use lanparty_proto::{EthernetFrame, MacAddr}; #[cfg(windows)] const TAP_INTERFACE_METRIC: u32 = 9_000; @@ -704,6 +705,52 @@ fn format_client_diagnostics(diagnostics: &ClientDiagnostics) -> String { ) } +#[cfg_attr(not(windows), allow(dead_code))] +fn client_frame_log_line( + direction: FrameDirection, + peer_id: Option, + frame_bytes: &[u8], + action: FrameAction, + drop_reason: Option, +) -> String { + let log = match EthernetFrame::parse(frame_bytes) { + Ok(frame) => FrameLog::from_ethernet(direction, peer_id, action, drop_reason, frame), + Err(_) => FrameLog::malformed(direction, peer_id, frame_bytes.len()), + }; + let source_mac = log + .source_mac() + .map(|mac| mac.to_string()) + .unwrap_or_else(|| "-".to_owned()); + let destination_mac = log + .destination_mac() + .map(|mac| mac.to_string()) + .unwrap_or_else(|| "-".to_owned()); + let ethertype_or_len = log + .ethertype_or_len() + .map(|value| format!("0x{value:04x}")) + .unwrap_or_else(|| "-".to_owned()); + let peer_id = log + .peer_id() + .map(|peer_id| peer_id.to_string()) + .unwrap_or_else(|| "-".to_owned()); + let drop_reason = log + .drop_reason() + .map(|reason| format!("{reason:?}")) + .unwrap_or_else(|| "-".to_owned()); + + format!( + "client frame direction={:?} peer_id={} src={} dst={} ethertype_or_len={} len={} action={:?} drop_reason={}", + log.direction(), + peer_id, + source_mac, + destination_mac, + ethertype_or_len, + log.frame_len(), + log.action(), + drop_reason, + ) +} + const fn yes_no(value: bool) -> &'static str { if value { "yes" } else { "no" } } @@ -1029,14 +1076,26 @@ async fn run_tap_frame_pump(relay_io: ClientRelayIo, tap: Arc) -> Re } relay_frame = relay_io.recv_ethernet() => { let relay_frame = relay_frame.context("failed to receive relay Ethernet frame")?; + let source_peer_id = relay_frame.source_peer_id(); let tap = Arc::clone(&tap); let payload = relay_frame.payload().to_vec(); + let log_payload = payload.clone(); tokio::task::spawn_blocking(move || { tap.write_ethernet_frame(&payload) .context("failed to write relay Ethernet frame to TAP") }) .await .context("TAP writer task panicked")??; + println!( + "{}", + client_frame_log_line( + FrameDirection::RelayToTap, + Some(source_peer_id), + &log_payload, + FrameAction::Forwarded, + None, + ) + ); } } } @@ -1076,9 +1135,29 @@ fn read_and_relay_tap_frame( .send_ethernet_with_outcome(&buffer[..len]) .context("failed to send TAP Ethernet frame to relay")? { - lanparty_client_core::ClientSendOutcome::Sent => {} + lanparty_client_core::ClientSendOutcome::Sent => { + println!( + "{}", + client_frame_log_line( + FrameDirection::TapToRelay, + Some(relay_io.welcome().peer_id()), + &buffer[..len], + FrameAction::Forwarded, + None, + ) + ); + } lanparty_client_core::ClientSendOutcome::Dropped(reason) => { - eprintln!("dropped TAP Ethernet frame before relay send: {reason:?}"); + eprintln!( + "{}", + client_frame_log_line( + FrameDirection::TapToRelay, + Some(relay_io.welcome().peer_id()), + &buffer[..len], + FrameAction::Dropped, + Some(reason), + ) + ); } } @@ -1149,6 +1228,32 @@ mod tests { ); } + #[test] + fn formats_client_frame_log_lines() { + let frame = ethernet_frame(mac(2), mac(1)); + + assert_eq!( + client_frame_log_line( + FrameDirection::TapToRelay, + Some(2), + &frame, + FrameAction::Forwarded, + None, + ), + "client frame direction=TapToRelay peer_id=2 src=02:00:00:00:00:01 dst=02:00:00:00:00:02 ethertype_or_len=0x0800 len=21 action=Forwarded drop_reason=-" + ); + assert_eq!( + client_frame_log_line( + FrameDirection::TapToRelay, + Some(2), + &[0; 4], + FrameAction::Dropped, + Some(DropReason::Malformed), + ), + "client frame direction=TapToRelay peer_id=2 src=- dst=- ethertype_or_len=- len=4 action=Dropped drop_reason=Malformed" + ); + } + #[test] fn formats_user_diagnostic_levels() { assert_eq!( @@ -1424,6 +1529,15 @@ mod tests { TapAdapterInfo::new(instance_id, "tap0901").unwrap() } + fn ethernet_frame(destination: MacAddr, source: MacAddr) -> Vec { + let mut frame = Vec::new(); + frame.extend_from_slice(&destination.octets()); + frame.extend_from_slice(&source.octets()); + frame.extend_from_slice(&0x0800_u16.to_be_bytes()); + frame.extend_from_slice(b"payload"); + frame + } + fn unique_temp_file(prefix: &str) -> std::path::PathBuf { let nanos = SystemTime::now() .duration_since(UNIX_EPOCH) diff --git a/crates/lanparty-obs/src/lib.rs b/crates/lanparty-obs/src/lib.rs index 58dddaf..87d0c7b 100644 --- a/crates/lanparty-obs/src/lib.rs +++ b/crates/lanparty-obs/src/lib.rs @@ -10,6 +10,8 @@ use lanparty_proto::{EthernetFrame, EthernetSafetyDrop, MacAddr}; #[derive(Debug, Clone, Copy, PartialEq, Eq, serde::Deserialize, serde::Serialize)] #[serde(rename_all = "snake_case")] pub enum FrameDirection { + TapToRelay, + RelayToTap, RemoteToLan, LanToRemote, RelayIngress,