diff --git a/crates/wzp-android/src/engine.rs b/crates/wzp-android/src/engine.rs index 7d30505..e7e35ac 100644 --- a/crates/wzp-android/src/engine.rs +++ b/crates/wzp-android/src/engine.rs @@ -538,7 +538,7 @@ async fn run_call( alias: alias.map(|s| s.to_string()), protocol_version: 2, supported_versions: vec![2], - video_codecs: vec![], + video_codecs: vec![CodecId::H264Baseline], }; transport.send_signal(&offer).await?; info!("CallOffer sent, waiting for CallAnswer..."); diff --git a/crates/wzp-client/src/handshake.rs b/crates/wzp-client/src/handshake.rs index 7813010..352ccb4 100644 --- a/crates/wzp-client/src/handshake.rs +++ b/crates/wzp-client/src/handshake.rs @@ -8,6 +8,8 @@ use wzp_proto::{ CodecId, HangupReason, MediaTransport, QualityProfile, SignalMessage, default_signal_version, }; +const SUPPORTED_VIDEO_CODECS: &[CodecId] = &[CodecId::H264Baseline]; + /// Result of a successful client-side handshake. pub struct HandshakeResult { pub session: Box, @@ -102,7 +104,7 @@ pub async fn perform_handshake( alias: alias.map(|s| s.to_string()), protocol_version: 2, supported_versions: vec![2], - video_codecs: vec![CodecId::Av1Main, CodecId::H264Baseline, CodecId::H265Main], + video_codecs: SUPPORTED_VIDEO_CODECS.to_vec(), }; transport .send_signal(&offer) @@ -189,16 +191,17 @@ mod tests { let mut kx2 = WarzoneKeyExchange::from_identity_seed(&[0x66; 32]); kx2.generate_ephemeral(); let session2 = kx2.derive_session(&[0u8; 32]).unwrap(); - let hs2 = HandshakeResult { session: session2, video_codec: Some(CodecId::Av1Main) }; - assert_eq!(hs2.video_codec, Some(CodecId::Av1Main)); + let hs2 = HandshakeResult { + session: session2, + video_codec: Some(CodecId::H264Baseline), + }; + assert_eq!(hs2.video_codec, Some(CodecId::H264Baseline)); } #[test] - fn offer_contains_three_video_codecs() { - // The offer sent in perform_handshake always includes the three codecs - // declared in order: AV1 > H264 > H265. Verify via the const list. - let offered = vec![CodecId::Av1Main, CodecId::H264Baseline, CodecId::H265Main]; - assert_eq!(offered.len(), 3); - assert_eq!(offered[0], CodecId::Av1Main, "AV1 must be preferred"); + fn offer_contains_h264_only() { + // Keep room video on the common denominator until Android AV1/HEVC + // send paths are proven in-device. + assert_eq!(SUPPORTED_VIDEO_CODECS, &[CodecId::H264Baseline]); } } diff --git a/crates/wzp-relay/src/handshake.rs b/crates/wzp-relay/src/handshake.rs index 4c2ac7b..42e5cf6 100644 --- a/crates/wzp-relay/src/handshake.rs +++ b/crates/wzp-relay/src/handshake.rs @@ -177,9 +177,9 @@ mod tests { #[test] fn video_codec_picks_first_offered() { - let codecs = vec![CodecId::Av1Main, CodecId::H264Baseline, CodecId::H265Main]; + let codecs = vec![CodecId::H264Baseline]; let chosen: Option = codecs.into_iter().next(); - assert_eq!(chosen, Some(CodecId::Av1Main)); + assert_eq!(chosen, Some(CodecId::H264Baseline)); } #[test] diff --git a/crates/wzp-video/src/mediacodec.rs b/crates/wzp-video/src/mediacodec.rs index 1692e87..8e1d43b 100644 --- a/crates/wzp-video/src/mediacodec.rs +++ b/crates/wzp-video/src/mediacodec.rs @@ -160,8 +160,11 @@ impl VideoEncoder for MediaCodecEncoder { if packet.is_empty() { return false; } - let nal_type = packet[0] & 0x1F; - nal_type == 5 + let nals = split_annex_b(packet); + if nals.is_empty() { + return (packet[0] & 0x1F) == 5; + } + nals.iter().any(|nal| !nal.is_empty() && (nal[0] & 0x1F) == 5) } } @@ -1135,6 +1138,11 @@ mod tests { }; assert!(enc.is_keyframe(&[0x65, 0x01])); assert!(!enc.is_keyframe(&[0x41, 0x01])); + assert!(enc.is_keyframe(&[ + 0x00, 0x00, 0x00, 0x01, 0x67, 0x01, // SPS + 0x00, 0x00, 0x00, 0x01, 0x68, 0x02, // PPS + 0x00, 0x00, 0x00, 0x01, 0x65, 0x03, // IDR + ])); } #[test] diff --git a/crates/wzp-video/src/videotoolbox.rs b/crates/wzp-video/src/videotoolbox.rs index 5a3b575..463b02a 100644 --- a/crates/wzp-video/src/videotoolbox.rs +++ b/crates/wzp-video/src/videotoolbox.rs @@ -160,9 +160,11 @@ impl VideoEncoder for VideoToolboxEncoder { if packet.is_empty() { return false; } - let nal_type = packet[0] & 0x1F; - // NAL type 5 = IDR slice (keyframe). - nal_type == 5 + let nals = split_annex_b(packet); + if nals.is_empty() { + return (packet[0] & 0x1F) == 5; + } + nals.iter().any(|nal| !nal.is_empty() && (nal[0] & 0x1F) == 5) } } @@ -791,6 +793,11 @@ mod tests { let enc = VideoToolboxEncoder::new(1280, 720, 2_000_000).unwrap(); assert!(enc.is_keyframe(&[0x65, 0x01, 0x02])); assert!(!enc.is_keyframe(&[0x41, 0x01, 0x02])); + assert!(enc.is_keyframe(&[ + 0x00, 0x00, 0x00, 0x01, 0x67, 0x01, // SPS + 0x00, 0x00, 0x00, 0x01, 0x68, 0x02, // PPS + 0x00, 0x00, 0x00, 0x01, 0x65, 0x03, // IDR + ])); } #[test] diff --git a/crates/wzp-video/tests/pipeline_roundtrip.rs b/crates/wzp-video/tests/pipeline_roundtrip.rs index 141b1db..5146bd6 100644 --- a/crates/wzp-video/tests/pipeline_roundtrip.rs +++ b/crates/wzp-video/tests/pipeline_roundtrip.rs @@ -177,9 +177,9 @@ fn missing_fragment_blocks_reassembly() { #[test] fn video_codec_selection_semantics() { // The relay's selection rule is: first codec offered by the caller. - let offered = vec![CodecId::Av1Main, CodecId::H264Baseline, CodecId::H265Main]; + let offered = vec![CodecId::H264Baseline]; let chosen = offered.into_iter().next(); - assert_eq!(chosen, Some(CodecId::Av1Main)); + assert_eq!(chosen, Some(CodecId::H264Baseline)); // When no codecs are offered, video is audio-only. let empty: Vec = vec![]; diff --git a/desktop/src-tauri/src/engine.rs b/desktop/src-tauri/src/engine.rs index f9847eb..68a7679 100644 --- a/desktop/src-tauri/src/engine.rs +++ b/desktop/src-tauri/src/engine.rs @@ -634,6 +634,7 @@ impl CallEngine { "connect:handshake_done", serde_json::json!({ "t_ms": call_t0.elapsed().as_millis(), + "video_codec": hs.video_codec.map(|c| format!("{:?}", c)), }), ); info!( @@ -653,6 +654,16 @@ impl CallEngine { ); (None, transport) }; + crate::emit_call_debug( + &app, + "video:negotiated", + serde_json::json!({ + "t_ms": call_t0.elapsed().as_millis(), + "codec": _negotiated_video_codec.map(|c| format!("{:?}", c)), + "enabled": _negotiated_video_codec.is_some(), + "direct_p2p": is_direct_p2p, + }), + ); // Do not emit the legacy "connected" call-event here. The frontend // ignores it and enters voice only after the command resolves; on // Android this synchronous emit was the only operation between @@ -1172,6 +1183,9 @@ impl CallEngine { let mut video_decoder: Option> = None; let mut video_decoder_codec: Option = None; let mut video_first_recv_logged = false; + let mut video_first_reassembled_logged = false; + let mut video_first_decoded_logged = false; + let mut video_decoder_buffering_count: u64 = 0; loop { if !recv_r.load(Ordering::Relaxed) { @@ -1203,15 +1217,59 @@ impl CallEngine { if let Some((codec_id, is_kf, frame)) = video_reassembler.push(&pkt) { + if !video_first_reassembled_logged { + video_first_reassembled_logged = true; + crate::emit_call_debug( + &recv_app, + "video:first_reassembled", + serde_json::json!({ + "t_ms": recv_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", codec_id), + "is_keyframe": is_kf, + "frame_bytes": frame.len(), + "platform": "android", + }), + ); + } if video_decoder_codec != Some(codec_id) { + crate::emit_call_debug( + &recv_app, + "video:decoder_init_start", + serde_json::json!({ + "t_ms": recv_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", codec_id), + "width": 1280, + "height": 720, + "platform": "android", + }), + ); match wzp_video::factory::create_video_decoder(codec_id, 1280, 720) { Ok(d) => { info!(codec = ?codec_id, "video decoder created (android)"); + crate::emit_call_debug( + &recv_app, + "video:decoder_started", + serde_json::json!({ + "t_ms": recv_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", codec_id), + "platform": "android", + }), + ); video_decoder = Some(d); video_decoder_codec = Some(codec_id); } Err(e) => { error!("video decoder init failed: {e}"); + crate::emit_call_debug( + &recv_app, + "video:decoder_init_failed", + serde_json::json!({ + "t_ms": recv_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", codec_id), + "error": e.to_string(), + "platform": "android", + }), + ); } } } @@ -1223,6 +1281,37 @@ impl CallEngine { yuv_frame.width, yuv_frame.height, ); + let jpeg_ok = jpeg_b64.is_some(); + if !video_first_decoded_logged { + video_first_decoded_logged = true; + crate::emit_call_debug( + &recv_app, + "video:first_decoded_frame", + serde_json::json!({ + "t_ms": recv_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", codec_id), + "width": yuv_frame.width, + "height": yuv_frame.height, + "yuv_bytes": yuv_frame.data.len(), + "jpeg_ok": jpeg_ok, + "platform": "android", + }), + ); + } + if !jpeg_ok { + crate::emit_call_debug( + &recv_app, + "video:jpeg_encode_failed", + serde_json::json!({ + "t_ms": recv_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", codec_id), + "width": yuv_frame.width, + "height": yuv_frame.height, + "yuv_bytes": yuv_frame.data.len(), + "platform": "android", + }), + ); + } let _ = recv_app.emit( "video:frame", serde_json::json!({ @@ -1234,9 +1323,35 @@ impl CallEngine { }), ); } - Ok(None) => {} + Ok(None) => { + video_decoder_buffering_count += 1; + if video_decoder_buffering_count == 1 + || video_decoder_buffering_count % 30 == 0 + { + crate::emit_call_debug( + &recv_app, + "video:decoder_buffering", + serde_json::json!({ + "t_ms": recv_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", codec_id), + "buffering": video_decoder_buffering_count, + "platform": "android", + }), + ); + } + } Err(e) => { error!("video decode error: {e}"); + crate::emit_call_debug( + &recv_app, + "video:decode_error", + serde_json::json!({ + "t_ms": recv_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", codec_id), + "error": e.to_string(), + "platform": "android", + }), + ); } } } @@ -1604,19 +1719,77 @@ impl CallEngine { let vid_running = running.clone(); let vid_t0 = call_t0; let vid_app = app.clone(); + crate::emit_call_debug( + &app, + "video:sender_channel_ready", + serde_json::json!({ + "t_ms": call_t0.elapsed().as_millis(), + "codec": format!("{:?}", vid_codec), + "queue_depth": 4, + "platform": "android", + }), + ); tokio::spawn(async move { + crate::emit_call_debug( + &vid_app, + "video:encoder_init_start", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "width": 1280, + "height": 720, + "bitrate_bps": 1_500_000, + "platform": "android", + }), + ); let mut encoder = match wzp_video::factory::create_video_encoder( vid_codec, 1280, 720, 1_500_000, ) { - Ok(e) => e, + Ok(e) => { + crate::emit_call_debug( + &vid_app, + "video:encoder_started", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "platform": "android", + }), + ); + e + } Err(e) => { error!("video encoder init failed (android): {e}"); + crate::emit_call_debug( + &vid_app, + "video:encoder_init_failed", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "platform": "android", + "error": e.to_string(), + }), + ); return; } }; let mut seq: u32 = 0; let mut frames_since_keyframe: u32 = 0; let mut first_send_logged = false; + let mut first_camera_frame_logged = false; + let mut camera_frames: u64 = 0; + let mut empty_encodes: u64 = 0; + let mut wait_ticks: u64 = 0; + encoder.request_keyframe(); + crate::emit_call_debug( + &vid_app, + "video:keyframe_requested", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "reason": "initial", + "platform": "android", + }), + ); info!(codec = ?vid_codec, "video send task started (android)"); while vid_running.load(Ordering::Relaxed) { let frame = match tokio::time::timeout( @@ -1625,13 +1798,58 @@ impl CallEngine { ) .await { - Ok(Some(f)) => f, + Ok(Some(f)) => { + wait_ticks = 0; + camera_frames += 1; + if !first_camera_frame_logged { + first_camera_frame_logged = true; + crate::emit_call_debug( + &vid_app, + "video:first_camera_frame", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "width": f.width, + "height": f.height, + "data_bytes": f.data.len(), + "platform": "android", + }), + ); + } + f + } Ok(None) => break, - Err(_) => continue, + Err(_) => { + wait_ticks += 1; + if wait_ticks == 10 || wait_ticks % 50 == 0 { + crate::emit_call_debug( + &vid_app, + "video:waiting_for_camera_frames", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "wait_ms": wait_ticks * 200, + "codec": format!("{:?}", vid_codec), + "platform": "android", + }), + ); + } + continue; + } }; if frames_since_keyframe >= 150 { encoder.request_keyframe(); + crate::emit_call_debug( + &vid_app, + "video:keyframe_requested", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "reason": "periodic", + "camera_frames": camera_frames, + "platform": "android", + }), + ); frames_since_keyframe = 0; } @@ -1639,9 +1857,37 @@ impl CallEngine { Ok(b) => b, Err(e) => { error!("video encode error (android): {e}"); + crate::emit_call_debug( + &vid_app, + "video:encode_error", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "camera_frames": camera_frames, + "error": e.to_string(), + "platform": "android", + }), + ); continue; } }; + if encoded.is_empty() { + empty_encodes += 1; + if empty_encodes == 1 || empty_encodes % 30 == 0 { + crate::emit_call_debug( + &vid_app, + "video:encode_empty", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "camera_frames": camera_frames, + "empty_encodes": empty_encodes, + "platform": "android", + }), + ); + } + continue; + } let is_keyframe = encoder.is_keyframe(&encoded); let ts_ms = vid_t0.elapsed().as_millis() as u32; @@ -1674,10 +1920,34 @@ impl CallEngine { } frames_since_keyframe += 1; } + crate::emit_call_debug( + &vid_app, + "video:sender_exit", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "camera_frames": camera_frames, + "empty_encodes": empty_encodes, + "platform": "android", + }), + ); info!("video send task exited (android)"); }); Some(tx) } else { + crate::emit_call_debug( + &app, + "video:send_disabled", + serde_json::json!({ + "t_ms": call_t0.elapsed().as_millis(), + "reason": if is_direct_p2p { + "direct_p2p_skips_relay_handshake" + } else { + "no_video_codec_negotiated" + }, + "platform": "android", + }), + ); None }; @@ -1795,6 +2065,14 @@ impl CallEngine { error!("perform_handshake failed: {e}"); e })?; + crate::emit_call_debug( + &_app, + "connect:handshake_done", + serde_json::json!({ + "t_ms": call_t0.elapsed().as_millis(), + "video_codec": hs.video_codec.map(|c| format!("{:?}", c)), + }), + ); info!(video_codec = ?hs.video_codec, "handshake complete"); drop(hs.session); (hs.video_codec, transport) @@ -1802,6 +2080,16 @@ impl CallEngine { info!("direct P2P — skipping relay handshake (QUIC TLS is the encryption layer)"); (None, transport) }; + crate::emit_call_debug( + &_app, + "video:negotiated", + serde_json::json!({ + "t_ms": call_t0.elapsed().as_millis(), + "codec": _negotiated_video_codec.map(|c| format!("{:?}", c)), + "enabled": _negotiated_video_codec.is_some(), + "direct_p2p": is_direct_p2p, + }), + ); info!("connected to relay, handshake complete"); event_cb("connected", &format!("joined room {room}")); @@ -2100,6 +2388,9 @@ impl CallEngine { let mut video_decoder: Option> = None; let mut video_decoder_codec: Option = None; let mut video_first_recv_logged_desktop = false; + let mut video_first_reassembled_logged = false; + let mut video_first_decoded_logged = false; + let mut video_decoder_buffering_count: u64 = 0; let mut decoded_frames: u64 = 0; let mut decode_errs: u64 = 0; let mut last_written: usize = 0; @@ -2136,16 +2427,60 @@ impl CallEngine { if let Some((codec_id, is_kf, frame)) = video_reassembler.push(&pkt) { + if !video_first_reassembled_logged { + video_first_reassembled_logged = true; + crate::emit_call_debug( + &recv_app, + "video:first_reassembled", + serde_json::json!({ + "t_ms": recv_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", codec_id), + "is_keyframe": is_kf, + "frame_bytes": frame.len(), + "platform": "desktop", + }), + ); + } // Lazy-init or switch decoder on codec change. if video_decoder_codec != Some(codec_id) { + crate::emit_call_debug( + &recv_app, + "video:decoder_init_start", + serde_json::json!({ + "t_ms": recv_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", codec_id), + "width": 1280, + "height": 720, + "platform": "desktop", + }), + ); match wzp_video::factory::create_video_decoder(codec_id, 1280, 720) { Ok(d) => { info!(codec = ?codec_id, "video decoder created"); + crate::emit_call_debug( + &recv_app, + "video:decoder_started", + serde_json::json!({ + "t_ms": recv_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", codec_id), + "platform": "desktop", + }), + ); video_decoder = Some(d); video_decoder_codec = Some(codec_id); } Err(e) => { error!("video decoder init failed: {e}"); + crate::emit_call_debug( + &recv_app, + "video:decoder_init_failed", + serde_json::json!({ + "t_ms": recv_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", codec_id), + "error": e.to_string(), + "platform": "desktop", + }), + ); } } } @@ -2160,6 +2495,37 @@ impl CallEngine { yuv_frame.width, yuv_frame.height, ); + let jpeg_ok = jpeg_b64.is_some(); + if !video_first_decoded_logged { + video_first_decoded_logged = true; + crate::emit_call_debug( + &recv_app, + "video:first_decoded_frame", + serde_json::json!({ + "t_ms": recv_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", codec_id), + "width": yuv_frame.width, + "height": yuv_frame.height, + "yuv_bytes": yuv_frame.data.len(), + "jpeg_ok": jpeg_ok, + "platform": "desktop", + }), + ); + } + if !jpeg_ok { + crate::emit_call_debug( + &recv_app, + "video:jpeg_encode_failed", + serde_json::json!({ + "t_ms": recv_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", codec_id), + "width": yuv_frame.width, + "height": yuv_frame.height, + "yuv_bytes": yuv_frame.data.len(), + "platform": "desktop", + }), + ); + } let _ = recv_app.emit( "video:frame", serde_json::json!({ @@ -2171,9 +2537,35 @@ impl CallEngine { }), ); } - Ok(None) => {} // decoder buffering — no output yet + Ok(None) => { + video_decoder_buffering_count += 1; + if video_decoder_buffering_count == 1 + || video_decoder_buffering_count % 30 == 0 + { + crate::emit_call_debug( + &recv_app, + "video:decoder_buffering", + serde_json::json!({ + "t_ms": recv_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", codec_id), + "buffering": video_decoder_buffering_count, + "platform": "desktop", + }), + ); + } + } Err(e) => { error!("video decode error: {e}"); + crate::emit_call_debug( + &recv_app, + "video:decode_error", + serde_json::json!({ + "t_ms": recv_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", codec_id), + "error": e.to_string(), + "platform": "desktop", + }), + ); } } } @@ -2387,19 +2779,77 @@ impl CallEngine { let vid_running = running.clone(); let vid_t0 = call_t0; let vid_app = _app.clone(); + crate::emit_call_debug( + &_app, + "video:sender_channel_ready", + serde_json::json!({ + "t_ms": call_t0.elapsed().as_millis(), + "codec": format!("{:?}", vid_codec), + "queue_depth": 4, + "platform": "desktop", + }), + ); tokio::spawn(async move { + crate::emit_call_debug( + &vid_app, + "video:encoder_init_start", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "width": 1280, + "height": 720, + "bitrate_bps": 1_500_000, + "platform": "desktop", + }), + ); let mut encoder = match wzp_video::factory::create_video_encoder( vid_codec, 1280, 720, 1_500_000, ) { - Ok(e) => e, + Ok(e) => { + crate::emit_call_debug( + &vid_app, + "video:encoder_started", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "platform": "desktop", + }), + ); + e + } Err(e) => { error!("video encoder init failed: {e}"); + crate::emit_call_debug( + &vid_app, + "video:encoder_init_failed", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "platform": "desktop", + "error": e.to_string(), + }), + ); return; } }; let mut seq: u32 = 0; let mut frames_since_keyframe: u32 = 0; let mut first_send_logged = false; + let mut first_camera_frame_logged = false; + let mut camera_frames: u64 = 0; + let mut empty_encodes: u64 = 0; + let mut wait_ticks: u64 = 0; + encoder.request_keyframe(); + crate::emit_call_debug( + &vid_app, + "video:keyframe_requested", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "reason": "initial", + "platform": "desktop", + }), + ); info!(codec = ?vid_codec, "video send task started"); while vid_running.load(Ordering::Relaxed) { let frame = match tokio::time::timeout( @@ -2408,13 +2858,58 @@ impl CallEngine { ) .await { - Ok(Some(f)) => f, + Ok(Some(f)) => { + wait_ticks = 0; + camera_frames += 1; + if !first_camera_frame_logged { + first_camera_frame_logged = true; + crate::emit_call_debug( + &vid_app, + "video:first_camera_frame", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "width": f.width, + "height": f.height, + "data_bytes": f.data.len(), + "platform": "desktop", + }), + ); + } + f + } Ok(None) => break, // sender dropped - Err(_) => continue, // no frame yet — keep looping + Err(_) => { + wait_ticks += 1; + if wait_ticks == 10 || wait_ticks % 50 == 0 { + crate::emit_call_debug( + &vid_app, + "video:waiting_for_camera_frames", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "wait_ms": wait_ticks * 200, + "codec": format!("{:?}", vid_codec), + "platform": "desktop", + }), + ); + } + continue; + } }; if frames_since_keyframe >= 150 { encoder.request_keyframe(); + crate::emit_call_debug( + &vid_app, + "video:keyframe_requested", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "reason": "periodic", + "camera_frames": camera_frames, + "platform": "desktop", + }), + ); frames_since_keyframe = 0; } @@ -2422,9 +2917,37 @@ impl CallEngine { Ok(b) => b, Err(e) => { error!("video encode error: {e}"); + crate::emit_call_debug( + &vid_app, + "video:encode_error", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "camera_frames": camera_frames, + "error": e.to_string(), + "platform": "desktop", + }), + ); continue; } }; + if encoded.is_empty() { + empty_encodes += 1; + if empty_encodes == 1 || empty_encodes % 30 == 0 { + crate::emit_call_debug( + &vid_app, + "video:encode_empty", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "camera_frames": camera_frames, + "empty_encodes": empty_encodes, + "platform": "desktop", + }), + ); + } + continue; + } let is_keyframe = encoder.is_keyframe(&encoded); let ts_ms = vid_t0.elapsed().as_millis() as u32; @@ -2457,10 +2980,34 @@ impl CallEngine { } frames_since_keyframe += 1; } + crate::emit_call_debug( + &vid_app, + "video:sender_exit", + serde_json::json!({ + "t_ms": vid_t0.elapsed().as_millis() as u64, + "codec": format!("{:?}", vid_codec), + "camera_frames": camera_frames, + "empty_encodes": empty_encodes, + "platform": "desktop", + }), + ); info!("video send task exited"); }); Some(tx) } else { + crate::emit_call_debug( + &_app, + "video:send_disabled", + serde_json::json!({ + "t_ms": call_t0.elapsed().as_millis(), + "reason": if is_direct_p2p { + "direct_p2p_skips_relay_handshake" + } else { + "no_video_codec_negotiated" + }, + "platform": "desktop", + }), + ); None }; diff --git a/desktop/src-tauri/src/lib.rs b/desktop/src-tauri/src/lib.rs index 69f8979..fba32f1 100644 --- a/desktop/src-tauri/src/lib.rs +++ b/desktop/src-tauri/src/lib.rs @@ -31,7 +31,7 @@ use engine::CallEngine; use serde::Serialize; use std::path::PathBuf; -use std::sync::atomic::{AtomicBool, Ordering}; +use std::sync::atomic::{AtomicBool, AtomicU64, Ordering}; use std::sync::{Arc, OnceLock}; use tauri::{Emitter, Manager}; use tokio::sync::Mutex; @@ -49,6 +49,11 @@ use wzp_proto::{MediaTransport, default_signal_version}; // Mirrors the existing `wzp_codec::dred_verbose_logs` pattern. static CALL_DEBUG_LOGS: AtomicBool = AtomicBool::new(false); +static CAMERA_PUSH_FRAMES: AtomicU64 = AtomicU64::new(0); +static CAMERA_PUSH_DROPS: AtomicU64 = AtomicU64::new(0); +static CAMERA_PUSH_NO_ENGINE: AtomicU64 = AtomicU64::new(0); +static CAMERA_PUSH_NO_SENDER: AtomicU64 = AtomicU64::new(0); +static CAMERA_PUSH_DECODE_ERRORS: AtomicU64 = AtomicU64::new(0); #[inline] fn call_debug_logs_enabled() -> bool { @@ -81,6 +86,18 @@ pub(crate) fn emit_call_debug(app: &tauri::AppHandle, step: &str, details: serde let _ = app.emit("call-debug-log", payload); } +#[tauri::command] +fn call_debug_log(app: tauri::AppHandle, step: String, details: serde_json::Value) { + if step == "camera:get_user_media_start" { + CAMERA_PUSH_FRAMES.store(0, Ordering::Relaxed); + CAMERA_PUSH_DROPS.store(0, Ordering::Relaxed); + CAMERA_PUSH_NO_ENGINE.store(0, Ordering::Relaxed); + CAMERA_PUSH_NO_SENDER.store(0, Ordering::Relaxed); + CAMERA_PUSH_DECODE_ERRORS.store(0, Ordering::Relaxed); + } + emit_call_debug(&app, &step, details); +} + /// Short git hash captured at compile time by build.rs. const GIT_HASH: &str = env!("WZP_GIT_HASH"); @@ -152,20 +169,66 @@ fn rgb_to_i420(rgb: &[u8], w: usize, h: usize) -> Vec { /// The frontend calls this at ~15 fps from a canvas.toDataURL() capture loop. #[tauri::command] async fn push_camera_frame( + app: tauri::AppHandle, state: tauri::State<'_, Arc>, jpeg_b64: String, ) -> Result<(), String> { use base64::Engine as _; - let jpeg_bytes = base64::engine::general_purpose::STANDARD - .decode(&jpeg_b64) - .map_err(|e| e.to_string())?; + let jpeg_bytes = match base64::engine::general_purpose::STANDARD.decode(&jpeg_b64) { + Ok(bytes) => bytes, + Err(e) => { + let errs = CAMERA_PUSH_DECODE_ERRORS.fetch_add(1, Ordering::Relaxed) + 1; + if errs == 1 || errs % 30 == 0 { + emit_call_debug( + &app, + "camera:jpeg_base64_decode_failed", + serde_json::json!({ + "errors": errs, + "error": e.to_string(), + "b64_len": jpeg_b64.len(), + }), + ); + } + return Err(e.to_string()); + } + }; - let dyn_img = image::load_from_memory_with_format(&jpeg_bytes, image::ImageFormat::Jpeg) - .map_err(|e| e.to_string())?; + let dyn_img = match image::load_from_memory_with_format(&jpeg_bytes, image::ImageFormat::Jpeg) { + Ok(img) => img, + Err(e) => { + let errs = CAMERA_PUSH_DECODE_ERRORS.fetch_add(1, Ordering::Relaxed) + 1; + if errs == 1 || errs % 30 == 0 { + emit_call_debug( + &app, + "camera:jpeg_decode_failed", + serde_json::json!({ + "errors": errs, + "error": e.to_string(), + "jpeg_bytes": jpeg_bytes.len(), + }), + ); + } + return Err(e.to_string()); + } + }; let rgb_img = dyn_img.to_rgb8(); let w = rgb_img.width() as usize; let h = rgb_img.height() as usize; let yuv = rgb_to_i420(rgb_img.as_raw(), w, h); + let frame_no = CAMERA_PUSH_FRAMES.fetch_add(1, Ordering::Relaxed) + 1; + if frame_no == 1 || frame_no % 150 == 0 { + emit_call_debug( + &app, + "camera:frame_received", + serde_json::json!({ + "frame_no": frame_no, + "width": w, + "height": h, + "jpeg_bytes": jpeg_bytes.len(), + "yuv_bytes": yuv.len(), + }), + ); + } let ts = std::time::SystemTime::now() .duration_since(std::time::UNIX_EPOCH) @@ -182,7 +245,52 @@ async fn push_camera_frame( let engine = state.engine.lock().await; if let Some(ref eng) = *engine { if let Some(ref tx) = eng.camera_tx { - let _ = tx.try_send(frame); // drop frame if send task is saturated + match tx.try_send(frame) { + Ok(()) => { + if frame_no == 1 || frame_no % 150 == 0 { + emit_call_debug( + &app, + "camera:frame_queued", + serde_json::json!({ "frame_no": frame_no }), + ); + } + } + Err(e) => { + let drops = CAMERA_PUSH_DROPS.fetch_add(1, Ordering::Relaxed) + 1; + if drops == 1 || drops % 30 == 0 { + emit_call_debug( + &app, + "camera:frame_drop", + serde_json::json!({ + "frame_no": frame_no, + "drops": drops, + "reason": e.to_string(), + }), + ); + } + } + } + } else { + let count = CAMERA_PUSH_NO_SENDER.fetch_add(1, Ordering::Relaxed) + 1; + if count == 1 || count % 150 == 0 { + emit_call_debug( + &app, + "camera:no_video_sender", + serde_json::json!({ + "count": count, + "hint": "video was not negotiated or the encoder task failed before camera_tx was installed", + }), + ); + } + } + } else { + let count = CAMERA_PUSH_NO_ENGINE.fetch_add(1, Ordering::Relaxed) + 1; + if count == 1 || count % 150 == 0 { + emit_call_debug( + &app, + "camera:no_call_engine", + serde_json::json!({ "count": count }), + ); } } Ok(()) @@ -3396,6 +3504,7 @@ pub fn run() { get_dred_verbose_logs, set_call_debug_logs, get_call_debug_logs, + call_debug_log, push_camera_frame, ]) .run(tauri::generate_context!()) diff --git a/desktop/src/main.ts b/desktop/src/main.ts index 348da70..7479cad 100644 --- a/desktop/src/main.ts +++ b/desktop/src/main.ts @@ -263,6 +263,10 @@ function renderCallDebugLog() { sCallDebugLogEl.scrollTop = sCallDebugLogEl.scrollHeight; } +function debugLog(step: string, details: any = {}) { + invoke("call_debug_log", { step, details }).catch(() => {}); +} + // ── Quality slider ──────────────────────────────────────────────── const QUALITY_STEPS = ["studio-64k", "studio-48k", "studio-32k", "auto", "good", "degraded", "codec2-3200", "catastrophic"]; const QUALITY_LABELS = ["Studio 64k", "Studio 48k", "Studio 32k", "Auto", "Opus 24k", "Opus 6k", "Codec2 3.2k", "Codec2 1.2k"]; @@ -488,14 +492,18 @@ vdSpkBtn.addEventListener("click", async () => { // ── Camera (Blocker 4 + 5) ──────────────────────────────────────── const camCaptureCanvas = document.createElement("canvas"); const camCaptureCtx = camCaptureCanvas.getContext("2d")!; +let cameraCaptureFrameNo = 0; +let cameraPushFailures = 0; async function startCamera() { if (cameraActive) return; + const constraints = { + video: { width: { ideal: 1280 }, height: { ideal: 720 }, facingMode: "user" }, + audio: false, + }; + debugLog("camera:get_user_media_start", { constraints }); try { - cameraStream = await navigator.mediaDevices.getUserMedia({ - video: { width: { ideal: 1280 }, height: { ideal: 720 }, facingMode: "user" }, - audio: false, - }); + cameraStream = await navigator.mediaDevices.getUserMedia(constraints); vdLocalVideo.srcObject = cameraStream; vdVideoStrip.classList.remove("hidden"); @@ -503,25 +511,61 @@ async function startCamera() { const settings = track.getSettings(); camCaptureCanvas.width = settings.width ?? 640; camCaptureCanvas.height = settings.height ?? 360; + debugLog("camera:get_user_media_ok", { + width: camCaptureCanvas.width, + height: camCaptureCanvas.height, + frameRate: settings.frameRate ?? null, + deviceId: settings.deviceId ? "present" : null, + facingMode: settings.facingMode ?? null, + }); cameraActive = true; + cameraCaptureFrameNo = 0; + cameraPushFailures = 0; vdCamIcon.textContent = "Cam ✓"; vdCamBtn.classList.add("active"); // Capture loop at ~15 fps cameraFrameTimer = window.setInterval(async () => { if (!cameraActive) return; - camCaptureCtx.drawImage(vdLocalVideo, 0, 0, camCaptureCanvas.width, camCaptureCanvas.height); - const dataUrl = camCaptureCanvas.toDataURL("image/jpeg", 0.75); - const b64 = dataUrl.slice(dataUrl.indexOf(",") + 1); - try { await invoke("push_camera_frame", { jpeg_b64: b64 }); } catch { /* call not active */ } + cameraCaptureFrameNo++; + try { + camCaptureCtx.drawImage(vdLocalVideo, 0, 0, camCaptureCanvas.width, camCaptureCanvas.height); + const dataUrl = camCaptureCanvas.toDataURL("image/jpeg", 0.75); + const b64 = dataUrl.slice(dataUrl.indexOf(",") + 1); + if (cameraCaptureFrameNo === 1 || cameraCaptureFrameNo % 150 === 0) { + debugLog("camera:capture_frame", { + frame_no: cameraCaptureFrameNo, + width: camCaptureCanvas.width, + height: camCaptureCanvas.height, + jpeg_b64_len: b64.length, + }); + } + await invoke("push_camera_frame", { jpegB64: b64 }); + } catch (e: any) { + cameraPushFailures++; + if (cameraPushFailures === 1 || cameraPushFailures % 30 === 0) { + debugLog("camera:push_failed", { + frame_no: cameraCaptureFrameNo, + failures: cameraPushFailures, + error: errorMessage(e), + }); + } + } }, 67); // 67 ms ≈ 15 fps - } catch (e) { + } catch (e: any) { console.warn("camera access denied or unavailable:", e); + debugLog("camera:get_user_media_failed", { + name: e?.name ?? null, + message: e?.message ?? String(e), + }); } } function stopCamera() { + if (cameraActive) { + debugLog("camera:stopped", { frames: cameraCaptureFrameNo }); + } cameraActive = false; if (cameraFrameTimer != null) { window.clearInterval(cameraFrameTimer); cameraFrameTimer = null; } if (cameraStream) { cameraStream.getTracks().forEach(t => t.stop()); cameraStream = null; }