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.
2026-05-05 15:56:47 +00:00
parent 3a2010d9c0
commit be8dd0a3bc
3 changed files with 94 additions and 5 deletions
@@ -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) }
    }

@@ -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",
@@ -122,6 +122,15 @@ class NestPlayer(
            scope.launch {
                val preroll = ArrayDeque<ShortArray>(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
+    }
 }