diag(android-audio): aggressive logging across the whole Oboe pipeline

User confirmed: mac hears android, android does not hear mac. So Oboe
capture works end-to-end but Oboe playout on Android silently drops
audio even though QUIC forwards the packets. Archaeology on the legacy
wzp-android crate also revealed that the "last known good" Android audio
path NEVER used Oboe in production — it used Kotlin AudioRecord +
AudioTrack via JNI, and cpp/oboe_bridge.cpp was dead code. So every time
we've "tested" Oboe end-to-end this week was the first production use,
and any of its config knobs could be the bug.

Instrumenting every stage of the pipeline so one smoke-test log dump can
isolate the layer at fault:

C++ (oboe_bridge.cpp)
  - Log the ACTUAL stream parameters after openStream for both capture
    and playout (sample rate, channels, format, framesPerBurst,
    framesPerDataCallback, bufferCapacityInFrames, sharing, perf mode).
    Oboe may silently override values we requested — e.g. if we ask for
    48kHz mono but the device gives us 44.1kHz stereo our 960-sample
    frames are the wrong duration and the pipeline drifts.
  - Capture callback: on cb#0 log sample range+RMS of the first frame
    to prove we get real mic data (not zeros). Every 50 callbacks
    (~1s at 20ms burst) log calls, numFrames, ring available_write,
    bytes actually written, ring_full_drops, total_written.
  - Playout callback: on cb#0 log numFrames + ring state. On the FIRST
    non-empty read log sample range+RMS so we can tell if the samples
    coming out of the ring are real audio or zeros. Every 50 callbacks
    log calls, nonempty count, numFrames, ring available_read,
    underrun_frames, total_played_real.

Rust wzp-native (src/lib.rs)
  - wzp_native_audio_write_playout now logs the first 3 writes and then
    every 50th: in_len, written, sample range, RMS, ring write/read
    cursors before, available_read and available_write after. Reveals
    ring-overflow and whether the engine is actually handing us audio.
  - Minimal android logcat shim via __android_log_write extern — no
    new crate dependency.
  - AudioBackend grows a `playout_write_log_count` AtomicU64 to gate
    the write-side log throttle.

Rust engine.rs (android branch)
  - Recv task: log sample range + RMS for the first 3 decoded PCM
    frames and then every 100th. Reveals whether decoder.decode is
    producing real audio or silent buffers.
  - Recv task: if audio_write_playout returns fewer samples than we
    handed it (partial write → ring nearly full) warn about it in the
    first 10 frames.
  - Recv heartbeat every 2s: recv_fr, decoded_frames, last_decode_n,
    last_written, written_samples, decode_errs, codec.

Expected flow in a healthy log:
  capture cb#0: numFrames=960 range=[-1200..900] rms=180          ← mic OK
  capture stream opened: actualSR=48000 Ch=1 ...                   ← no override
  playout stream opened: actualSR=48000 Ch=1 ...
  CallEngine::start invoked ... → connected → audio started
  recv: first media packet received ...
  recv: decoded PCM sample range decoded_frames=1 range=[-300..250] rms=92
  playout WRITE #0: in_len=960 written=960 range=[-300..250] rms=92
  playout FIRST nonempty read: to_read=960 range=[-300..250] rms=92
  playout heartbeat: calls=50 nonempty=50 underrun=0 ...
  recv heartbeat: decoded_frames=100 last_written=960 ...

If any of those are missing/zero we know the exact stage to fix.

crates/wzp-native/cpp/oboe_bridge.cpp

@@ -83,6 +83,11 @@ static std::atomic<float> g_playout_latency_ms{0.0f};
 
 class CaptureCallback : public oboe::AudioStreamDataCallback {
 public:
+    uint64_t calls = 0;
+    uint64_t total_frames = 0;
+    uint64_t total_written = 0;
+    uint64_t ring_full_drops = 0;
+
     oboe::DataCallbackResult onAudioReady(
             oboe::AudioStream* stream,
             void* audioData,
@@ -102,6 +107,32 @@ public:
                        g_rings.capture_write_idx, g_rings.capture_read_idx,
                        src, to_write);
         }
