From d7b37a5749192acd6682367f2b6066b1172b13e8 Mon Sep 17 00:00:00 2001 From: Siavash Sameni Date: Thu, 9 Apr 2026 19:17:03 +0400 Subject: [PATCH] diag: tracing for direct-call signal loop + CallEngine::start stages MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit User reports tapping "answer" on an incoming direct call does nothing visible, and suspects the same may affect desktop. The signal recv loop had no tracing at all, so we can't tell whether CallSetup is being received, whether the recv loop died silently, or whether CallEngine::start is failing between "identity loaded" and "connected to relay, handshake complete". - register_signal recv loop now logs every message type with fields (CallRinging, DirectCallOffer, DirectCallAnswer, CallSetup, Hangup, unhandled), plus a warn! on recv errors and a final warn when the loop exits. - place_call / answer_call commands log entry + success / error. The answer_call error path logs the underlying send_signal error so we can see it in logcat instead of only in the JS error toast. - CallEngine::start android branch logs relay/room/alias on entry, logs "endpoint created, dialing relay" between create_endpoint and connect, "QUIC connection established, performing handshake" between connect and perform_handshake, and promotes all three potential failures to explicit error! logs so a silent hang / error becomes visible in logcat. No functional changes — pure diagnostics. Stacks on b35a6b7 (the Oboe stack-pointer-escape fix) so build #43 carries both. --- desktop/src-tauri/src/engine.rs | 14 +++++++++--- desktop/src-tauri/src/lib.rs | 39 ++++++++++++++++++++++++++++----- 2 files changed, 44 insertions(+), 9 deletions(-) diff --git a/desktop/src-tauri/src/engine.rs b/desktop/src-tauri/src/engine.rs index 9cc1e75..29e9d8c 100644 --- a/desktop/src-tauri/src/engine.rs +++ b/desktop/src-tauri/src/engine.rs @@ -110,9 +110,11 @@ impl CallEngine { where F: Fn(&str, &str) + Send + Sync + 'static, { + info!(%relay, %room, %alias, %quality, "CallEngine::start (android) invoked"); let _ = rustls::crypto::ring::default_provider().install_default(); let relay_addr: SocketAddr = relay.parse()?; + info!(%relay_addr, "resolved relay addr"); // Identity via shared helper (uses Tauri path().app_data_dir()). let seed = crate::load_or_create_seed() @@ -123,9 +125,14 @@ impl CallEngine { // QUIC transport + handshake. let bind_addr: SocketAddr = "0.0.0.0:0".parse().unwrap(); - let endpoint = wzp_transport::create_endpoint(bind_addr, None)?; + let endpoint = wzp_transport::create_endpoint(bind_addr, None) + .map_err(|e| { error!("create_endpoint failed: {e}"); e })?; + info!("endpoint created, dialing relay"); let client_config = wzp_transport::client_config(); - let conn = wzp_transport::connect(&endpoint, relay_addr, &room, client_config).await?; + let conn = wzp_transport::connect(&endpoint, relay_addr, &room, client_config) + .await + .map_err(|e| { error!("connect failed: {e}"); e })?; + info!("QUIC connection established, performing handshake"); let transport = Arc::new(wzp_transport::QuinnTransport::new(conn)); let _session = wzp_client::handshake::perform_handshake( @@ -133,7 +140,8 @@ impl CallEngine { &seed.0, Some(&alias), ) - .await?; + .await + .map_err(|e| { error!("perform_handshake failed: {e}"); e })?; info!("connected to relay, handshake complete"); event_cb("connected", &format!("joined room {room}")); diff --git a/desktop/src-tauri/src/lib.rs b/desktop/src-tauri/src/lib.rs index fef0dc5..c3b8101 100644 --- a/desktop/src-tauri/src/lib.rs +++ b/desktop/src-tauri/src/lib.rs @@ -382,32 +382,50 @@ async fn register_signal( { let mut sig = state.signal.lock().await; sig.transport = Some(transport.clone()); sig.fingerprint = fp.clone(); sig.signal_status = "registered".into(); } + tracing::info!(%fp, "signal registered, spawning recv loop"); let signal_state = Arc::clone(&state.signal); let app_clone = app.clone(); tokio::spawn(async move { loop { match transport.recv_signal().await { Ok(Some(SignalMessage::CallRinging { call_id })) => { + tracing::info!(%call_id, "signal: CallRinging"); let mut sig = signal_state.lock().await; sig.signal_status = "ringing".into(); let _ = app_clone.emit("signal-event", serde_json::json!({"type":"ringing","call_id":call_id})); } Ok(Some(SignalMessage::DirectCallOffer { caller_fingerprint, caller_alias, call_id, .. })) => { + tracing::info!(%call_id, caller = %caller_fingerprint, "signal: DirectCallOffer"); let mut sig = signal_state.lock().await; sig.signal_status = "incoming".into(); sig.incoming_call_id = Some(call_id.clone()); sig.incoming_caller_fp = Some(caller_fingerprint.clone()); sig.incoming_caller_alias = caller_alias.clone(); let _ = app_clone.emit("signal-event", serde_json::json!({"type":"incoming","call_id":call_id,"caller_fp":caller_fingerprint,"caller_alias":caller_alias})); } + Ok(Some(SignalMessage::DirectCallAnswer { call_id, accept_mode, .. })) => { + tracing::info!(%call_id, ?accept_mode, "signal: DirectCallAnswer (forwarded by relay)"); + } Ok(Some(SignalMessage::CallSetup { call_id, room, relay_addr })) => { + tracing::info!(%call_id, %room, %relay_addr, "signal: CallSetup — emitting setup event to JS"); let mut sig = signal_state.lock().await; sig.signal_status = "setup".into(); let _ = app_clone.emit("signal-event", serde_json::json!({"type":"setup","call_id":call_id,"room":room,"relay_addr":relay_addr})); } - Ok(Some(SignalMessage::Hangup { .. })) => { + Ok(Some(SignalMessage::Hangup { reason })) => { + tracing::info!(?reason, "signal: Hangup"); let mut sig = signal_state.lock().await; sig.signal_status = "registered".into(); sig.incoming_call_id = None; let _ = app_clone.emit("signal-event", serde_json::json!({"type":"hangup"})); } - Ok(None) | Err(_) => break, - _ => {} + Ok(Some(other)) => { + tracing::debug!(?other, "signal: unhandled message"); + } + Ok(None) => { + tracing::warn!("signal recv returned None — peer closed"); + break; + } + Err(e) => { + tracing::warn!(error = %e, "signal recv error — breaking loop"); + break; + } } } + tracing::warn!("signal recv loop exited — signal_status=idle, transport dropped"); let mut sig = signal_state.lock().await; sig.signal_status = "idle".into(); sig.transport = None; }); Ok(fp) @@ -419,6 +437,7 @@ async fn place_call(state: tauri::State<'_, Arc>, target_fp: String) - let sig = state.signal.lock().await; let transport = sig.transport.as_ref().ok_or("not registered")?; let call_id = format!("{:016x}", std::time::SystemTime::now().duration_since(std::time::UNIX_EPOCH).unwrap().as_nanos()); + tracing::info!(%call_id, %target_fp, "place_call: sending DirectCallOffer"); transport.send_signal(&SignalMessage::DirectCallOffer { caller_fingerprint: sig.fingerprint.clone(), caller_alias: None, target_fingerprint: target_fp, call_id, identity_pub: [0u8; 32], ephemeral_pub: [0u8; 32], signature: vec![], @@ -431,12 +450,20 @@ async fn place_call(state: tauri::State<'_, Arc>, target_fp: String) - async fn answer_call(state: tauri::State<'_, Arc>, call_id: String, mode: i32) -> Result<(), String> { use wzp_proto::SignalMessage; let sig = state.signal.lock().await; - let transport = sig.transport.as_ref().ok_or("not registered")?; + let transport = sig.transport.as_ref().ok_or_else(|| { + tracing::warn!("answer_call: not registered (no transport)"); + "not registered".to_string() + })?; let accept_mode = match mode { 0 => wzp_proto::CallAcceptMode::Reject, 1 => wzp_proto::CallAcceptMode::AcceptTrusted, _ => wzp_proto::CallAcceptMode::AcceptGeneric }; + tracing::info!(%call_id, ?accept_mode, "answer_call: sending DirectCallAnswer"); transport.send_signal(&SignalMessage::DirectCallAnswer { - call_id, accept_mode, identity_pub: None, ephemeral_pub: None, signature: None, + call_id: call_id.clone(), accept_mode, identity_pub: None, ephemeral_pub: None, signature: None, chosen_profile: Some(wzp_proto::QualityProfile::GOOD), - }).await.map_err(|e| format!("{e}"))?; + }).await.map_err(|e| { + tracing::error!(%call_id, error = %e, "answer_call: send_signal failed"); + format!("{e}") + })?; + tracing::info!(%call_id, "answer_call: DirectCallAnswer sent successfully"); Ok(()) }