From 5f90588fe4f31658732286c720a00b442817e964 Mon Sep 17 00:00:00 2001 From: Claude Date: Sun, 26 Apr 2026 20:10:43 +0000 Subject: [PATCH] test(audio-rooms): InteropDebug step logger + harness diagnostics MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit When an interop test fails today the report shows a generic AssertionError pointing at a `runBlocking {` line — useless for narrowing down which sub-step (mintToken, WT connect, ANNOUNCE, SUBSCRIBE_OK, frame round-trip) actually exploded. This adds a small InteropDebug helper that: - prints a labelled "▶ start" / "✔ ok" / "✘ fail — Class: msg ⟵ Cause: msg" trail per step (output gated on `-DnestsInterop=true` so the default test run stays silent) - walks chained `cause` so the surface message reveals the real network / protocol error instead of the wrapping string - pretty-prints NestsSpeakerState / NestsListenerState (Failed in particular unwraps `cause` for the report) Each test body in NostrNestsRoundTripInteropTest + NostrNestsMultiPeerInteropTest now wraps connect / startBroadcasting / subscribeSpeaker / await-frames in `InteropDebug.stepSuspending(...)` so a failure points at the exact sub-step rather than the test method. Harness diagnostics: when `start()` fails, capture `docker compose ps` + recent logs for moq-auth / moq-relay / strfry into the IllegalStateException message before tearing the stack down. Without this, the test report only shows "exited with code 1" — operators have to re-run by hand to find out which container crashed. Output is hidden by default; only surfaces when `-DnestsInterop=true` (or the explicit `-DnestsInteropDebug=true`) is set. --- .../nestsclient/interop/InteropDebug.kt | 190 ++++++++++++++++++ .../nestsclient/interop/NostrNestsHarness.kt | 53 ++++- .../interop/NostrNestsMultiPeerInteropTest.kt | 186 +++++++++++------ .../interop/NostrNestsRoundTripInteropTest.kt | 100 ++++----- 4 files changed, 424 insertions(+), 105 deletions(-) create mode 100644 nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/InteropDebug.kt diff --git a/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/InteropDebug.kt b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/InteropDebug.kt new file mode 100644 index 000000000..ae440546b --- /dev/null +++ b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/InteropDebug.kt @@ -0,0 +1,190 @@ +/* + * Copyright (c) 2025 Vitor Pamplona + * + * Permission is hereby granted, free of charge, to any person obtaining a copy of + * this software and associated documentation files (the "Software"), to deal in + * the Software without restriction, including without limitation the rights to use, + * copy, modify, merge, publish, distribute, sublicense, and/or sell copies of the + * Software, and to permit persons to whom the Software is furnished to do so, + * subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in all + * copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, FITNESS + * FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR + * COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN + * AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION + * WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. + */ +package com.vitorpamplona.nestsclient.interop + +import com.vitorpamplona.nestsclient.NestsListenerState +import com.vitorpamplona.nestsclient.NestsSpeakerState +import kotlin.test.fail + +/** + * Shared debug helpers for the interop tests. Gradle captures stdout + * per test and renders it in the HTML report — these helpers make + * the report explain exactly which sub-step of a multi-step interop + * scenario fired (or didn't), without forcing every assert into a + * giant message string. + * + * Output is silent unless `-DnestsInteropDebug=true` (or the harness + * is enabled). That keeps the default test run noise-free. + */ +object InteropDebug { + private val enabled: Boolean by lazy { + // If the harness is on, the test is going to talk to a real + // network anyway — surface every step. Otherwise allow an + // explicit opt-in. + System.getProperty(NostrNestsHarness.ENABLE_PROPERTY) == "true" || + System.getProperty("nestsInteropDebug") == "true" + } + + /** Print a labelled checkpoint. Cheap; safe in inner loops. */ + fun checkpoint( + scope: String, + message: String, + ) { + if (!enabled) return + println("· [$scope] $message") + } + + /** + * Run [block] surrounded by an "▶ start" / "✔ ok" / "✘ fail" log. + * Re-throws any exception so the test still fails — but the report + * makes it obvious which step actually exploded. + */ + inline fun step( + scope: String, + name: String, + block: () -> T, + ): T { + checkpoint(scope, "▶ $name") + return try { + block().also { checkpoint(scope, "✔ $name") } + } catch (t: Throwable) { + checkpoint(scope, "✘ $name — ${describe(t)}") + throw t + } + } + + /** + * Async-friendly variant for `suspend` step bodies. + */ + suspend inline fun stepSuspending( + scope: String, + name: String, + block: () -> T, + ): T { + checkpoint(scope, "▶ $name") + return try { + block().also { checkpoint(scope, "✔ $name") } + } catch (t: Throwable) { + checkpoint(scope, "✘ $name — ${describe(t)}") + throw t + } + } + + /** + * One-line summary of [t] including the chained cause(s) — useful + * because the surface message often hides the real reason in + * `cause.cause.cause...` (network → NestsException → AssertionError + * is a common stack here). + */ + fun describe(t: Throwable): String = + buildString { + var current: Throwable? = t + var depth = 0 + while (current != null && depth < 5) { + if (depth > 0) append(" ⟵ ") + append(current::class.simpleName).append(": ").append(current.message ?: "(no message)") + current = current.cause + depth += 1 + } + } + + /** + * Pretty-print a [NestsSpeakerState] — for [Failed] in particular, + * unwraps the chained cause so the assertion message names the + * real network error rather than the wrapping string. + */ + fun describe(state: NestsSpeakerState): String = + when (state) { + is NestsSpeakerState.Failed -> { + "Failed(reason='${state.reason}'" + + (state.cause?.let { ", cause=${describe(it)}" } ?: "") + + ")" + } + + is NestsSpeakerState.Connected -> { + "Connected(room=${state.room.moqNamespace()}, moqVersion=0x${state.negotiatedMoqVersion.toString(16)})" + } + + is NestsSpeakerState.Broadcasting -> { + "Broadcasting(room=${state.room.moqNamespace()}, isMuted=${state.isMuted})" + } + + else -> { + state.toString() + } + } + + /** Mirror of [describe] for the listener side. */ + fun describe(state: NestsListenerState): String = + when (state) { + is NestsListenerState.Failed -> { + "Failed(reason='${state.reason}'" + + (state.cause?.let { ", cause=${describe(it)}" } ?: "") + + ")" + } + + is NestsListenerState.Connected -> { + "Connected(room=${state.room.moqNamespace()}, moqVersion=0x${state.negotiatedMoqVersion.toString(16)})" + } + + else -> { + state.toString() + } + } + + /** + * Assert [actual] is [NestsSpeakerState.Connected] or + * [NestsSpeakerState.Broadcasting], printing a richly-described + * failure message including any nested cause. + */ + fun assertSpeakerReached( + scope: String, + expectedClass: String, + actual: NestsSpeakerState, + ) { + val ok = + when (expectedClass) { + "Connected" -> actual is NestsSpeakerState.Connected + "Broadcasting" -> actual is NestsSpeakerState.Broadcasting + else -> error("unsupported expectedClass=$expectedClass") + } + if (!ok) { + fail("[$scope] speaker did not reach $expectedClass — was ${describe(actual)}") + } + checkpoint(scope, "speaker @ $expectedClass — ${describe(actual)}") + } + + fun assertListenerReached( + scope: String, + expectedClass: String, + actual: NestsListenerState, + ) { + val ok = + when (expectedClass) { + "Connected" -> actual is NestsListenerState.Connected + else -> error("unsupported expectedClass=$expectedClass") + } + if (!ok) { + fail("[$scope] listener did not reach $expectedClass — was ${describe(actual)}") + } + checkpoint(scope, "listener @ $expectedClass — ${describe(actual)}") + } +} diff --git a/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrNestsHarness.kt b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrNestsHarness.kt index 45da9a1d8..3b4683f87 100644 --- a/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrNestsHarness.kt +++ b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrNestsHarness.kt @@ -162,10 +162,17 @@ class NostrNestsHarness private constructor( // otherwise hits the first test of the second class. waitForHealth("http://127.0.0.1:$AUTH_HOST_PORT/health", PORT_READY_TIMEOUT_MS) } catch (t: Throwable) { - // If readiness probe fails, tear down so we don't leak the - // stack into the next test run. + // Capture container state + recent logs BEFORE tearing + // down so the failure message is actually actionable. + // Otherwise we get "Port 8090 not ready in 90 s" with + // zero clue whether moq-auth crashed, the build failed, + // or something else was binding the port. + val diagnostics = captureFailureDiagnostics(workDir) runCatching { runDocker(workDir, "down", "-v", "--remove-orphans") } - throw t + throw IllegalStateException( + "harness start failed: ${t.message}\n--- diagnostics ---\n$diagnostics", + t, + ) } return NostrNestsHarness( workDir = workDir, @@ -287,6 +294,46 @@ class NostrNestsHarness private constructor( } } + /** + * Snapshot `docker compose ps` + the tail of each service's + * logs into a single string for inclusion in a thrown + * exception message. Best-effort — never throws, so it can + * be called from a [start] catch handler without masking the + * original error. + */ + private fun captureFailureDiagnostics(workDir: File): String = + buildString { + append("== docker compose ps ==\n") + append(captureDocker(workDir, listOf("ps"))) + for (service in listOf("moq-auth", "moq-relay", "strfry")) { + append("\n== docker compose logs --tail 30 $service ==\n") + append(captureDocker(workDir, listOf("logs", "--tail", "30", service))) + } + } + + /** + * Run a docker compose subcommand and return its combined + * stdout/stderr; on any failure return the error text instead + * of throwing. + */ + private fun captureDocker( + workDir: File, + args: List, + ): String = + try { + val process = + ProcessBuilder(listOf("docker", "compose", "-f", COMPOSE_FILE) + args) + .directory(workDir) + .redirectErrorStream(true) + .start() + process.inputStream + .bufferedReader() + .readText() + .also { process.waitFor() } + } catch (t: Throwable) { + "(failed to capture: ${t.message})" + } + private fun waitForPort( host: String, port: Int, diff --git a/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrNestsMultiPeerInteropTest.kt b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrNestsMultiPeerInteropTest.kt index ab33a4779..31aaefa02 100644 --- a/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrNestsMultiPeerInteropTest.kt +++ b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrNestsMultiPeerInteropTest.kt @@ -21,10 +21,8 @@ package com.vitorpamplona.nestsclient.interop import com.vitorpamplona.nestsclient.NestsListener -import com.vitorpamplona.nestsclient.NestsListenerState import com.vitorpamplona.nestsclient.NestsRoomConfig import com.vitorpamplona.nestsclient.NestsSpeaker -import com.vitorpamplona.nestsclient.NestsSpeakerState import com.vitorpamplona.nestsclient.OkHttpNestsClient import com.vitorpamplona.nestsclient.audio.AudioCapture import com.vitorpamplona.nestsclient.audio.OpusEncoder @@ -52,8 +50,7 @@ import org.junit.BeforeClass import org.junit.Test import kotlin.test.assertContentEquals import kotlin.test.assertEquals -import kotlin.test.assertNotNull -import kotlin.test.assertTrue +import kotlin.test.fail /** * Phase-4 multi-peer interop tests. Each test brings up a real @@ -92,6 +89,9 @@ class NostrNestsMultiPeerInteropTest { val listenerSignerA = NostrSignerInternal(KeyPair()) val listenerSignerB = NostrSignerInternal(KeyPair()) + val scope = "fanout" + InteropDebug.checkpoint(scope, "room=${speakerRoom.moqNamespace()} speaker=${speakerSigner.pubKey.take(8)}") + try { val speaker = connectSpeaker( @@ -99,26 +99,39 @@ class NostrNestsMultiPeerInteropTest { room = speakerRoom, signer = speakerSigner, capture = capture, + debugScope = scope, ) - speaker.startBroadcasting() + InteropDebug.stepSuspending(scope, "speaker.startBroadcasting") { speaker.startBroadcasting() } + InteropDebug.assertSpeakerReached(scope, "Broadcasting", speaker.state.value) - val listenerA = connectListener(pumpScope, speakerRoom, listenerSignerA) - val listenerB = connectListener(pumpScope, speakerRoom, listenerSignerB) + val listenerA = connectListener(pumpScope, speakerRoom, listenerSignerA, debugScope = "$scope/listenerA") + val listenerB = connectListener(pumpScope, speakerRoom, listenerSignerB, debugScope = "$scope/listenerB") - val subA = listenerA.subscribeSpeaker(speakerSigner.pubKey) - val subB = listenerB.subscribeSpeaker(speakerSigner.pubKey) + val subA = + InteropDebug.stepSuspending("$scope/listenerA", "subscribeSpeaker(${speakerSigner.pubKey.take(8)})") { + listenerA.subscribeSpeaker(speakerSigner.pubKey) + } + val subB = + InteropDebug.stepSuspending("$scope/listenerB", "subscribeSpeaker(${speakerSigner.pubKey.take(8)})") { + listenerB.subscribeSpeaker(speakerSigner.pubKey) + } val collectedA = collectFrames(pumpScope, subA, FRAMES_FANOUT) val collectedB = collectFrames(pumpScope, subB, FRAMES_FANOUT) delay(SUBSCRIBE_SETTLE_MS) + InteropDebug.checkpoint(scope, "pushing $FRAMES_FANOUT frames") for (i in 0 until FRAMES_FANOUT) { capture.push(shortArrayOf(i.toShort())) delay(FRAME_SPACING_MS) } - assertFrameSequence(collectedA.await(), FRAMES_FANOUT, "listener A") - assertFrameSequence(collectedB.await(), FRAMES_FANOUT, "listener B") + InteropDebug.stepSuspending(scope, "await listener A frames") { + assertFrameSequence(collectedA.await(), FRAMES_FANOUT, "$scope/listenerA") + } + InteropDebug.stepSuspending(scope, "await listener B frames") { + assertFrameSequence(collectedB.await(), FRAMES_FANOUT, "$scope/listenerB") + } runCatching { subA.unsubscribe() } runCatching { subB.unsubscribe() } @@ -154,47 +167,88 @@ class NostrNestsMultiPeerInteropTest { val captureA = DriverCapture() val captureB = DriverCapture() + val scope = "multispeaker" + InteropDebug.checkpoint(scope, "room=${room.moqNamespace()} A=${signerA.pubKey.take(8)} B=${signerB.pubKey.take(8)}") + try { val speakerA = - connectSpeaker(pumpScope, room, signerA, captureA, encoderPrefix = "A:") + connectSpeaker( + pumpScope, + room, + signerA, + captureA, + encoderPrefix = "A:", + debugScope = "$scope/speakerA", + ) val speakerB = - connectSpeaker(pumpScope, room, signerB, captureB, encoderPrefix = "B:") - speakerA.startBroadcasting() - speakerB.startBroadcasting() + connectSpeaker( + pumpScope, + room, + signerB, + captureB, + encoderPrefix = "B:", + debugScope = "$scope/speakerB", + ) + InteropDebug.stepSuspending("$scope/speakerA", "startBroadcasting") { speakerA.startBroadcasting() } + InteropDebug.assertSpeakerReached("$scope/speakerA", "Broadcasting", speakerA.state.value) + InteropDebug.stepSuspending("$scope/speakerB", "startBroadcasting") { speakerB.startBroadcasting() } + InteropDebug.assertSpeakerReached("$scope/speakerB", "Broadcasting", speakerB.state.value) - val listener = connectListener(pumpScope, room, listenerSigner) - val subA = listener.subscribeSpeaker(signerA.pubKey) - val subB = listener.subscribeSpeaker(signerB.pubKey) + val listener = connectListener(pumpScope, room, listenerSigner, debugScope = "$scope/listener") + val subA = + InteropDebug.stepSuspending("$scope/listener", "subscribeSpeaker(A=${signerA.pubKey.take(8)})") { + listener.subscribeSpeaker(signerA.pubKey) + } + val subB = + InteropDebug.stepSuspending("$scope/listener", "subscribeSpeaker(B=${signerB.pubKey.take(8)})") { + listener.subscribeSpeaker(signerB.pubKey) + } val collectedA = collectFrames(pumpScope, subA, FRAMES_MULTI_SPEAKER) val collectedB = collectFrames(pumpScope, subB, FRAMES_MULTI_SPEAKER) delay(SUBSCRIBE_SETTLE_MS) + InteropDebug.checkpoint(scope, "pushing $FRAMES_MULTI_SPEAKER frames into each capture") for (i in 0 until FRAMES_MULTI_SPEAKER) { captureA.push(shortArrayOf((i + 0).toShort())) captureB.push(shortArrayOf((i + 100).toShort())) delay(FRAME_SPACING_MS) } - val resA = collectedA.await() - val resB = collectedB.await() - assertNotNull(resA, "listener never received speaker-A frames") - assertNotNull(resB, "listener never received speaker-B frames") - assertEquals(FRAMES_MULTI_SPEAKER, resA.size, "speaker A count") - assertEquals(FRAMES_MULTI_SPEAKER, resB.size, "speaker B count") + val resA = + InteropDebug.stepSuspending(scope, "await speaker A frames") { collectedA.await() } + val resB = + InteropDebug.stepSuspending(scope, "await speaker B frames") { collectedB.await() } + if (resA == null) { + fail( + "[$scope] listener never received speaker-A frames within ${RECEIVE_TIMEOUT_MS}ms — " + + "speakerA=${InteropDebug.describe(speakerA.state.value)}, " + + "listener=${InteropDebug.describe(listener.state.value)}", + ) + } + if (resB == null) { + fail( + "[$scope] listener never received speaker-B frames within ${RECEIVE_TIMEOUT_MS}ms — " + + "speakerB=${InteropDebug.describe(speakerB.state.value)}, " + + "listener=${InteropDebug.describe(listener.state.value)}", + ) + } + InteropDebug.checkpoint(scope, "received ${resA.size} A-frames, ${resB.size} B-frames") + assertEquals(FRAMES_MULTI_SPEAKER, resA.size, "[$scope] speaker A count") + assertEquals(FRAMES_MULTI_SPEAKER, resB.size, "[$scope] speaker B count") resA.forEachIndexed { idx, obj -> assertContentEquals( "A:".encodeToByteArray() + byteArrayOf(idx.toByte()), obj.payload, - "speaker A frame $idx — must not contain B's payload (no cross-talk)", + "[$scope] speaker A frame $idx — must not contain B's payload (no cross-talk)", ) } resB.forEachIndexed { idx, obj -> assertContentEquals( "B:".encodeToByteArray() + byteArrayOf((idx + 100).toByte()), obj.payload, - "speaker B frame $idx — must not contain A's payload (no cross-talk)", + "[$scope] speaker B frame $idx — must not contain A's payload (no cross-talk)", ) } @@ -228,27 +282,38 @@ class NostrNestsMultiPeerInteropTest { val pumpScope = CoroutineScope(supervisor + Dispatchers.IO) val capture = DriverCapture() + val scope = "presub" + InteropDebug.checkpoint(scope, "room=${room.moqNamespace()} speaker=${speakerSigner.pubKey.take(8)}") + try { - val listener = connectListener(pumpScope, room, listenerSigner) - val sub = listener.subscribeSpeaker(speakerSigner.pubKey) + val listener = connectListener(pumpScope, room, listenerSigner, debugScope = "$scope/listener") + val sub = + InteropDebug.stepSuspending("$scope/listener", "subscribeSpeaker(${speakerSigner.pubKey.take(8)})") { + listener.subscribeSpeaker(speakerSigner.pubKey) + } val collected = collectFrames(pumpScope, sub, FRAMES_PRESUB) // Wait briefly so the SUBSCRIBE is on the relay before // the publisher arrives — the relay should hold it. delay(SUBSCRIBE_SETTLE_MS) + InteropDebug.checkpoint(scope, "subscribe settled — bringing speaker up now") - val speaker = connectSpeaker(pumpScope, room, speakerSigner, capture) - speaker.startBroadcasting() + val speaker = connectSpeaker(pumpScope, room, speakerSigner, capture, debugScope = "$scope/speaker") + InteropDebug.stepSuspending("$scope/speaker", "startBroadcasting") { speaker.startBroadcasting() } + InteropDebug.assertSpeakerReached("$scope/speaker", "Broadcasting", speaker.state.value) // Give the announce + publisher-side subscribe matchup // time to plumb before pushing frames. delay(SUBSCRIBE_SETTLE_MS) + InteropDebug.checkpoint(scope, "pushing $FRAMES_PRESUB frames into capture") for (i in 0 until FRAMES_PRESUB) { capture.push(shortArrayOf(i.toShort())) delay(FRAME_SPACING_MS) } - assertFrameSequence(collected.await(), FRAMES_PRESUB, "pre-subscribed listener") + InteropDebug.stepSuspending(scope, "await pre-subscribed listener frames") { + assertFrameSequence(collected.await(), FRAMES_PRESUB, "$scope/listener") + } runCatching { sub.unsubscribe() } runCatching { listener.close() } @@ -268,22 +333,22 @@ class NostrNestsMultiPeerInteropTest { signer: NostrSignerInternal, capture: AudioCapture, encoderPrefix: String = "FRAME-", + debugScope: String = "speaker(${signer.pubKey.take(8)})", ): NestsSpeaker { val speaker = - connectNestsSpeaker( - httpClient = http, - transport = transport, - scope = scope, - room = room, - signer = signer, - speakerPubkeyHex = signer.pubKey, - captureFactory = { capture }, - encoderFactory = { StubEncoder(encoderPrefix.encodeToByteArray()) }, - ) - assertTrue( - speaker.state.value is NestsSpeakerState.Connected, - "speaker did not reach Connected — was ${speaker.state.value}", - ) + InteropDebug.stepSuspending(debugScope, "connectNestsSpeaker") { + connectNestsSpeaker( + httpClient = http, + transport = transport, + scope = scope, + room = room, + signer = signer, + speakerPubkeyHex = signer.pubKey, + captureFactory = { capture }, + encoderFactory = { StubEncoder(encoderPrefix.encodeToByteArray()) }, + ) + } + InteropDebug.assertSpeakerReached(debugScope, "Connected", speaker.state.value) return speaker } @@ -291,19 +356,19 @@ class NostrNestsMultiPeerInteropTest { scope: CoroutineScope, room: NestsRoomConfig, signer: NostrSignerInternal, + debugScope: String = "listener(${signer.pubKey.take(8)})", ): NestsListener { val listener = - connectNestsListener( - httpClient = http, - transport = transport, - scope = scope, - room = room, - signer = signer, - ) - assertTrue( - listener.state.value is NestsListenerState.Connected, - "listener did not reach Connected — was ${listener.state.value}", - ) + InteropDebug.stepSuspending(debugScope, "connectNestsListener") { + connectNestsListener( + httpClient = http, + transport = transport, + scope = scope, + room = room, + signer = signer, + ) + } + InteropDebug.assertListenerReached(debugScope, "Connected", listener.state.value) return listener } @@ -322,7 +387,14 @@ class NostrNestsMultiPeerInteropTest { expectedCount: Int, who: String, ) { - assertNotNull(objs, "$who did not receive $expectedCount frames within ${RECEIVE_TIMEOUT_MS}ms") + if (objs == null) { + fail( + "$who did not receive $expectedCount frames within ${RECEIVE_TIMEOUT_MS}ms — " + + "verify the speaker actually announced + the relay forwarded; " + + "look upstream for ✘ checkpoints in the captured stdout", + ) + } + InteropDebug.checkpoint(who, "received ${objs.size} frames (expected $expectedCount)") assertEquals(expectedCount, objs.size, "$who frame count") objs.forEachIndexed { idx, obj -> assertEquals(idx.toLong(), obj.objectId, "$who object id at index $idx") diff --git a/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrNestsRoundTripInteropTest.kt b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrNestsRoundTripInteropTest.kt index 5d5e31723..027fb8572 100644 --- a/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrNestsRoundTripInteropTest.kt +++ b/nestsClient/src/jvmTest/kotlin/com/vitorpamplona/nestsclient/interop/NostrNestsRoundTripInteropTest.kt @@ -20,14 +20,14 @@ */ package com.vitorpamplona.nestsclient.interop -import com.vitorpamplona.nestsclient.NestsListenerState import com.vitorpamplona.nestsclient.NestsRoomConfig -import com.vitorpamplona.nestsclient.NestsSpeakerState import com.vitorpamplona.nestsclient.OkHttpNestsClient import com.vitorpamplona.nestsclient.audio.AudioCapture +import com.vitorpamplona.nestsclient.audio.AudioRoomMoqLiteBroadcaster import com.vitorpamplona.nestsclient.audio.OpusEncoder import com.vitorpamplona.nestsclient.connectNestsListener import com.vitorpamplona.nestsclient.connectNestsSpeaker +import com.vitorpamplona.nestsclient.moq.SubscribeHandle import com.vitorpamplona.nestsclient.transport.QuicWebTransportFactory import com.vitorpamplona.quartz.nip01Core.crypto.KeyPair import com.vitorpamplona.quartz.nip01Core.signers.NostrSignerInternal @@ -48,8 +48,7 @@ import org.junit.BeforeClass import org.junit.Test import kotlin.test.assertContentEquals import kotlin.test.assertEquals -import kotlin.test.assertNotNull -import kotlin.test.assertTrue +import kotlin.test.fail /** * End-to-end interop test. Drives the production [connectNestsSpeaker] @@ -58,11 +57,10 @@ import kotlin.test.assertTrue * (`MoqLitePublisherHandle`), the listener subscribes by speaker * pubkey (`broadcast=pubkey`, `track="audio/data"`), the speaker * pushes deterministic Opus-shaped payloads through the - * [com.vitorpamplona.nestsclient.audio.AudioRoomMoqLiteBroadcaster] - * pipeline, and the listener collects them via - * [com.vitorpamplona.nestsclient.moq.SubscribeHandle.objects] (which - * the moq-lite adapter wraps over `MoqLiteFrame` so existing decoder - * / player code keeps working). + * [AudioRoomMoqLiteBroadcaster] pipeline, and the listener collects + * them via [SubscribeHandle.objects] (which the moq-lite adapter + * wraps over `MoqLiteFrame` so existing decoder / player code keeps + * working). * * Verifies: * - QuicWebTransportFactory + PermissiveCertificateValidator can speak @@ -118,43 +116,47 @@ class NostrNestsRoundTripInteropTest { val capture = DriverCapture() val encoder = StubEncoder(prefix = "FRAME-".encodeToByteArray()) + val scope = "round-trip" + InteropDebug.checkpoint(scope, "room=${room.moqNamespace()} authBase=${room.authBaseUrl} endpoint=${room.endpoint}") + try { val speaker = - connectNestsSpeaker( - httpClient = httpClient, - transport = transport, - scope = pumpScope, - room = room, - signer = signer, - speakerPubkeyHex = pubkey, - captureFactory = { capture }, - encoderFactory = { encoder }, - ) - assertTrue( - speaker.state.value is NestsSpeakerState.Connected, - "speaker did not reach Connected — was ${speaker.state.value}", - ) + InteropDebug.stepSuspending(scope, "connectNestsSpeaker") { + connectNestsSpeaker( + httpClient = httpClient, + transport = transport, + scope = pumpScope, + room = room, + signer = signer, + speakerPubkeyHex = pubkey, + captureFactory = { capture }, + encoderFactory = { encoder }, + ) + } + InteropDebug.assertSpeakerReached(scope, "Connected", speaker.state.value) - val broadcast = speaker.startBroadcasting() - assertTrue( - speaker.state.value is NestsSpeakerState.Broadcasting, - "speaker did not reach Broadcasting — was ${speaker.state.value}", - ) + val broadcast = + InteropDebug.stepSuspending(scope, "speaker.startBroadcasting") { + speaker.startBroadcasting() + } + InteropDebug.assertSpeakerReached(scope, "Broadcasting", speaker.state.value) val listener = - connectNestsListener( - httpClient = httpClient, - transport = transport, - scope = pumpScope, - room = room, - signer = signer, - ) - assertTrue( - listener.state.value is NestsListenerState.Connected, - "listener did not reach Connected — was ${listener.state.value}", - ) + InteropDebug.stepSuspending(scope, "connectNestsListener") { + connectNestsListener( + httpClient = httpClient, + transport = transport, + scope = pumpScope, + room = room, + signer = signer, + ) + } + InteropDebug.assertListenerReached(scope, "Connected", listener.state.value) - val subscription = listener.subscribeSpeaker(pubkey) + val subscription = + InteropDebug.stepSuspending(scope, "listener.subscribeSpeaker(pubkey)") { + listener.subscribeSpeaker(pubkey) + } // Start collecting before the speaker publishes anything — // moq-lite group frames that arrive before .objects.collect @@ -172,6 +174,7 @@ class NostrNestsRoundTripInteropTest { // and rolls back the object id without queuing a datagram). delay(SUBSCRIBE_SETTLE_MS) + InteropDebug.checkpoint(scope, "pushing $N_FRAMES frames into capture") for (i in 0 until N_FRAMES) { capture.push(shortArrayOf(i.toShort())) // Pace frames slightly so a transient datagram drop @@ -179,11 +182,18 @@ class NostrNestsRoundTripInteropTest { delay(FRAME_SPACING_MS) } - val datagrams = received.await() - assertNotNull( - datagrams, - "Did not receive $N_FRAMES moq-lite frames within ${RECEIVE_TIMEOUT_MS}ms", - ) + val datagrams = + InteropDebug.stepSuspending(scope, "await $N_FRAMES frames on subscription") { + received.await() + } + if (datagrams == null) { + fail( + "[$scope] Did not receive $N_FRAMES moq-lite frames within ${RECEIVE_TIMEOUT_MS}ms — " + + "speaker=${InteropDebug.describe(speaker.state.value)}, " + + "listener=${InteropDebug.describe(listener.state.value)}", + ) + } + InteropDebug.checkpoint(scope, "received ${datagrams.size} frames (expected $N_FRAMES)") assertEquals(N_FRAMES, datagrams.size, "expected exactly $N_FRAMES objects") datagrams.forEachIndexed { idx, obj ->