+        total_frames += numFrames;
+        total_written += to_write;
+        if (to_write < numFrames) {
+            ring_full_drops += (numFrames - to_write);
+        }
+
+        // Sample-range probe on the FIRST callback to prove we get real audio
+        if (calls == 0 && numFrames > 0) {
+            int16_t lo = src[0], hi = src[0];
+            int32_t sumsq = 0;
+            for (int32_t i = 0; i < numFrames; i++) {
+                if (src[i] < lo) lo = src[i];
+                if (src[i] > hi) hi = src[i];
+                sumsq += (int32_t)src[i] * (int32_t)src[i];
+            }
+            int32_t rms = (int32_t) (numFrames > 0 ? (int32_t)__builtin_sqrt((double)sumsq / (double)numFrames) : 0);
+            LOGI("capture cb#0: numFrames=%d sample_range=[%d..%d] rms=%d to_write=%d",
+                 numFrames, lo, hi, rms, to_write);
+        }
+        // Heartbeat every 50 callbacks (~1s at 20ms/burst)
+        calls++;
+        if ((calls % 50) == 0) {
+            LOGI("capture heartbeat: calls=%llu numFrames=%d ring_avail_write=%d to_write=%d full_drops=%llu total_written=%llu",
+                 (unsigned long long)calls, numFrames, avail, to_write,
+                 (unsigned long long)ring_full_drops, (unsigned long long)total_written);
+        }
 
         // Update latency estimate
         auto result = stream->calculateLatencyMillis();
