From 192ab25bbdf23833ea9c97520bcf43e235a66dd6 Mon Sep 17 00:00:00 2001 From: Aleksandr Bogomiakov Date: Wed, 30 Sep 2026 23:08:23 +0100 Subject: [PATCH] Support RUST_LOG, enable UPnP portmapper and add NAT traversal logging Previously, `tsunagi-cli` configured clap with a fixed default_value and `env = "TSUNAGI_LOG"`, which caused `RUST_LOG` to be completely ignored. In addition, `iroh` was built with `default-features = false` and lacked the `"portmapper"` feature, which caused it to compile a stub client and disable UPnP-IGD, PCP, and NAT-PMP port mapping. Furthermore, there was no visibility into STUN address discovery, UPnP port mapping status, or QUIC transmission path switching (hole punch vs relay). Key improvements: - Enable the `"portmapper"` feature on `iroh` in workspace Cargo.toml, pulling in `portmapper` and `igd-next` to actively request port mappings on local routers. - In `crates/tsunagi-cli/src/main.rs`, support `RUST_LOG` with fallback precedence (`--log` > `TSUNAGI_LOG` > `RUST_LOG` > default filter). When debug or trace filtering is active, automatically enable `.with_target(true)` so users can see which subsystem emitted the log (e.g., portmapper, iroh::magicsock, tsunagi::net). - In `crates/tsunagi/src/net.rs`, monitor `endpoint.watch_addr()` and `endpoint.home_relay_status()`. Emit `DEBUG` logs for local socket binding, discovered STUN reflexive/UPnP addresses, and relay connections. If no direct addresses are discovered after probe grace, emit a concise `WARN`. - In `crates/tsunagi/src/agent/session.rs`, monitor connection `path_events()` to log when transmission paths are opened, closed, or selected (switching between relay and direct hole-punched paths), with bounded task winding down on shutdown. Validation on Linux: - cargo fmt --all -- --check passed. - cargo clippy --locked --workspace --all-targets -- -D warnings passed. - cargo test --locked --workspace --all-targets passed (349 tests passed). - Live verification with `RUST_LOG=debug` confirmed SSDP broadcast to 239.255.255.250:1900, portmapper logs, STUN QAD discovery, and clean relay shutdown. --- Cargo.lock | 104 ++++++++++++++++++++++++++++ Cargo.toml | 2 +- crates/tsunagi-cli/src/main.rs | 25 ++++--- crates/tsunagi/Cargo.toml | 1 + crates/tsunagi/src/agent/session.rs | 57 ++++++++++++++- crates/tsunagi/src/net.rs | 85 +++++++++++++++++++++++ 6 files changed, 262 insertions(+), 12 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 7864a03..8f870b9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -234,6 +234,18 @@ version = "1.1.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "1505bd5d3d116872e7271a6d4e16d81d0c8570876c8de68093a09ac269d8aac0" +[[package]] +name = "attohttpc" +version = "0.30.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "16e2cdb6d5ed835199484bb92bb8b3edd526effe995c61732580439c1a67e2e9" +dependencies = [ + "base64 0.22.1", + "http", + "log", + "url", +] + [[package]] name = "autocfg" version = "1.5.1" @@ -1112,6 +1124,12 @@ dependencies = [ "spin 0.9.9", ] +[[package]] +name = "fnv" +version = "1.0.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3f9eec918d3f24069decb9af1554cad7c880e2da24a9afd88aca000531ab82c1" + [[package]] name = "foldhash" version = "0.2.0" @@ -1341,6 +1359,25 @@ dependencies = [ "wasm-bindgen", ] +[[package]] +name = "h2" +version = "0.4.19" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ef8e5e5a340588f4452631496976cf8636d4a7ecf600239fdc27615d2530bc16" +dependencies = [ + "atomic-waker", + "bytes", + "fnv", + "futures-core", + "futures-sink", + "http", + "indexmap", + "slab", + "tokio", + "tokio-util", + "tracing", +] + [[package]] name = "hashbrown" version = "0.16.1" @@ -1473,6 +1510,7 @@ dependencies = [ "bytes", "futures-channel", "futures-core", + "h2", "http", "http-body", "httparse", @@ -1656,6 +1694,26 @@ dependencies = [ "icu_properties", ] +[[package]] +name = "igd-next" +version = "0.17.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "de7238d487a9aff61f81b5ab41c0a841532a115a398b5fa92a2fadd0885e2581" +dependencies = [ + "attohttpc", + "bytes", + "futures", + "http", + "http-body-util", + "hyper", + "hyper-util", + "log", + "rand 0.10.3", + "tokio", + "url", + "xmltree", +] + [[package]] name = "indexmap" version = "2.14.2" @@ -1748,6 +1806,7 @@ dependencies = [ "papaya", "pin-project", "portable-atomic", + "portmapper", "rand 0.10.3", "reqwest", "rustc-hash", @@ -2936,6 +2995,35 @@ dependencies = [ "serde", ] +[[package]] +name = "portmapper" +version = "0.19.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ca97242f016e090a25330613bc2382aab65eb22f9149dbe84d8f8e711d49a530" +dependencies = [ + "base64 0.22.1", + "bytes", + "derive_more", + "hyper-util", + "igd-next", + "iroh-metrics", + "libc", + "n0-error", + "n0-future", + "netwatch", + "num_enum", + "rand 0.10.3", + "serde", + "smallvec", + "socket2", + "time", + "tokio", + "tokio-util", + "tower-layer", + "tracing", + "url", +] + [[package]] name = "postcard" version = "1.1.3" @@ -4138,6 +4226,7 @@ dependencies = [ "thiserror 2.0.20", "tld", "tokio", + "tokio-stream", "tracing", "tracing-subscriber", "tsunagi", @@ -4876,6 +4965,21 @@ dependencies = [ "time", ] +[[package]] +name = "xml-rs" +version = "0.8.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e450f9b2ed1dff33c94c12589a87338689467b9c4f5d8a5710bd09a847d2c8a7" + +[[package]] +name = "xmltree" +version = "0.10.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d7d8a75eaf6557bb84a65ace8609883db44a29951042ada9b393151532e41fcb" +dependencies = [ + "xml-rs", +] + [[package]] name = "yasna" version = "0.6.0" diff --git a/Cargo.toml b/Cargo.toml index 62619cf..88e172f 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -27,7 +27,7 @@ expect_used = "warn" panic = "warn" [workspace.dependencies] -iroh = { version = "1.2", default-features = false, features = ["tls-ring"] } +iroh = { version = "1.2", default-features = false, features = ["tls-ring", "portmapper"] } tokio = { version = "1.53", features = ["rt", "rt-multi-thread", "sync", "time", "macros"] } serde = { version = "1.0", features = ["derive"] } postcard = { version = "1.1", default-features = false, features = ["use-std"] } diff --git a/crates/tsunagi-cli/src/main.rs b/crates/tsunagi-cli/src/main.rs index d606ea0..bda260d 100644 --- a/crates/tsunagi-cli/src/main.rs +++ b/crates/tsunagi-cli/src/main.rs @@ -33,13 +33,10 @@ use tsunagi_wg_quic::{WireguardConfig, WireguardPlugin}; #[command(name = "tsunagi", version, about, long_about = None)] struct Cli { /// Log filter, for example `info` or `tsunagi=debug`. - #[arg( - long, - global = true, - env = "TSUNAGI_LOG", - default_value = "info,iroh=warn,quinn=warn,rustls=warn,boringtun=warn,mainline=off" - )] - log: String, + /// + /// Can also be set via the `TSUNAGI_LOG` or `RUST_LOG` environment variables. + #[arg(long, global = true)] + log: Option, #[command(subcommand)] command: Command, @@ -696,9 +693,19 @@ fn parse_peer(text: &str) -> Result { fn main() -> std::process::ExitCode { let cli = Cli::parse(); + let log_filter = cli + .log + .or_else(|| std::env::var("TSUNAGI_LOG").ok()) + .or_else(|| std::env::var("RUST_LOG").ok()) + .unwrap_or_else(|| { + "info,iroh=warn,quinn=warn,rustls=warn,boringtun=warn,mainline=off".to_string() + }); + + let is_debug = log_filter.contains("debug") || log_filter.contains("trace"); + tracing_subscriber::fmt() - .with_env_filter(tracing_subscriber::EnvFilter::new(&cli.log)) - .with_target(false) + .with_env_filter(tracing_subscriber::EnvFilter::new(&log_filter)) + .with_target(is_debug) .compact() .with_writer(std::io::stderr) .init(); diff --git a/crates/tsunagi/Cargo.toml b/crates/tsunagi/Cargo.toml index 03b970d..fc974d7 100644 --- a/crates/tsunagi/Cargo.toml +++ b/crates/tsunagi/Cargo.toml @@ -38,6 +38,7 @@ iroh.workspace = true # `net` for the local control interface: a Unix socket on Unix, a named pipe # on Windows. Both live behind the same `net` feature. tokio = { workspace = true, features = ["net"] } +tokio-stream = "0.1" serde.workspace = true postcard.workspace = true bytes.workspace = true diff --git a/crates/tsunagi/src/agent/session.rs b/crates/tsunagi/src/agent/session.rs index e274265..a44e2a9 100644 --- a/crates/tsunagi/src/agent/session.rs +++ b/crates/tsunagi/src/agent/session.rs @@ -80,11 +80,12 @@ pub(crate) struct Session { pub(crate) bytes_received: u64, reader: JoinHandle<()>, writer: JoinHandle<()>, + path_monitor: JoinHandle<()>, shutdown: Shutdown, } impl Session { - /// Signals both tasks to stop and waits for them, with a bounded grace + /// Signals all tasks to stop and waits for them, with a bounded grace /// period. /// /// A peer that stops reading must not be able to hold up shutdown, so the @@ -94,6 +95,7 @@ impl Session { conn, reader, writer, + path_monitor, shutdown, .. } = self; @@ -103,23 +105,27 @@ impl Session { let reader_abort = reader.abort_handle(); let writer_abort = writer.abort_handle(); + let path_abort = path_monitor.abort_handle(); let joined = tokio::time::timeout(STOP_GRACE, async move { let _ = reader.await; let _ = writer.await; + let _ = path_monitor.await; }) .await; if joined.is_err() { tracing::debug!("session tasks did not wind down in time; aborting them"); reader_abort.abort(); writer_abort.abort(); + path_abort.abort(); } } - /// Aborts both tasks without waiting. Used on replacement. + /// Aborts all tasks without waiting. Used on replacement. pub(crate) fn abort(&self) { self.shutdown.trigger(); self.reader.abort(); self.writer.abort(); + self.path_monitor.abort(); } } @@ -155,6 +161,52 @@ pub(crate) fn spawn( parent_shutdown.clone(), )); + let path_conn = conn.clone(); + let path_shutdown = shutdown.clone(); + let path_parent = parent_shutdown.clone(); + let path_monitor = tokio::spawn(async move { + use tokio_stream::StreamExt; + let mut events = path_conn.path_events(); + loop { + tokio::select! { + biased; + _ = path_shutdown.wait() => break, + _ = path_parent.wait() => break, + ev = events.next() => { + match ev { + Some(iroh::endpoint::PathEvent::Selected { remote_addr, local_addr, .. }) => { + tracing::debug!( + peer = %peer.fmt_short(), + remote = %remote_addr, + local = ?local_addr, + "Connection path selected (direct / relay / hole punch switch)" + ); + } + Some(iroh::endpoint::PathEvent::Opened { remote_addr, .. }) => { + tracing::debug!( + peer = %peer.fmt_short(), + remote = %remote_addr, + "Network path opened to peer" + ); + } + Some(iroh::endpoint::PathEvent::Closed { remote_addr, .. }) => { + tracing::debug!( + peer = %peer.fmt_short(), + remote = %remote_addr, + "Network path closed for peer" + ); + } + Some(iroh::endpoint::PathEvent::Lagged { missed, .. }) => { + tracing::trace!(peer = %peer.fmt_short(), missed, "Path events lagged"); + } + Some(_) => {} + None => break, + } + } + } + } + }); + let reader = tokio::spawn(reader_task( id, network_id, @@ -182,6 +234,7 @@ pub(crate) fn spawn( bytes_received: 0, reader, writer, + path_monitor, shutdown, } } diff --git a/crates/tsunagi/src/net.rs b/crates/tsunagi/src/net.rs index cc34bdf..6fdbebf 100644 --- a/crates/tsunagi/src/net.rs +++ b/crates/tsunagi/src/net.rs @@ -259,6 +259,91 @@ impl EndpointAdapter { .await .map_err(|err| Error::Endpoint(format!("cannot bind endpoint: {err}")))?; + tracing::debug!( + endpoint = %endpoint.id().fmt_short(), + bound_sockets = ?endpoint.bound_sockets(), + "iroh endpoint bound locally" + ); + + let ep_id = endpoint.id(); + let mut addr_watcher = endpoint.watch_addr(); + let mut relay_watcher = endpoint.home_relay_status(); + let close_token = endpoint.clone(); + tokio::spawn(async move { + use iroh::Watcher; + let mut last_addrs: Vec = Vec::new(); + let mut last_relays: Vec = Vec::new(); + + let warn_timer = tokio::time::sleep(Duration::from_secs(12)); + tokio::pin!(warn_timer); + let mut warned = false; + + loop { + tokio::select! { + biased; + _ = close_token.closed() => { + break; + } + () = &mut warn_timer, if !warned => { + warned = true; + if last_addrs.is_empty() && !last_relays.is_empty() { + tracing::warn!( + endpoint = %ep_id.fmt_short(), + relays = ?last_relays, + "No direct reflexive or UPnP addresses discovered after probe; communications will rely on relay servers" + ); + } else if last_addrs.is_empty() && last_relays.is_empty() { + tracing::warn!( + endpoint = %ep_id.fmt_short(), + "No reachability discovered (neither direct reflexive/UPnP addresses nor relay servers available)" + ); + } + } + res = addr_watcher.updated() => { + let addr = match res { + Ok(a) => a, + Err(_) => break, + }; + let addrs: Vec = addr.ip_addrs().copied().collect(); + let relays: Vec = addr.relay_urls().map(|u| u.to_string()).collect(); + + if addrs != last_addrs || relays != last_relays { + tracing::debug!( + endpoint = %ep_id.fmt_short(), + direct_addrs = ?addrs, + relays = ?relays, + "Discovered endpoint reachability (STUN/UPnP/local/relay)" + ); + last_addrs = addrs; + last_relays = relays; + } + } + res = relay_watcher.updated() => { + let relays = match res { + Ok(r) => r, + Err(_) => break, + }; + for relay in &relays { + if relay.is_connected() { + tracing::debug!( + endpoint = %ep_id.fmt_short(), + relay = %relay.url(), + "Connected to home relay server" + ); + } else if let Some(err) = relay.last_error() { + tracing::debug!( + endpoint = %ep_id.fmt_short(), + relay = %relay.url(), + error = %err, + "Relay connection attempt failed" + ); + } + } + } + } + } + }); + Ok(Self { endpoint }) }