From be8dd0a3bc1e4fb06fd2b9f21b17448c5ff2e50f Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 5 May 2026 15:56:47 +0000 Subject: [PATCH] debug(nests): add playback-path logs to localise receiver silence The wire is healthy: drainOneGroup logs show every group reaching the receiver with 5 frames each, no drops, no parse errors, no pump exits, no announce-ended teardown. Yet the green ring on the receiver still blinks-and-stops. The bug must be in the playback pipeline below drainOneGroup. Add NestPlay-tagged logs there so the next repro identifies whether the failure is decoder, AudioTrack allocation, beginPlayback, or write-blocking. NestPlayer.play (`NestPlay` tag): - log start with prerollFrames - log preroll flush + beginPlayback transition - throttled per-N counters: receivedObjects / decodedFrames / emptyDecodes / enqueued - log decoder.decode throws explicitly - log empty-pcm decoder returns (separate from throws) - log enqueue duration when > 50 ms (catches AudioTrack.write-blocking) - log flow COMPLETED / cancelled / pipeline threw with final counts AudioTrackPlayer (`NestPlay` tag): - log start() + the constructed AudioTrack's state / playState / bufferSizeBytes / minBuffer - log beginPlayback's t.play() return + post-call state - log AudioTrack.write partial / error returns - log setMuted / setVolume changes (silent mute is a known suspect for "audio not playing") MediaCodecOpusDecoder (`NestPlay` tag): - log codec name on successful allocation - log allocation failure with exception type / message All log calls use the lambda overload so format work only runs when the tag is enabled. Throttled counters keep logcat at < 1 line/sec per speaker even at 50 fps capture cadence. --- .../nestsclient/audio/AudioTrackPlayer.kt | 24 ++++++++ .../audio/MediaCodecOpusDecoder.kt | 17 ++++-- .../nestsclient/audio/NestPlayer.kt | 58 ++++++++++++++++++- 3 files changed, 94 insertions(+), 5 deletions(-) diff --git a/nestsClient/src/androidMain/kotlin/com/vitorpamplona/nestsclient/audio/AudioTrackPlayer.kt b/nestsClient/src/androidMain/kotlin/com/vitorpamplona/nestsclient/audio/AudioTrackPlayer.kt index 8434263ea..dfd2eaa6e 100644 --- a/nestsClient/src/androidMain/kotlin/com/vitorpamplona/nestsclient/audio/AudioTrackPlayer.kt +++ b/nestsClient/src/androidMain/kotlin/com/vitorpamplona/nestsclient/audio/AudioTrackPlayer.kt @@ -96,6 +96,8 @@ class AudioTrackPlayer( override fun start() { if (track != null) return + com.vitorpamplona.quartz.utils.Log + .d("NestPlay") { "AudioTrackPlayer.start() — allocating AudioTrack" } val channelMask = when (AudioFormat.CHANNELS) { @@ -178,6 +180,10 @@ class AudioTrackPlayer( audioExecutor = executor audioDispatcher = executor.asCoroutineDispatcher() track = newTrack + com.vitorpamplona.quartz.utils.Log.d("NestPlay") { + "AudioTrack allocated: state=${newTrack.state} playState=${newTrack.playState} " + + "bufferSizeBytes=$bufferBytes minBuffer=$minBuffer sampleRate=${AudioFormat.SAMPLE_RATE_HZ}" + } } override fun beginPlayback() { @@ -189,12 +195,18 @@ class AudioTrackPlayer( val t = track ?: return try { t.play() + com.vitorpamplona.quartz.utils.Log.d("NestPlay") { + "AudioTrack.play() returned, state=${t.playState} bufferSize=${t.bufferSizeInFrames} muted=$muted volume=$volume" + } } catch (e: Throwable) { // PLAY-on-uninitialized AudioTrack is the only realistic // failure here, and we already guard against an unallocated // track above. Throw so [NestPlayer]'s outer catch surfaces // it via `onError(AudioException.PlaybackFailed)` — same path // that handles every other mid-stream device failure. + com.vitorpamplona.quartz.utils.Log.w("NestPlay") { + "AudioTrack.play() threw: ${e::class.simpleName}: ${e.message}" + } throw AudioException( AudioException.Kind.DeviceUnavailable, "AudioTrack.play() rejected start", @@ -215,21 +227,33 @@ class AudioTrackPlayer( withContext(dispatcher) { val written = t.write(pcm, 0, pcm.size, AudioTrack.WRITE_BLOCKING) if (written < 0) { + com.vitorpamplona.quartz.utils.Log.w("NestPlay") { + "AudioTrack.write returned error $written (state=${t.playState})" + } throw AudioException( AudioException.Kind.PlaybackFailed, "AudioTrack.write returned error code $written", ) } + if (written != pcm.size) { + com.vitorpamplona.quartz.utils.Log.w("NestPlay") { + "AudioTrack.write partial: requested=${pcm.size} written=$written" + } + } } } override fun setMuted(muted: Boolean) { this.muted = muted + com.vitorpamplona.quartz.utils.Log + .d("NestPlay") { "AudioTrackPlayer.setMuted($muted) volume=$volume" } track?.let { applyMuteVolume(it) } } override fun setVolume(volume: Float) { this.volume = volume.coerceIn(0f, 1f) + com.vitorpamplona.quartz.utils.Log + .d("NestPlay") { "AudioTrackPlayer.setVolume($volume) muted=$muted" } track?.let { applyMuteVolume(it) } } diff --git a/nestsClient/src/androidMain/kotlin/com/vitorpamplona/nestsclient/audio/MediaCodecOpusDecoder.kt b/nestsClient/src/androidMain/kotlin/com/vitorpamplona/nestsclient/audio/MediaCodecOpusDecoder.kt index 5f044d508..c656a5d07 100644 --- a/nestsClient/src/androidMain/kotlin/com/vitorpamplona/nestsclient/audio/MediaCodecOpusDecoder.kt +++ b/nestsClient/src/androidMain/kotlin/com/vitorpamplona/nestsclient/audio/MediaCodecOpusDecoder.kt @@ -38,11 +38,20 @@ import java.nio.ByteOrder class MediaCodecOpusDecoder : OpusDecoder { private val codec: MediaCodec = try { - MediaCodec.createDecoderByType(MediaFormat.MIMETYPE_AUDIO_OPUS).apply { - configure(buildFormat(), null, null, 0) - start() - } + MediaCodec + .createDecoderByType(MediaFormat.MIMETYPE_AUDIO_OPUS) + .apply { + configure(buildFormat(), null, null, 0) + start() + }.also { + com.vitorpamplona.quartz.utils.Log.d("NestPlay") { + "MediaCodecOpusDecoder allocated codec='${it.name}'" + } + } } catch (t: Throwable) { + com.vitorpamplona.quartz.utils.Log.w("NestPlay") { + "MediaCodec audio/opus decoder allocation FAILED: ${t::class.simpleName}: ${t.message}" + } throw AudioException( AudioException.Kind.DeviceUnavailable, "Failed to allocate MediaCodec audio/opus decoder", diff --git a/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/audio/NestPlayer.kt b/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/audio/NestPlayer.kt index fe641b994..d70137cbf 100644 --- a/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/audio/NestPlayer.kt +++ b/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/audio/NestPlayer.kt @@ -122,6 +122,15 @@ class NestPlayer( scope.launch { val preroll = ArrayDeque(prerollFrames.coerceAtLeast(1)) var playbackBegun = false + // Diagnostic counters: at 50 fps a per-frame log floods logcat; + // throttle to every Nth event. + var receivedObjects: Long = 0L + var decodedFrames: Long = 0L + var emptyDecodes: Long = 0L + var enqueued: Long = 0L + com.vitorpamplona.quartz.utils.Log.d("NestPlay") { + "NestPlayer.play started (prerollFrames=$prerollFrames)" + } suspend fun beginAndFlushIfNeeded() { if (playbackBegun) return @@ -137,20 +146,34 @@ class NestPlayer( // hardware starts pulling samples; getting // [enqueue] in first means the very first sample // pulled is from our pre-rolled audio, not silence. + com.vitorpamplona.quartz.utils.Log.d("NestPlay") { + "NestPlayer flushing preroll (${preroll.size} frames) → beginPlayback" + } while (preroll.isNotEmpty()) { player.enqueue(preroll.removeFirst()) } player.beginPlayback() playbackBegun = true + com.vitorpamplona.quartz.utils.Log + .d("NestPlay") { "NestPlayer beginPlayback returned" } } try { objects.collect { obj -> + receivedObjects += 1 + if (receivedObjects % PLAY_LOG_THROTTLE == 0L) { + com.vitorpamplona.quartz.utils.Log.d("NestPlay") { + "NestPlayer received obj #$receivedObjects (decoded=$decodedFrames empty=$emptyDecodes enqueued=$enqueued playbackBegun=$playbackBegun)" + } + } val pcm = try { decoder.decode(obj.payload) } catch (ce: CancellationException) { throw ce } catch (t: Throwable) { + com.vitorpamplona.quartz.utils.Log.w("NestPlay") { + "decoder.decode threw on obj #$receivedObjects: ${t::class.simpleName}: ${t.message}" + } onError( AudioException( AudioException.Kind.DecoderError, @@ -160,10 +183,26 @@ class NestPlayer( ) return@collect } - if (pcm.isNotEmpty()) { + if (pcm.isEmpty()) { + emptyDecodes += 1 + if (emptyDecodes % PLAY_LOG_THROTTLE == 0L) { + com.vitorpamplona.quartz.utils.Log.w("NestPlay") { + "decoder returned empty pcm (count=$emptyDecodes / received=$receivedObjects)" + } + } + } else { + decodedFrames += 1 onLevel(peakAmplitude(pcm)) if (playbackBegun) { + val enqueueStart = System.currentTimeMillis() player.enqueue(pcm) + val enqueueMs = System.currentTimeMillis() - enqueueStart + enqueued += 1 + if (enqueued % PLAY_LOG_THROTTLE == 0L || enqueueMs > 50) { + com.vitorpamplona.quartz.utils.Log.d("NestPlay") { + "NestPlayer enqueued #$enqueued (took ${enqueueMs}ms)" + } + } } else { preroll.addLast(pcm) if (preroll.size >= prerollFrames) { @@ -172,14 +211,23 @@ class NestPlayer( } } } + com.vitorpamplona.quartz.utils.Log.w("NestPlay") { + "NestPlayer objects flow COMPLETED (received=$receivedObjects decoded=$decodedFrames empty=$emptyDecodes enqueued=$enqueued)" + } // Flow ended without enough frames to fill the pre-roll // (e.g. the publisher cycled before pre-roll was full, // or the room ended). Flush whatever's queued so any // already-decoded audio still reaches the device. beginAndFlushIfNeeded() } catch (ce: CancellationException) { + com.vitorpamplona.quartz.utils.Log.d("NestPlay") { + "NestPlayer cancelled (received=$receivedObjects decoded=$decodedFrames enqueued=$enqueued)" + } throw ce } catch (t: Throwable) { + com.vitorpamplona.quartz.utils.Log.w("NestPlay") { + "NestPlayer pipeline threw: ${t::class.simpleName}: ${t.message}" + } onError( AudioException( AudioException.Kind.PlaybackFailed, @@ -203,8 +251,16 @@ class NestPlayer( suspend fun stop() { if (stopped) return stopped = true + com.vitorpamplona.quartz.utils.Log + .d("NestPlay") { "NestPlayer.stop()" } job?.cancelAndJoin() runCatching { player.stop() } runCatching { decoder.release() } } + + companion object { + // Diagnostic throttle: log every Nth event during normal flow so a + // sustained 50 fps stream doesn't flood logcat. + private const val PLAY_LOG_THROTTLE: Long = 50L + } }