@@ -120,6 +151,12 @@ public:
 
 class PlayoutCallback : public oboe::AudioStreamDataCallback {
 public:
+    uint64_t calls = 0;
+    uint64_t total_frames = 0;
+    uint64_t total_played_real = 0;
+    uint64_t underrun_frames = 0;
+    uint64_t nonempty_calls = 0;
+
     oboe::DataCallbackResult onAudioReady(
             oboe::AudioStream* stream,
             void* audioData,
@@ -140,10 +177,43 @@ public:
             ring_read(g_rings.playout_buf, g_rings.playout_capacity,
                       g_rings.playout_write_idx, g_rings.playout_read_idx,
                       dst, to_read);
+            nonempty_calls++;
         }
         // Fill remainder with silence on underrun
         if (to_read < numFrames) {
             memset(dst + to_read, 0, (numFrames - to_read) * sizeof(int16_t));
+            underrun_frames += (numFrames - to_read);
+        }
+        total_frames += numFrames;
+        total_played_real += to_read;
+
+        // First callback: log requested config + prove we're being called
+        if (calls == 0) {
+            LOGI("playout cb#0: numFrames=%d ring_avail_read=%d to_read=%d",
+                 numFrames, avail, to_read);
+        }
+        // On the first callback that actually has data, log the sample range
+        // so we can tell if the samples coming out of the ring look like real
+        // audio vs constant-zeroes vs garbage.
+        if (to_read > 0 && nonempty_calls == 1) {
+            int16_t lo = dst[0], hi = dst[0];
+            int32_t sumsq = 0;
+            for (int32_t i = 0; i < to_read; i++) {
+                if (dst[i] < lo) lo = dst[i];
+                if (dst[i] > hi) hi = dst[i];
+                sumsq += (int32_t)dst[i] * (int32_t)dst[i];
+            }
+            int32_t rms = (to_read > 0) ? (int32_t)__builtin_sqrt((double)sumsq / (double)to_read) : 0;
+            LOGI("playout FIRST nonempty read: to_read=%d sample_range=[%d..%d] rms=%d",
+                 to_read, lo, hi, rms);
+        }
+        // Heartbeat every 50 callbacks (~1s at 20ms/burst)
+        calls++;
+        if ((calls % 50) == 0) {
+            LOGI("playout heartbeat: calls=%llu nonempty=%llu numFrames=%d ring_avail_read=%d to_read=%d underrun_frames=%llu total_played_real=%llu",
+                 (unsigned long long)calls, (unsigned long long)nonempty_calls,
+                 numFrames, avail, to_read,
+                 (unsigned long long)underrun_frames, (unsigned long long)total_played_real);
         }
 
         // Update latency estimate
@@ -193,6 +263,15 @@ int wzp_oboe_start(const WzpOboeConfig* config, const WzpOboeRings* rings) {
         LOGE("Failed to open capture stream: %s", oboe::convertToText(result));
         return -2;
     }
+    LOGI("capture stream opened: actualSR=%d actualCh=%d actualFormat=%d actualFramesPerBurst=%d actualFramesPerDataCallback=%d bufferCapacityInFrames=%d sharing=%d perfMode=%d",
+         g_capture_stream->getSampleRate(),
+         g_capture_stream->getChannelCount(),
+         (int)g_capture_stream->getFormat(),
+         g_capture_stream->getFramesPerBurst(),
+         g_capture_stream->getFramesPerDataCallback(),
+         g_capture_stream->getBufferCapacityInFrames(),
+         (int)g_capture_stream->getSharingMode(),
+         (int)g_capture_stream->getPerformanceMode());
 
     // Build playout stream
     //
@@ -224,6 +303,15 @@ int wzp_oboe_start(const WzpOboeConfig* config, const WzpOboeRings* rings) {
         g_capture_stream.reset();
         return -3;
     }
+    LOGI("playout stream opened: actualSR=%d actualCh=%d actualFormat=%d actualFramesPerBurst=%d actualFramesPerDataCallback=%d bufferCapacityInFrames=%d sharing=%d perfMode=%d",
+         g_playout_stream->getSampleRate(),
+         g_playout_stream->getChannelCount(),
+         (int)g_playout_stream->getFormat(),
+         g_playout_stream->getFramesPerBurst(),
+         g_playout_stream->getFramesPerDataCallback(),
+         g_playout_stream->getBufferCapacityInFrames(),
+         (int)g_playout_stream->getSharingMode(),
+         (int)g_playout_stream->getPerformanceMode());
 
     g_running.store(true, std::memory_order_release);
 

crates/wzp-native/src/lib.rs

@@ -172,6 +172,8 @@ struct AudioBackend {
     capture: RingBuffer,
     playout: RingBuffer,
     started: std::sync::Mutex<bool>,
+    /// Per-write logging throttle counter for wzp_native_audio_write_playout.
+    playout_write_log_count: std::sync::atomic::AtomicU64,
 }
 
 static BACKEND: OnceLock<&'static AudioBackend> = OnceLock::new();
@@ -182,6 +184,7 @@ fn backend() -> &'static AudioBackend {
             capture: RingBuffer::new(RING_CAPACITY),
             playout: RingBuffer::new(RING_CAPACITY),
             started: std::sync::Mutex::new(false),
+            playout_write_log_count: std::sync::atomic::AtomicU64::new(0),
         }))
     })
 }
@@ -258,9 +261,56 @@ pub unsafe extern "C" fn wzp_native_audio_write_playout(input: *const i16, in_le
         return 0;
     }
     let slice = unsafe { std::slice::from_raw_parts(input, in_len) };
-    backend().playout.write(slice)
+    let b = backend();
+    let before_w = b.playout.write_idx.load(std::sync::atomic::Ordering::Relaxed);
+    let before_r = b.playout.read_idx.load(std::sync::atomic::Ordering::Relaxed);
+    let written = b.playout.write(slice);
+    // First few writes: log ring state + sample range so we can compare what
+    // engine.rs hands us to what the C++ playout callback reads.
+    let first_writes = b.playout_write_log_count.fetch_add(1, std::sync::atomic::Ordering::Relaxed);
+    if first_writes < 3 || first_writes % 50 == 0 {
+        let (mut lo, mut hi, mut sumsq) = (i16::MAX, i16::MIN, 0i64);
+        for &s in slice.iter() {
+            if s < lo { lo = s; }
+            if s > hi { hi = s; }
+            sumsq += (s as i64) * (s as i64);
+        }
+        let rms = (sumsq as f64 / slice.len() as f64).sqrt() as i32;
+        let avail_w_after = b.playout.available_write();
+        let avail_r_after = b.playout.available_read();
+        let msg = format!(
+            "playout WRITE #{first_writes}: in_len={} written={} range=[{lo}..{hi}] rms={rms} before_w={before_w} before_r={before_r} avail_read_after={avail_r_after} avail_write_after={avail_w_after}",
+            slice.len(), written
+        );
+        unsafe {
+            android_log(msg.as_str());
+        }
+    }
+    written
 }
 
