diff --git a/ft8af/app/src/main/cpp/usb_audio_capture.cpp b/ft8af/app/src/main/cpp/usb_audio_capture.cpp index 1adb4b04..5e40457f 100644 --- a/ft8af/app/src/main/cpp/usb_audio_capture.cpp +++ b/ft8af/app/src/main/cpp/usb_audio_capture.cpp @@ -65,6 +65,12 @@ struct CaptureSession { std::thread eventThread; std::atomic running{false}; std::atomic inFlight{0}; + // Why the capture session ended, surfaced to Java via onCaptureStopped(code) + // and logged to debug.log. 0 = clean stop (nativeStop). Otherwise the first + // cause recorded wins (see recordStopReason / kStopReason* below): this is + // the diagnostic that pins down why iso capture retires ~100ms in on some + // host+adapter combos, which logcat's native tag doesn't reliably surface. + std::atomic stopReason{0}; // Anti-aliasing decimator: a windowed-sinc FIR low-pass + integer decimation, replacing // the old box-filter average. Configured with the real ratio in nativeStart. `monoScratch` @@ -147,6 +153,29 @@ void emitStopped(CaptureSession* s, int code) { // and feed them into the decimation accumulator. When the accumulator has // enough samples for a 12kHz block we emit a callback to Java. +// Stop-reason encoding, decoded by UsbAudioDevice.describeCaptureStopCode() on +// the Java side and written to debug.log. The bases keep the three failure +// families distinguishable while still carrying the underlying code: +// 1000 + libusb_transfer_status — a transfer completed with a terminal +// status and was not resubmitted (e.g. 1005 = NO_DEVICE, 1003 = +// CANCELLED, 1001 = ERROR). +// 2000 + (-libusb_error) — libusb_submit_transfer() refused to +// re-arm a transfer (e.g. 2005 = NO_DEVICE, 2001 = IO). +// 3000 + (-libusb_error) — libusb_handle_events() itself failed. +// 1 — all transfers retired with no specific +// terminal cause recorded (transient errors that stopped resubmitting). +constexpr int kStopReasonRetiredUnknown = 1; +constexpr int kStopReasonBaseTransferStatus = 1000; +constexpr int kStopReasonBaseResubmit = 2000; +constexpr int kStopReasonBaseHandleEvents = 3000; + +// Record why capture is ending — first cause wins, so the originating failure +// isn't overwritten by the teardown it triggers. +inline void recordStopReason(CaptureSession* s, int code) { + int expected = 0; + s->stopReason.compare_exchange_strong(expected, code); +} + void LIBUSB_CALL onTransferComplete(libusb_transfer* xfer) { auto* s = static_cast(xfer->user_data); @@ -162,6 +191,7 @@ void LIBUSB_CALL onTransferComplete(libusb_transfer* xfer) { // pumping; isochronous is best-effort by spec. if (xfer->status == LIBUSB_TRANSFER_NO_DEVICE || xfer->status == LIBUSB_TRANSFER_CANCELLED) { + recordStopReason(s, kStopReasonBaseTransferStatus + xfer->status); s->running.store(false, std::memory_order_release); s->inFlight.fetch_sub(1, std::memory_order_acq_rel); return; @@ -218,6 +248,7 @@ void LIBUSB_CALL onTransferComplete(libusb_transfer* xfer) { int rc = libusb_submit_transfer(xfer); if (rc != 0) { LOGW("libusb_submit_transfer failed: %s", libusb_error_name(rc)); + recordStopReason(s, kStopReasonBaseResubmit + (-rc)); s->running.store(false, std::memory_order_release); s->inFlight.fetch_sub(1, std::memory_order_acq_rel); } @@ -234,12 +265,15 @@ void eventLoop(CaptureSession* s) { int rc = libusb_handle_events_timeout_completed(s->ctx, &tv, nullptr); if (rc != 0 && rc != LIBUSB_ERROR_INTERRUPTED) { LOGW("libusb_handle_events failed: %s", libusb_error_name(rc)); + recordStopReason(s, kStopReasonBaseHandleEvents + (-rc)); break; } if (s->inFlight.load(std::memory_order_acquire) == 0) { // All transfers retired without being re-submitted (e.g., device - // gone). Exit cleanly so Java can fall back to mic. - LOGW("all transfers retired; ending capture"); + // gone). Exit cleanly so Java can decide whether to re-arm. + recordStopReason(s, kStopReasonRetiredUnknown); + LOGW("all transfers retired; ending capture (stopReason=%d)", + s->stopReason.load()); break; } } @@ -256,7 +290,9 @@ void eventLoop(CaptureSession* s) { libusb_handle_events_timeout_completed(s->ctx, &tv, nullptr); } - emitStopped(s, 0); + // Report why capture ended. 0 means running was cleared externally + // (nativeStop) with no transfer-level failure — a clean, requested stop. + emitStopped(s, s->stopReason.load()); } } // namespace diff --git a/ft8af/app/src/main/java/com/k1af/ft8af/wave/MicRecorder.java b/ft8af/app/src/main/java/com/k1af/ft8af/wave/MicRecorder.java index 47cc7331..aa967222 100644 --- a/ft8af/app/src/main/java/com/k1af/ft8af/wave/MicRecorder.java +++ b/ft8af/app/src/main/java/com/k1af/ft8af/wave/MicRecorder.java @@ -51,18 +51,26 @@ public class MicRecorder { private volatile int captureGeneration = 0; private static final long CAPTURE_JOIN_TIMEOUT_MS = 1000; - // USB-audio death-loop guard. On some hosts (notably car-dash Android - // tablets) UsbRequest.requestWait() returns null on first iteration and - // onCaptureStopped() fires immediately. Without this, MicRecorder would - // reinitialize() in a ~30ms-per-cycle tight loop. We rate-limit the - // self-rebind and after MAX_CONSECUTIVE_USB_FAILURES failed cycles give up - // on the raw USB path and fall back to AudioRecord+default mic so the app - // keeps running (read-only) instead of spinning the USB bus. + // USB-audio death-loop guard. A libusb-direct capture session can end + // prematurely two ways: (1) the host can't drive iso at all and it dies in + // ~10ms with no data (car-dash Android 11 tablets), or (2) it delivers a + // little audio then retires every iso transfer ~100ms in (Pixel 8 + C-Media + // 0D8C:0012 in the field). Both, left unguarded, make MicRecorder + // reinitialize() in a tight loop that freezes the waterfall and churns + // libusb_init/exit into a native crash. + // + // Guard: UsbCaptureRetryPolicy counts a session as failed when it saw no + // data OR stayed alive too briefly to be useful, and hands back an + // exponential, capped backoff. We keep retrying USB at that cadence and + // never silently switch to the phone's built-in mic — an operator wants + // radio audio or none. private long lastReinitMs = 0; private int consecutiveUsbFailures = 0; private volatile boolean usbAudioSawData = false; + // When the current USB capture session started, to measure how long it + // stayed alive (System.currentTimeMillis; 0 = no session started yet). + private volatile long usbCaptureStartMs = 0; private static final long MIN_REINIT_INTERVAL_MS = 2000; - private static final int MAX_CONSECUTIVE_USB_FAILURES = 3; static final int FALLBACK_BUFFER_SIZE = 4096; public interface OnDataListener{ @@ -229,12 +237,17 @@ public synchronized void start(){ private void startUsbCapture() { final MicRecorder self = this; usbAudioSawData = false; + usbCaptureStartMs = System.currentTimeMillis(); usbAudioDevice.startCapture(sampleRateInHz, new UsbAudioDevice.AudioInputCallback() { @Override public void onAudioData(float[] data, int length) { if (length > 0 && !usbAudioSawData) { usbAudioSawData = true; - consecutiveUsbFailures = 0; + // NB: do not reset consecutiveUsbFailures here. A session + // that dies right after delivering a few samples is still a + // failure (see UsbCaptureRetryPolicy); the tally is only + // reset in onCaptureStopped() when a session stayed alive + // long enough to be useful. GeneralVariables.fileLog( "startUsbCapture: first audio data received, " + "USB stream is live"); @@ -246,54 +259,57 @@ public void onAudioData(float[] data, int length) { @Override public void onCaptureStopped() { - // The USB audio capture loop exited without an explicit stop. - // Two distinct cases we need to handle differently: - // 1. Genuine device-gone / temporary glitch — rebind once, - // hope the next attempt sticks. - // 2. Host can't drive isochronous transfers and requestWait() - // returns null on the first iteration — capture dies in - // ~10ms. Without a guard, reinitialize -> open -> start -> - // die -> reinitialize... spins forever at ~30ms per cycle - // (saw this on a car-dash Android 11 tablet). - // Strategy: rate-limit to one reinit per MIN_REINIT_INTERVAL_MS, - // and after MAX_CONSECUTIVE_USB_FAILURES cycles without ever - // seeing audio data, force-fall-back to AudioRecord. The app - // can't transmit through USB then but at least stops thrashing. - if (!usbAudioSawData) { + // The libusb-direct capture session ended without an explicit + // stop. Decide whether it counts as a failure by how long it + // stayed alive: a session that dies before it can carry a + // fraction of an FT8 cycle is useless even if a few samples + // arrived first (the Pixel 8 + C-Media field mode: ~100ms of + // audio, then every iso transfer retires). The old rule only + // counted "no data at all", so that mode never tripped the tally + // and churned a fresh libusb_init/exit every 2s forever — the + // waterfall freeze, and the churn that raced libusb into a + // native SIGSEGV. + long now = System.currentTimeMillis(); + long aliveMs = now - usbCaptureStartMs; + boolean failure = UsbCaptureRetryPolicy.isFailure(usbAudioSawData, aliveMs); + if (failure) { consecutiveUsbFailures++; + } else { + consecutiveUsbFailures = 0; } - long now = System.currentTimeMillis(); - long sinceLast = now - lastReinitMs; GeneralVariables.fileLog(String.format( - "startUsbCapture: capture STOPPED (sawData=%b " - + "consecFailures=%d sinceLastReinit=%s)", - usbAudioSawData, consecutiveUsbFailures, - formatSinceReinit(now, lastReinitMs))); - - if (consecutiveUsbFailures >= MAX_CONSECUTIVE_USB_FAILURES - && !usbAudioSawData) { + "startUsbCapture: capture STOPPED (sawData=%b aliveMs=%d " + + "failure=%b consecFailures=%d)", + usbAudioSawData, aliveMs, failure, consecutiveUsbFailures)); + + // Exponential, capped backoff before the next attempt. We keep + // retrying USB and never silently switch to the phone's built-in + // mic — an operator wants radio audio or none. A persistently + // dead adapter is still retried at the cap in case it recovers, + // without spinning the bus or libusb global state. + long backoff = UsbCaptureRetryPolicy.backoffMs(consecutiveUsbFailures); + if (backoff > 0) { GeneralVariables.fileLog( - "startUsbCapture: giving up on raw USB after " - + consecutiveUsbFailures - + " failures, forcing fallback to AudioRecord"); - // Temporarily blank the USB selection so reinitialize() - // takes the AudioRecord branch instead of looping. - GeneralVariables.audioInputDeviceId = 0; - self.reinitialize(); - return; - } - - if (sinceLast < MIN_REINIT_INTERVAL_MS) { - GeneralVariables.fileLog( - "startUsbCapture: throttling reinit (last was " - + sinceLast + "ms ago)"); + "startUsbCapture: backing off " + backoff + + "ms before USB reinit (consecFailures=" + + consecutiveUsbFailures + ")"); try { - Thread.sleep(MIN_REINIT_INTERVAL_MS - sinceLast); + Thread.sleep(backoff); } catch (InterruptedException ignored) { Thread.currentThread().interrupt(); return; } } + + // A stop may have landed during the backoff (app teardown, or a + // real unplug already drove reinitialize elsewhere). Don't + // re-arm capture when we are no longer supposed to be running. + if (!isRunning) { + GeneralVariables.fileLog( + "startUsbCapture: not re-arming USB capture " + + "(isRunning=false)"); + return; + } lastReinitMs = System.currentTimeMillis(); self.reinitialize(); } diff --git a/ft8af/app/src/main/java/com/k1af/ft8af/wave/UsbAudioDevice.java b/ft8af/app/src/main/java/com/k1af/ft8af/wave/UsbAudioDevice.java index d51388b2..c8616073 100644 --- a/ft8af/app/src/main/java/com/k1af/ft8af/wave/UsbAudioDevice.java +++ b/ft8af/app/src/main/java/com/k1af/ft8af/wave/UsbAudioDevice.java @@ -536,7 +536,8 @@ public void onAudioData(float[] data, int length) { public void onCaptureStopped(int code) { com.k1af.ft8af.GeneralVariables.fileLog( "UsbAudioDevice: libusb capture stopped, " - + "code=" + code); + + "code=" + code + " (" + + describeCaptureStopCode(code) + ")"); nativeCaptureHandle = 0; capturing = false; if (javaCb != null) javaCb.onCaptureStopped(); @@ -972,6 +973,55 @@ public void close() { * *

Package-visible for testing. */ + /** + * Decodes the {@code onCaptureStopped(code)} reason set by the native capture + * event loop ({@code usb_audio_capture.cpp}, see {@code recordStopReason}) into + * a human-readable phrase for {@code debug.log}. This is the diagnostic that + * pins down why isochronous capture retires on a given host+adapter combo, + * which the native {@code ft8af_usb_capture} logcat tag does not reliably + * surface in the field. Encoding: + * + *

    + *
  • {@code 0} — clean stop (an explicit {@code nativeStop})
    • + *
  • {@code 1} — all transfers retired with no terminal cause recorded
    • + *
  • {@code 1000+status} — a transfer completed with terminal + * {@code libusb_transfer_status} (e.g. {@code 1005} = NO_DEVICE)
    • + *
  • {@code 2000+(-err)} — {@code libusb_submit_transfer} refused to + * re-arm a transfer (e.g. {@code 2004} = NO_DEVICE)
    • + *
  • {@code 3000+(-err)} — {@code libusb_handle_events} failed
    • + *
+ * + *

Package-visible for testing. + */ + static String describeCaptureStopCode(int code) { + if (code == 0) return "clean stop (nativeStop)"; + if (code == 1) return "all transfers retired (no terminal cause)"; + if (code >= 1000 && code < 2000) { + return "transfer terminal status " + transferStatusName(code - 1000); + } + if (code >= 2000 && code < 3000) { + return "resubmit failed: " + describeLibusbWriteError(-(code - 2000)); + } + if (code >= 3000 && code < 4000) { + return "handle_events failed: " + describeLibusbWriteError(-(code - 3000)); + } + return "unknown code"; + } + + /** {@code libusb_transfer_status} name. Package-visible for testing. */ + static String transferStatusName(int status) { + switch (status) { + case 0: return "COMPLETED"; + case 1: return "ERROR"; + case 2: return "TIMED_OUT"; + case 3: return "CANCELLED"; + case 4: return "STALL"; + case 5: return "NO_DEVICE"; + case 6: return "OVERFLOW"; + default: return "UNKNOWN(" + status + ")"; + } + } + static String describeLibusbWriteError(int rc) { String name; switch (rc) { diff --git a/ft8af/app/src/main/java/com/k1af/ft8af/wave/UsbCaptureRetryPolicy.java b/ft8af/app/src/main/java/com/k1af/ft8af/wave/UsbCaptureRetryPolicy.java new file mode 100644 index 00000000..0960b088 --- /dev/null +++ b/ft8af/app/src/main/java/com/k1af/ft8af/wave/UsbCaptureRetryPolicy.java @@ -0,0 +1,74 @@ +package com.k1af.ft8af.wave; + +/** + * Decides how {@link MicRecorder} reacts when a libusb-direct USB audio capture + * session ends unexpectedly. Pure logic, no Android types — unit-tested. + * + *

Answers two questions: + * + *

    + *
  1. Was the session a failure? A session that dies before it can + * carry even a fraction of a 15 s FT8 cycle is useless even if a + * handful of samples arrived first. That is the field failure mode on + * a Pixel 8 + C-Media adapter (VID:PID {@code 0D8C:0012}): every + * libusb session delivered ~100 ms of audio and then retired all its + * isochronous transfers ({@code code=0}). The old rule counted only + * "saw no data at all" as a failure, so that case never tripped + * the failure tally and churned a fresh {@code libusb_init}/{@code + * libusb_exit} every 2 s forever — the waterfall freeze, and the + * repeated init/exit that raced libusb into a native SIGSEGV.
    2. + *
  2. How long to wait before the next attempt? Exponential backoff so + * a persistently-failing device stops hammering the bus (and libusb global + * state), capped so a device that recovers is still picked back up. We + * never fall back to the phone's built-in microphone: an operator wants + * radio audio or none.
    3. + *
+ */ +public final class UsbCaptureRetryPolicy { + + private UsbCaptureRetryPolicy() {} + + /** + * A session alive for less than this was too short to be useful — under a + * third of a 15 s FT8 cycle, so it cannot have carried a decodable + * transmission no matter how many samples it briefly delivered. + */ + static final long MIN_USEFUL_SESSION_MS = 5_000; + + /** First backoff step. */ + static final long BASE_BACKOFF_MS = 2_000; + + /** + * Backoff ceiling. A persistently-dead adapter is still retried this often, + * in case it comes back (cable resettled, RF-desense cleared), without + * spinning the bus. + */ + static final long MAX_BACKOFF_MS = 60_000; + + /** + * Whether a finished capture session should count against the + * consecutive-failure tally. + * + * @param sawData whether any audio arrived during the session + * @param aliveMs how long the session ran before it stopped + */ + static boolean isFailure(boolean sawData, long aliveMs) { + if (!sawData) return true; + return aliveMs < MIN_USEFUL_SESSION_MS; + } + + /** + * Delay before the next USB reinit, given how many consecutive failures have + * occurred so far ({@code 1} = the first failure). Exponential + * (2 s, 4 s, 8 s, …) capped at {@link #MAX_BACKOFF_MS}. A + * non-positive count (a healthy session just reset the tally) yields no wait. + */ + static long backoffMs(int consecutiveFailures) { + if (consecutiveFailures <= 0) return 0; + // Cap the shift so the left-shift can't overflow before we clamp. + int shift = Math.min(consecutiveFailures - 1, 20); + long delay = BASE_BACKOFF_MS << shift; + if (delay <= 0 || delay > MAX_BACKOFF_MS) return MAX_BACKOFF_MS; + return delay; + } +} diff --git a/ft8af/app/src/test/java/com/k1af/ft8af/wave/UsbAudioWriteErrorTest.java b/ft8af/app/src/test/java/com/k1af/ft8af/wave/UsbAudioWriteErrorTest.java index 48ba94a8..befd3943 100644 --- a/ft8af/app/src/test/java/com/k1af/ft8af/wave/UsbAudioWriteErrorTest.java +++ b/ft8af/app/src/test/java/com/k1af/ft8af/wave/UsbAudioWriteErrorTest.java @@ -141,4 +141,61 @@ public void fallback_userCancelled_denied() { public void fallback_success_neverFallsBack() { assertThat(UsbAudioDevice.shouldFallbackToUsbRequest(0, 10)).isFalse(); } + + // ---- describeCaptureStopCode -------------------------------------------- + // The reason the native capture event loop ended, surfaced to debug.log so + // the iso-retire failure mode is diagnosable in the field. + + @Test + public void captureStop_cleanStop() { + assertThat(UsbAudioDevice.describeCaptureStopCode(0)) + .isEqualTo("clean stop (nativeStop)"); + } + + @Test + public void captureStop_retiredNoCause() { + assertThat(UsbAudioDevice.describeCaptureStopCode(1)) + .isEqualTo("all transfers retired (no terminal cause)"); + } + + @Test + public void captureStop_transferTerminalNoDevice() { + // 1000 + libusb_transfer_status(5=NO_DEVICE) + assertThat(UsbAudioDevice.describeCaptureStopCode(1005)) + .isEqualTo("transfer terminal status NO_DEVICE"); + } + + @Test + public void captureStop_transferTerminalStall() { + assertThat(UsbAudioDevice.describeCaptureStopCode(1004)) + .isEqualTo("transfer terminal status STALL"); + } + + @Test + public void captureStop_resubmitFailedNoDevice() { + // 2000 + (-LIBUSB_ERROR_NO_DEVICE=-(-4)=4) + assertThat(UsbAudioDevice.describeCaptureStopCode(2004)) + .isEqualTo("resubmit failed: rc=-4 NO_DEVICE"); + } + + @Test + public void captureStop_handleEventsFailedIo() { + // 3000 + (-LIBUSB_ERROR_IO=-(-1)=1) + assertThat(UsbAudioDevice.describeCaptureStopCode(3001)) + .isEqualTo("handle_events failed: rc=-1 IO"); + } + + @Test + public void captureStop_unknownCode() { + assertThat(UsbAudioDevice.describeCaptureStopCode(42)) + .isEqualTo("unknown code"); + } + + @Test + public void transferStatusName_maps() { + assertThat(UsbAudioDevice.transferStatusName(0)).isEqualTo("COMPLETED"); + assertThat(UsbAudioDevice.transferStatusName(5)).isEqualTo("NO_DEVICE"); + assertThat(UsbAudioDevice.transferStatusName(6)).isEqualTo("OVERFLOW"); + assertThat(UsbAudioDevice.transferStatusName(9)).isEqualTo("UNKNOWN(9)"); + } } diff --git a/ft8af/app/src/test/java/com/k1af/ft8af/wave/UsbCaptureRetryPolicyTest.java b/ft8af/app/src/test/java/com/k1af/ft8af/wave/UsbCaptureRetryPolicyTest.java new file mode 100644 index 00000000..cde4233f --- /dev/null +++ b/ft8af/app/src/test/java/com/k1af/ft8af/wave/UsbCaptureRetryPolicyTest.java @@ -0,0 +1,61 @@ +package com.k1af.ft8af.wave; + +import static com.google.common.truth.Truth.assertThat; + +import org.junit.Test; + +/** Pure-JVM tests for {@link UsbCaptureRetryPolicy}. */ +public class UsbCaptureRetryPolicyTest { + + @Test + public void isFailure_noDataEver_isFailure() { + // The car-dash case: requestWait/iso dies immediately, no samples. + assertThat(UsbCaptureRetryPolicy.isFailure(false, 0)).isTrue(); + assertThat(UsbCaptureRetryPolicy.isFailure(false, 10_000)).isTrue(); + } + + @Test + public void isFailure_sawDataButDiedTooQuickly_isFailure() { + // The Pixel 8 + C-Media field case: a little audio, then all transfers + // retire ~100ms in. Must count as a failure so the churn breaks. + assertThat(UsbCaptureRetryPolicy.isFailure(true, 100)).isTrue(); + assertThat(UsbCaptureRetryPolicy.isFailure( + true, UsbCaptureRetryPolicy.MIN_USEFUL_SESSION_MS - 1)).isTrue(); + } + + @Test + public void isFailure_sawDataAndStayedAlive_isNotFailure() { + assertThat(UsbCaptureRetryPolicy.isFailure( + true, UsbCaptureRetryPolicy.MIN_USEFUL_SESSION_MS)).isFalse(); + assertThat(UsbCaptureRetryPolicy.isFailure(true, 60_000)).isFalse(); + } + + @Test + public void backoff_isExponential() { + assertThat(UsbCaptureRetryPolicy.backoffMs(1)) + .isEqualTo(UsbCaptureRetryPolicy.BASE_BACKOFF_MS); // 2s + assertThat(UsbCaptureRetryPolicy.backoffMs(2)) + .isEqualTo(UsbCaptureRetryPolicy.BASE_BACKOFF_MS * 2); // 4s + assertThat(UsbCaptureRetryPolicy.backoffMs(3)) + .isEqualTo(UsbCaptureRetryPolicy.BASE_BACKOFF_MS * 4); // 8s + assertThat(UsbCaptureRetryPolicy.backoffMs(4)) + .isEqualTo(UsbCaptureRetryPolicy.BASE_BACKOFF_MS * 8); // 16s + } + + @Test + public void backoff_isCappedAndNeverOverflows() { + assertThat(UsbCaptureRetryPolicy.backoffMs(10)) + .isEqualTo(UsbCaptureRetryPolicy.MAX_BACKOFF_MS); + // A pathological count must not overflow the shift into a negative/huge delay. + assertThat(UsbCaptureRetryPolicy.backoffMs(1000)) + .isEqualTo(UsbCaptureRetryPolicy.MAX_BACKOFF_MS); + assertThat(UsbCaptureRetryPolicy.backoffMs(Integer.MAX_VALUE)) + .isEqualTo(UsbCaptureRetryPolicy.MAX_BACKOFF_MS); + } + + @Test + public void backoff_nonPositiveCount_isZero() { + assertThat(UsbCaptureRetryPolicy.backoffMs(0)).isEqualTo(0); + assertThat(UsbCaptureRetryPolicy.backoffMs(-5)).isEqualTo(0); + } +}