diff --git a/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/viewmodels/NestViewModel.kt b/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/viewmodels/NestViewModel.kt index e33b0ecc3..9bc9255ba 100644 --- a/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/viewmodels/NestViewModel.kt +++ b/commons/src/commonMain/kotlin/com/vitorpamplona/amethyst/commons/viewmodels/NestViewModel.kt @@ -831,6 +831,10 @@ class NestViewModel( com.vitorpamplona.quartz.utils.Log.d("NestRx") { "observeAnnounces #$emissionCount active=${ann.active} pubkey='${ann.pubkey.take(12)}' → ${if (ann.active) "ADD" else "REMOVE"}" } + com.vitorpamplona.nestsclient.trace.NestsTrace.emit("vm_observe_announce") { + "\"emission\":$emissionCount,\"active\":${ann.active}," + + "\"pubkey\":${com.vitorpamplona.nestsclient.trace.jsonStr(ann.pubkey)}" + } if (ann.active) { _announcedSpeakers.update { it + ann.pubkey } } else { @@ -1382,6 +1386,15 @@ class NestViewModel( com.vitorpamplona.quartz.utils.Log.d("NestRx") { "cliff-detector tick=$ticks active=${activeSpeakers.size} announced=${announced.size} lastFrameAges=[$ages]" } + com.vitorpamplona.nestsclient.trace.NestsTrace.emit("cliff_tick") { + "\"tick\":$ticks," + + "\"active\":${com.vitorpamplona.nestsclient.trace.jsonArrStr(activeSpeakers)}," + + "\"announced\":${com.vitorpamplona.nestsclient.trace.jsonArrStr(announced)}," + + "\"last_frame_age_ms\":{" + + lastFrameAt.entries.joinToString { + "${com.vitorpamplona.nestsclient.trace.jsonStr(it.key)}:${it.value.elapsedNow().inWholeMilliseconds}" + } + "}" + } } val stalled = computeStalledSpeakers( @@ -1396,6 +1409,10 @@ class NestViewModel( com.vitorpamplona.quartz.utils.Log.w("NestRx") { "cliff-detector: announced+subscribed but silent for ≥${ROOM_AUDIO_CLIFF_TIMEOUT_MS}ms — recycling session. stalled=$stalled" } + com.vitorpamplona.nestsclient.trace.NestsTrace.emit("cliff_recycle") { + "\"timeout_ms\":$ROOM_AUDIO_CLIFF_TIMEOUT_MS," + + "\"stalled\":${com.vitorpamplona.nestsclient.trace.jsonArrStr(stalled)}" + } val recycleMark = kotlin.time.TimeSource.Monotonic .markNow() diff --git a/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/moq/lite/MoqLiteSession.kt b/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/moq/lite/MoqLiteSession.kt index 903c7526e..72afdb4ce 100644 --- a/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/moq/lite/MoqLiteSession.kt +++ b/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/moq/lite/MoqLiteSession.kt @@ -22,6 +22,8 @@ package com.vitorpamplona.nestsclient.moq.lite import com.vitorpamplona.nestsclient.moq.MoqCodecException import com.vitorpamplona.nestsclient.moq.MoqWriter +import com.vitorpamplona.nestsclient.trace.NestsTrace +import com.vitorpamplona.nestsclient.trace.jsonStr import com.vitorpamplona.nestsclient.transport.WebTransportSession import com.vitorpamplona.quartz.utils.Log import com.vitorpamplona.quic.Varint @@ -137,6 +139,7 @@ class MoqLiteSession internal constructor( onBufferOverflow = BufferOverflow.DROP_OLDEST, ) Log.d("NestRx") { "session.announce(prefix='$prefix') bidi opened, pump launching (replayCap=64)" } + NestsTrace.emit("announce_bidi_opened") { "\"prefix\":${jsonStr(prefix)}" } val pump = scope.launch { val buffer = MoqLiteFrameBuffer() @@ -155,14 +158,29 @@ class MoqLiteSession internal constructor( "status=${decoded.status} suffix='${decoded.suffix.take(12)}' " + "(chunks=$chunkCount)" } + NestsTrace.emit("announce_pump_emit") { + "\"prefix\":${jsonStr(prefix)}," + + "\"emit_count\":$emitCount," + + "\"status\":${jsonStr(decoded.status.toString())}," + + "\"suffix\":${jsonStr(decoded.suffix)}," + + "\"chunks\":$chunkCount" + } updates.emit(decoded) } } Log.w("NestRx") { "session.announce(prefix='$prefix') bidi.incoming() ended naturally (chunks=$chunkCount, emits=$emitCount)" } + NestsTrace.emit("announce_bidi_ended_naturally") { + "\"prefix\":${jsonStr(prefix)},\"chunks\":$chunkCount,\"emits\":$emitCount" + } } catch (ce: CancellationException) { throw ce } catch (t: Throwable) { Log.w("NestRx") { "announce(prefix='$prefix'): bidi.incoming() threw ${t::class.simpleName}: ${t.message} (chunks=$chunkCount, emits=$emitCount)" } + NestsTrace.emit("announce_bidi_threw") { + "\"prefix\":${jsonStr(prefix)},\"chunks\":$chunkCount,\"emits\":$emitCount," + + "\"error\":${jsonStr(t::class.simpleName ?: "?")}," + + "\"message\":${jsonStr(t.message ?: "")}" + } // Flow terminated (peer FIN or transport close). // The Announce stream's emit-side just stops; consumers // see an end-of-flow. @@ -291,6 +309,10 @@ class MoqLiteSession internal constructor( if (groupPump == null) groupPump = scope.launch { pumpUniStreams() } } Log.d("NestRx") { "SUBSCRIBE send id=$id broadcast='$broadcast' track='$track' maxLatencyMs=$maxLatencyMillis" } + NestsTrace.emit("subscribe_send") { + "\"id\":$id,\"broadcast\":${jsonStr(broadcast)},\"track\":${jsonStr(track)}," + + "\"max_latency_ms\":$maxLatencyMillis" + } // Now that the subscription is registered, push the SUBSCRIBE // bytes. If `bidi.write` throws (transport torn down, peer // reset) we'd otherwise leave an orphaned map entry whose @@ -358,6 +380,10 @@ class MoqLiteSession internal constructor( val removed = state.withLock { subscriptionsBySubscribeId.remove(id) } if (removed != null) { Log.w("NestRx") { "SUBSCRIBE bidi exited, closing frames id=$id broadcast='${removed.request.broadcast}' track='${removed.request.track}'" } + NestsTrace.emit("subscribe_bidi_exited") { + "\"id\":$id,\"broadcast\":${jsonStr(removed.request.broadcast)}," + + "\"track\":${jsonStr(removed.request.track)}" + } } removed?.frames?.close() } @@ -377,6 +403,11 @@ class MoqLiteSession internal constructor( "SUBSCRIBE_DROP id=$id broadcast='$broadcast' track='$track' " + "errCode=${resp.drop.errorCode} reason='${resp.drop.reasonPhrase}'" } + NestsTrace.emit("subscribe_drop") { + "\"id\":$id,\"broadcast\":${jsonStr(broadcast)},\"track\":${jsonStr(track)}," + + "\"err_code\":${resp.drop.errorCode}," + + "\"reason\":${jsonStr(resp.drop.reasonPhrase)}" + } state.withLock { subscriptionsBySubscribeId.remove(id) } frames.close() runCatching { bidi.finish() } @@ -388,6 +419,9 @@ class MoqLiteSession internal constructor( is MoqLiteCodec.SubscribeResponse.Ok -> { Log.d("NestRx") { "SUBSCRIBE_OK id=$id broadcast='$broadcast' track='$track'" } + NestsTrace.emit("subscribe_ok") { + "\"id\":$id,\"broadcast\":${jsonStr(broadcast)},\"track\":${jsonStr(track)}" + } return MoqLiteSubscribeHandle( id = id, ok = resp.ok, @@ -464,6 +498,11 @@ class MoqLiteSession internal constructor( try { handle.updates.collect { update -> Log.d("NestRx") { "ANNOUNCE update status=${update.status} suffix='${update.suffix}' hops=${update.hops}" } + NestsTrace.emit("announce_watch_update") { + "\"status\":${jsonStr(update.status.toString())}," + + "\"suffix\":${jsonStr(update.suffix)}," + + "\"hops\":${update.hops}" + } if (update.status != MoqLiteAnnounceStatus.Ended) return@collect val targets = state.withLock { @@ -473,6 +512,10 @@ class MoqLiteSession internal constructor( } if (targets.isNotEmpty()) { Log.w("NestRx") { "ANNOUNCE Ended for suffix='${update.suffix}' → closing ${targets.size} subscription(s): ${targets.map { "id=${it.id} track='${it.request.track}'" }}" } + NestsTrace.emit("announce_watch_ended_closing_subs") { + "\"suffix\":${jsonStr(update.suffix)}," + + "\"closed_count\":${targets.size}" + } } for (sub in targets) { // Just close the frames channel — the @@ -512,6 +555,7 @@ class MoqLiteSession internal constructor( */ private suspend fun pumpUniStreams() { Log.d("NestRx") { "pumpUniStreams started" } + NestsTrace.emit("uni_pump_started") var streamCount = 0L try { // coroutineScope binds each per-stream drain to this pump's @@ -564,6 +608,9 @@ class MoqLiteSession internal constructor( groupSequence = hdr.sequence headerRead = true Log.d("NestRx") { "drainOneGroup#$streamSeq header subId=$subscribeId groupSeq=$groupSequence" } + NestsTrace.emit("group_header") { + "\"stream_seq\":$streamSeq,\"sub_id\":$subscribeId,\"group_seq\":$groupSequence" + } } while (true) { val frame = buffer.readSizePrefixed() ?: break @@ -588,10 +635,20 @@ class MoqLiteSession internal constructor( } } Log.d("NestRx") { "drainOneGroup#$streamSeq FIN subId=$subscribeId groupSeq=$groupSequence frames=$frameCount droppedNoSub=$droppedNoSub trySendFail=$trySendFailures" } + NestsTrace.emit("group_fin") { + "\"stream_seq\":$streamSeq,\"sub_id\":$subscribeId,\"group_seq\":$groupSequence," + + "\"frames\":$frameCount,\"dropped_no_sub\":$droppedNoSub,\"try_send_fail\":$trySendFailures" + } } catch (ce: CancellationException) { throw ce } catch (t: Throwable) { Log.w("NestRx") { "drainOneGroup#$streamSeq threw subId=$subscribeId groupSeq=$groupSequence frames=$frameCount: ${t::class.simpleName}: ${t.message}" } + NestsTrace.emit("group_threw") { + "\"stream_seq\":$streamSeq,\"sub_id\":$subscribeId,\"group_seq\":$groupSequence," + + "\"frames\":$frameCount," + + "\"error\":${jsonStr(t::class.simpleName ?: "?")}," + + "\"message\":${jsonStr(t.message ?: "")}" + } // Stream errored / FIN'd. Nothing to do — the next group // arrives on a fresh uni stream. } diff --git a/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/trace/NestsTrace.kt b/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/trace/NestsTrace.kt new file mode 100644 index 000000000..b0b88912b --- /dev/null +++ b/nestsClient/src/commonMain/kotlin/com/vitorpamplona/nestsclient/trace/NestsTrace.kt @@ -0,0 +1,191 @@ +/* + * 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.trace + +/** + * Append-only event recorder for the moq-lite + Nests audio path. + * + * Designed to capture enough wire-level + decision-level data from a real + * production session that the same communication can be replayed in a + * unit test without a network — i.e., feed the recorded events back + * through a `TraceReplayingTransport` (planned, not yet implemented) into + * the unmodified [com.vitorpamplona.nestsclient.moq.lite.MoqLiteSession] + * + [com.vitorpamplona.nestsclient.MoqLiteNestsListener] + + * [com.vitorpamplona.amethyst.commons.viewmodels.NestViewModel] stack + * and assert on observable behaviour (frames received, cliff-detector + * decisions, recycle counts). + * + * **Cost when disabled**: a single volatile-load + branch per call site + * (the [emit] inline guards `if (!enabled) return` before the lambda + * runs). Production builds that never call [setRecording] pay nothing. + * + * **Output format**: one JSON object per line, written via + * [com.vitorpamplona.quartz.utils.Log] at the [TAG] tag. Capture from a + * connected device with: + * + * adb logcat -c + * adb logcat -s NestsTraceJsonl:D -v raw > nest-trace.jsonl + * + * The `-v raw` formatter strips the `D NestsTraceJsonl:` prefix so the + * captured file is valid JSONL ready for replay tooling. + * + * **Schema**: each event is a JSON object with at least + * - `t_ms` — milliseconds since [setRecording] was called with `true` + * - `kind` — string discriminator naming the event + * and additional kind-specific fields. Keep all field names lower-snake- + * case and stable; the replay tool will pattern-match on `kind`. + * + * Anonymisation: pubkeys + track names are recorded verbatim because + * they're already in the production logs the user is sharing (the + * `NestRx` / `NestTx` tags). Frame payloads are NEVER recorded — only + * sizes — so audio content can't leak through a trace dump. + */ +object NestsTrace { + /** Tag the JSONL lines are emitted under. Filter logcat with `-s NestsTraceJsonl:D`. */ + const val TAG: String = "NestsTraceJsonl" + + // `@PublishedApi internal` rather than `private` because [emit] is + // inline — its body becomes part of every call site's bytecode and + // must be able to reach the backing fields. `private` would refuse + // to compile ("Public-API inline function cannot access non-public- + // API property"). Marking these `@PublishedApi internal` keeps them + // unreachable from outside the module while satisfying the inliner. + @PublishedApi + @Volatile + internal var enabled: Boolean = false + + @PublishedApi + @Volatile + internal var startMark: kotlin.time.TimeMark? = null + + /** + * Idempotent. When `on` flips from false → true, [startMark] is + * captured so subsequent [emit] calls record monotonic-time deltas + * relative to enable. Flipping true → false stops further emits but + * does NOT alter prior log output. + * + * Call from a debug-build app start-up hook, a debug menu toggle, or + * a test `@Before`. Production release builds should leave the + * default disabled. + * + * Named `setRecording` (not `setEnabled`) so it doesn't clash with + * the JVM-generated setter for the `enabled` backing property — + * that property is `@PublishedApi internal` for the inline [emit] + * to access, which forces the setter to share the `setEnabled` + * JVM name. + */ + fun setRecording(on: Boolean) { + if (on == enabled) return + if (on) { + startMark = + kotlin.time.TimeSource.Monotonic + .markNow() + } + enabled = on + } + + fun isRecording(): Boolean = enabled + + /** + * Record an event. The lambda is invoked ONLY when tracing is + * enabled, so the call site pays nothing in the disabled path beyond + * the field-load + comparison. + * + * The lambda must return the kind-specific JSON fields portion + * (no surrounding braces, no leading or trailing comma — empty + * string when there are no fields). This recorder prepends + * `{"t_ms":N,"kind":"K"`, joins fields with a comma when present, + * and appends `}`. + * + * Use [jsonStr] / [jsonArrStr] to safely quote string values and + * arrays. Numeric / boolean values can be interpolated directly. + * + * Example: + * + * NestsTrace.emit("subscribe_send") { + * "\"id\":$id,\"broadcast\":${jsonStr(broadcast)},\"track\":${jsonStr(track)}" + * } + */ + inline fun emit( + kind: String, + fieldsJson: () -> String = { "" }, + ) { + if (!enabled) return + val mark = startMark ?: return + val tMs = mark.elapsedNow().inWholeMilliseconds + val fields = fieldsJson() + val sep = if (fields.isEmpty()) "" else "," + com.vitorpamplona.quartz.utils.Log.d(TAG) { + "{\"t_ms\":$tMs,\"kind\":\"$kind\"$sep$fields}" + } + } +} + +/** + * Quote a string as a JSON literal, escaping the small set of characters + * that would otherwise produce invalid JSONL (`"`, `\`, control chars). + * Keeps the implementation small + commonMain-portable rather than + * pulling in a full JSON library for what is effectively a single + * field-value path. + */ +fun jsonStr(value: String): String { + val sb = StringBuilder(value.length + 2) + sb.append('"') + for (c in value) { + when (c) { + '"' -> { + sb.append('\\').append('"') + } + + '\\' -> { + sb.append('\\').append('\\') + } + + '\n' -> { + sb.append('\\').append('n') + } + + '\r' -> { + sb.append('\\').append('r') + } + + '\t' -> { + sb.append('\\').append('t') + } + + else -> { + if (c.code < 0x20) { + sb.append("\\u00") + val h = c.code.toString(16) + if (h.length == 1) sb.append('0') + sb.append(h) + } else { + sb.append(c) + } + } + } + } + sb.append('"') + return sb.toString() +} + +/** JSON array of strings: `["a","b","c"]`. */ +fun jsonArrStr(values: Iterable): String = values.joinToString(separator = ",", prefix = "[", postfix = "]") { jsonStr(it) } diff --git a/nestsClient/src/commonTest/kotlin/com/vitorpamplona/nestsclient/trace/NestsTraceTest.kt b/nestsClient/src/commonTest/kotlin/com/vitorpamplona/nestsclient/trace/NestsTraceTest.kt new file mode 100644 index 000000000..774e05f5e --- /dev/null +++ b/nestsClient/src/commonTest/kotlin/com/vitorpamplona/nestsclient/trace/NestsTraceTest.kt @@ -0,0 +1,149 @@ +/* + * 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.trace + +import kotlin.test.Test +import kotlin.test.assertEquals +import kotlin.test.assertFalse +import kotlin.test.assertTrue + +/** + * Pure-string tests for [jsonStr] / [jsonArrStr] (the JSON-quoting + * helpers used at every trace call site) and a small toggle test for + * [NestsTrace.setRecording]'s state-machine. + * + * The actual `emit` log-output side is untestable in commonTest because + * `com.vitorpamplona.quartz.utils.Log` writes to logcat / stdout via + * platform actuals, not via an injectable sink. The schema correctness + * we DO want to pin — a JSON-syntax bug at one of the call sites would + * silently corrupt the trace file and break replay tooling — is covered + * by exercising the quoting helpers exhaustively and asserting on + * concatenated round-trip equality with hand-built JSON literals. + */ +class NestsTraceTest { + @Test + fun jsonStrEscapesQuotesAndBackslashes() { + assertEquals("\"hello\"", jsonStr("hello")) + assertEquals("\"with \\\"quotes\\\"\"", jsonStr("with \"quotes\"")) + assertEquals("\"backslash \\\\ here\"", jsonStr("backslash \\ here")) + } + + @Test + fun jsonStrEscapesControlCharacters() { + assertEquals("\"line1\\nline2\"", jsonStr("line1\nline2")) + assertEquals("\"col1\\tcol2\"", jsonStr("col1\tcol2")) + assertEquals("\"crlf\\r\\n\"", jsonStr("crlf\r\n")) + } + + @Test + fun jsonStrEscapesLowControlCharsAsUnicode() { + //  (start of heading) — must be  in JSON, not raw. + val raw = "xy" + val quoted = jsonStr(raw) + assertEquals("\"x\\u0001y\"", quoted) + } + + @Test + fun jsonStrLeavesPrintableAsciiAlone() { + // Every printable ASCII char that isn't `"` or `\` must round-trip + // unmodified — most production trace fields are pubkey hex, + // track names, event-kind enums. + val allPrintable = + (0x20..0x7e) + .map { it.toChar() } + .filter { it != '"' && it != '\\' } + .joinToString("") + val quoted = jsonStr(allPrintable) + assertEquals("\"$allPrintable\"", quoted) + } + + @Test + fun jsonArrStrEmitsValidJsonArray() { + assertEquals("[]", jsonArrStr(emptyList())) + assertEquals("[\"a\"]", jsonArrStr(listOf("a"))) + assertEquals( + "[\"alpha\",\"beta\",\"gamma\"]", + jsonArrStr(listOf("alpha", "beta", "gamma")), + ) + } + + @Test + fun jsonArrStrEscapesElementsConsistentlyWithJsonStr() { + // Each element runs through jsonStr — quotes and backslashes + // inside an element must be escaped just like a stand-alone field. + assertEquals( + "[\"a\\\"b\",\"c\\\\d\"]", + jsonArrStr(listOf("a\"b", "c\\d")), + ) + } + + @Test + fun setRecordingIsIdempotent() { + // Set up clean state for the test — flip off in case a prior + // test left the recorder enabled. (No reset() API by design; + // tests share the singleton.) + NestsTrace.setRecording(false) + assertFalse(NestsTrace.isRecording()) + + NestsTrace.setRecording(true) + assertTrue(NestsTrace.isRecording()) + + // Double-enable: no change in state, no error. + NestsTrace.setRecording(true) + assertTrue(NestsTrace.isRecording()) + + NestsTrace.setRecording(false) + assertFalse(NestsTrace.isRecording()) + + // Double-disable: no change in state, no error. + NestsTrace.setRecording(false) + assertFalse(NestsTrace.isRecording()) + } + + @Test + fun emitIsNoOpWhenDisabled() { + // Lambda must not run when tracing is off — call sites pass + // a non-trivial allocator (string concat) and we promise zero + // work on the disabled path. + NestsTrace.setRecording(false) + var lambdaRanCount = 0 + NestsTrace.emit("would_have_recorded") { + lambdaRanCount += 1 + "" + } + assertEquals(0, lambdaRanCount, "emit's fields lambda must not run when tracing is disabled") + } + + @Test + fun emitRunsLambdaWhenEnabled() { + NestsTrace.setRecording(true) + try { + var lambdaRanCount = 0 + NestsTrace.emit("did_record") { + lambdaRanCount += 1 + "\"k\":\"v\"" + } + assertEquals(1, lambdaRanCount, "emit's fields lambda must run exactly once when enabled") + } finally { + NestsTrace.setRecording(false) + } + } +}