diag(android-audio): aggressive logging across the whole Oboe pipeline
Some checks failed
Mirror to GitHub / mirror (push) Failing after 40s
Build Release Binaries / build-amd64 (push) Failing after 3m46s

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.
This commit is contained in:
Siavash Sameni
2026-04-09 21:13:29 +04:00
parent 8c4d640f89
commit 96be740fd9
3 changed files with 178 additions and 1 deletions

View File

@@ -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();
}
}
});