+// Minimal android logcat shim so we can print from the cdylib without pulling
+// in android_logger crate (which would add another dep that has to build with
+// cargo-ndk). Uses libc's __android_log_print via extern linkage.
+#[cfg(target_os = "android")]
+unsafe extern "C" {
+    fn __android_log_write(prio: i32, tag: *const u8, text: *const u8) -> i32;
+}
+
+#[cfg(target_os = "android")]
+unsafe fn android_log(msg: &str) {
+    // ANDROID_LOG_INFO = 4. Tag and text must be NUL-terminated.
+    let tag = b"wzp-native\0";
+    let mut buf = Vec::with_capacity(msg.len() + 1);
+    buf.extend_from_slice(msg.as_bytes());
+    buf.push(0);
+    unsafe { __android_log_write(4, tag.as_ptr(), buf.as_ptr()); }
+}
+
+#[cfg(not(target_os = "android"))]
+#[allow(dead_code)]
+unsafe fn android_log(_msg: &str) {}
+
 /// Current capture latency reported by Oboe, in milliseconds. Returns
 /// NaN / 0.0 if the stream isn't running.
 #[unsafe(no_mangle)]

desktop/src-tauri/src/engine.rs

@@ -351,11 +351,34 @@ impl CallEngine {
                                 Ok(n) => {
                                     last_decode_n = n;
                                     decoded_frames += 1;
+                                    // Log sample range for the first few decoded frames and periodically
+                                    if decoded_frames <= 3 || decoded_frames % 100 == 0 {
+                                        let slice = &pcm[..n];
+                                        let (mut lo, mut hi, mut sumsq) = (i16::MAX, i16::MIN, 0i64);
+                                        for &s in slice.iter() {
+                                            if s < lo { lo = s; }
+                                            if s > hi { hi = s; }
+                                            sumsq += (s as i64) * (s as i64);
+                                        }
+                                        let rms = (sumsq as f64 / n as f64).sqrt() as i32;
+                                        info!(
+                                            decoded_frames,
+                                            n,
+                                            sample_lo = lo,
+                                            sample_hi = hi,
+                                            rms,
+                                            codec = ?current_codec,
+                                            "recv: decoded PCM sample range"
+                                        );
+                                    }
                                     agc.process_frame(&mut pcm[..n]);
                                     if !recv_spk.load(Ordering::Relaxed) {
                                         let w = crate::wzp_native::audio_write_playout(&pcm[..n]);
                                         last_written = w;
                                         written_samples = written_samples.saturating_add(w as u64);
+                                        if w < n && decoded_frames <= 10 {
+                                            tracing::warn!(n, w, "recv: partial playout write (ring nearly full)");
+                                        }
                                     }
                                 }
                                 Err(e) => {
@@ -378,6 +401,22 @@ impl CallEngine {
                     }
                     Err(_) => {}
                 }
+
+                // Heartbeat every 2s with decode+playout state
+                if heartbeat.elapsed() >= std::time::Duration::from_secs(2) {
+                    let fr = recv_fr.load(Ordering::Relaxed);
+                    info!(
+                        recv_fr = fr,
+                        decoded_frames,
+                        last_decode_n,
+                        last_written,
+                        written_samples,
+                        decode_errs,
+                        codec = ?current_codec,
+                        "recv heartbeat (android)"
+                    );
+                    heartbeat = std::time::Instant::now();
+                }
             }
         });