From 60e3df72b243edf3c5c58feaffa1fd66548c97cc Mon Sep 17 00:00:00 2001 From: Vitor Pamplona Date: Wed, 29 Jul 2026 17:58:11 -0400 Subject: [PATCH 1/4] fix(logs): make the default log a boot narrative, not a firehose MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A cold start emitted 6,198 app lines in 80s (~77/sec) on a real device. Six tags produced 83% of it, and the lines that are actually actionable — relay protocol refusals like `auth-required`, `rate-limited`, `unsupported: too many filters` — were buried among them. `Log.minLevel` was `DEBUG` in debug and `ERROR` in release: two settings, both wrong. Release dropped all 460 `Log.w` call sites, so the field never saw a single relay refusal. Debug kept everything. Now debug defaults to INFO and release to WARN, with `Amethyst.VERBOSE_LOGS` to restore the firehose. 333 files already route through `quartz.utils.Log` (only 13 use raw `android.util.Log`), so `minLevel` is a real global gate — which is why three of the four loudest buckets needed no code change at all: relay socket lifecycle (1,659 lines), `RelaySpeedLogger` (1,308) and Arti's per-stream SOCKS errors (753) were already `Log.d`. The rest: - `RelayLogger.onCannotConnect` E -> D. Under the outbox model a boot dials ~400 relays and most fail identically; one line per dead socket is not actionable, and its multi-line TLS certificate dumps were 3-4 logcat lines each. This one mattered most: at `Log.e` it survived every level. - `BootRelayDiagnostics` rollup -> INFO, per-relay WASTE/SERVE tables -> DEBUG. The census line carries the aggregate the 655 per-socket errors spelled out. - `Duplicated/SPAM` -> DEBUG: a detection is the filter working, and it is already reported via `relayStats.newSpam()` and `flowSpam` to the UI. - `MarmotDbg` "not a member of group" -> DEBUG: relays serve kind:445 for every group they carry, so this is the steady state. It was burying the real warning next to it ("Generation N already consumed"). Measured on emulator (4 accounts, Tor on): 6,198 -> 433 lines. Flipping VERBOSE_LOGS gives 5,574 back, so nothing was deleted. Co-Authored-By: Claude Opus 5 (1M context) --- .../com/vitorpamplona/amethyst/Amethyst.kt | 27 ++++++++++++++++++- .../amethyst/model/AntiSpamFilter.kt | 16 +++++++++-- .../diagnostics/BootRelayDiagnostics.kt | 25 ++++++++++------- .../loggedIn/DecryptAndIndexProcessor.kt | 7 ++++- .../relay/client/accessories/RelayLogger.kt | 10 ++++++- 5 files changed, 70 insertions(+), 15 deletions(-) diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/Amethyst.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/Amethyst.kt index 2e9b8fb209..a8a45a5ccf 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/Amethyst.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/Amethyst.kt @@ -56,11 +56,36 @@ import java.io.File */ class Amethyst : Application() { init { - Log.minLevel = if (BuildConfig.DEBUG) LogLevel.DEBUG else LogLevel.ERROR + Log.minLevel = DEFAULT_LOG_LEVEL Log.d("AmethystApp") { "Creating App $this" } } companion object { + /** + * Restores the full firehose in debug builds: per-socket relay lifecycle + * (`Connecting…`/`Disconnected`/`OnOpen`), per-second event throughput, per-stream Arti + * SOCKS errors and per-relay census detail. + * + * Off by default. A cold start on the outbox model dials ~400 relays, and those sources + * alone emit ~3.7k of the ~6.2k lines an 80s boot produces — which buries the boot + * narrative and the relay-protocol warnings (`auth-required`, `rate-limited`, + * `unsupported: too many filters`) that are the actionable ones. Flip this, or set + * [Log.minLevel] at runtime, when you need the per-socket detail back. + */ + const val VERBOSE_LOGS = false + + /** + * Debug defaults to INFO so a boot reads as a narrative plus warnings; release defaults to + * WARN rather than ERROR so relay-protocol refusals stay visible in the field — they are + * the highest-value-per-line diagnostics we emit and were previously dropped entirely. + */ + val DEFAULT_LOG_LEVEL: LogLevel = + when { + !BuildConfig.DEBUG -> LogLevel.WARN + VERBOSE_LOGS -> LogLevel.DEBUG + else -> LogLevel.INFO + } + lateinit var instance: AppModules private set } diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/model/AntiSpamFilter.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/model/AntiSpamFilter.kt index dbecbb436f..752492a5c3 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/model/AntiSpamFilter.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/model/AntiSpamFilter.kt @@ -89,7 +89,13 @@ class AntiSpamFilter { val link2 = njumpLink(NAddress.create(event.kind, event.pubKey, event.dTag(), relay)) val link1 = existingAddress?.let { njumpLink(NAddress.create(it.kind, it.pubKeyHex, it.dTag, relay)) } ?: link2 - Log.w("Duplicated/SPAM") { "${relay?.url} $link1 $link2" } + // Debug, not warn: a duplicate detection is this filter working, not a fault, and + // it is already reported where it can be acted on — relayStats.newSpam below and + // the flowSpam emission that drives the UI. On a normal boot this fires ~34 times + // with a pair of njump links each, which is the widest line in the log and says + // nothing the spam counters don't. Keep the links at DEBUG for when you need to + // open the two events and compare them. + Log.d("Duplicated/SPAM") { "${relay?.url} $link1 $link2" } // Log down offenders val spammer = logOffender(hash, event) @@ -118,7 +124,13 @@ class AntiSpamFilter { // LRU cache while the spammer record still matches this hash. val link1 = existingEvent?.let { njumpLink(NEvent.create(it, null, null, relay)) } ?: link2 - Log.w("Duplicated/SPAM") { "${relay?.url} $link1 $link2" } + // Debug, not warn: a duplicate detection is this filter working, not a fault, and + // it is already reported where it can be acted on — relayStats.newSpam below and + // the flowSpam emission that drives the UI. On a normal boot this fires ~34 times + // with a pair of njump links each, which is the widest line in the log and says + // nothing the spam counters don't. Keep the links at DEBUG for when you need to + // open the two events and compare them. + Log.d("Duplicated/SPAM") { "${relay?.url} $link1 $link2" } // Log down offenders val spammer = logOffender(hash, event) diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/relayClient/diagnostics/BootRelayDiagnostics.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/relayClient/diagnostics/BootRelayDiagnostics.kt index cb21713277..2e9506d6ef 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/relayClient/diagnostics/BootRelayDiagnostics.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/relayClient/diagnostics/BootRelayDiagnostics.kt @@ -197,8 +197,13 @@ class BootRelayDiagnostics( fun detach() = client.removeConnectionListener(listener) /** - * One line per relay plus a rollup. Kept to a single Log.w per line so the whole census + * One line per relay plus a rollup. Kept to a single Log call per line so the whole census * survives logcat's per-tag rate limiting on a busy boot. + * + * The rollup goes out at INFO — it is the one boot line worth reading by default, and it + * carries the aggregate that per-socket failure logging used to spell out a few hundred + * times. The per-relay WASTE/SERVE tables are DEBUG: useful when you are chasing a specific + * relay, too long (up to 45 lines a census) to sit in the default log. */ fun dump(atSeconds: Long) { val snapshot = records.toMap() @@ -214,8 +219,8 @@ class BootRelayDiagnostics( r.closed.forEach { (k, v) -> closedTotals[k] = (closedTotals[k] ?: 0) + v.get() } } - Log.w(TAG, "===== boot census @${atSeconds}s =====") - Log.w( + Log.i(TAG, "===== boot census @${atSeconds}s =====") + Log.i( TAG, "pool=${snapshot.size} opened=${opened.size} served_events=${served.size} never_opened=${neverOpened.size} " + "dials=${snapshot.values.sumOf { it.tentatives.get() }} " + @@ -223,18 +228,18 @@ class BootRelayDiagnostics( "reqs=${snapshot.values.sumOf { it.reqsSent.get() }} " + "auths=${snapshot.values.sumOf { it.authsSent.get() }}", ) - Log.w(TAG, "failures_by_cause=" + causeTotals.entries.sortedByDescending { it.value }.joinToString { "${it.key}:${it.value}" }) - Log.w(TAG, "closed_by_prefix=" + closedTotals.entries.sortedByDescending { it.value }.joinToString { "${it.key}:${it.value}" }) + Log.i(TAG, "failures_by_cause=" + causeTotals.entries.sortedByDescending { it.value }.joinToString { "${it.key}:${it.value}" }) + Log.i(TAG, "closed_by_prefix=" + closedTotals.entries.sortedByDescending { it.value }.joinToString { "${it.key}:${it.value}" }) // Relays that cost us dials and gave nothing back, worst first: the wasted-effort list. - Log.w(TAG, "--- top wasted dials (no events received) ---") + Log.d(TAG, "--- top wasted dials (no events received) ---") snapshot .filter { it.value.events.get() == 0 } .entries .sortedByDescending { it.value.tentatives.get() } .take(25) .forEach { (url, r) -> - Log.w( + Log.d( TAG, "WASTE ${url.url} dials=${r.tentatives.get()} opens=${r.opens.get()} " + "fail=[${r.failures.entries.joinToString { "${it.key}:${it.value.get()}" }}] " + @@ -245,17 +250,17 @@ class BootRelayDiagnostics( // The relays actually carrying the boot, so a suppression change can be checked for // coverage loss rather than just CLOSED reduction. - Log.w(TAG, "--- top event providers ---") + Log.d(TAG, "--- top event providers ---") served.entries .sortedByDescending { it.value.events.get() } .take(20) .forEach { (url, r) -> - Log.w( + Log.d( TAG, "SERVE ${url.url} events=${r.events.get()} reqs=${r.reqsSent.get()} eose=${r.eoses.get()} " + "openMs=${r.firstOpenAtMs.get()} eoseMs=${r.firstEoseAtMs.get()} dials=${r.tentatives.get()}", ) } - Log.w(TAG, "===== end census @${atSeconds}s =====") + Log.i(TAG, "===== end census @${atSeconds}s =====") } } diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/ui/screen/loggedIn/DecryptAndIndexProcessor.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/ui/screen/loggedIn/DecryptAndIndexProcessor.kt index b8e81813fd..42f9e17572 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/ui/screen/loggedIn/DecryptAndIndexProcessor.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/ui/screen/loggedIn/DecryptAndIndexProcessor.kt @@ -608,7 +608,12 @@ class GroupEventHandler( return } if (!manager.isMember(groupId)) { - Log.w("MarmotDbg") { + // Debug, not warn: relays serve kind:445 for every group they carry, so traffic for + // groups we are not in is the expected steady state, not an anomaly — unlike the null + // manager and missing 'h' tag above, which stay warnings because they mean we cannot + // process a group we *should* be handling. Fires ~22 times a boot (the same handful of + // events, re-offered on each pass), which drowns the two real warnings next to it. + Log.d("MarmotDbg") { "GroupEventHandler.add: not a member of group=${groupId.take(8)}… — dropping kind:445 ${event.id.take(8)}…" } return diff --git a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip01Core/relay/client/accessories/RelayLogger.kt b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip01Core/relay/client/accessories/RelayLogger.kt index f1b95de2f2..78b304edae 100644 --- a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip01Core/relay/client/accessories/RelayLogger.kt +++ b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip01Core/relay/client/accessories/RelayLogger.kt @@ -101,12 +101,20 @@ class RelayLogger( Log.d(logTag(relay.url), "Disconnected") } + /** + * Debug, not error: under the outbox model a client dials hundreds of relays per boot, + * and a large share of them are dead, unreachable, or refused by the local Tor proxy. + * One line per failed socket is a few hundred lines that say the same four things + * ("SOCKS: TTL expired", "SSLHandshakeException", "Host unreachable", …) and cannot be + * acted on individually. The actionable form is the aggregate — failures bucketed by + * cause, which the consumer's boot census already reports. + */ override fun onCannotConnect( relay: IRelayClient, errorMessage: String, ) { super.onCannotConnect(relay, errorMessage) - Log.e(logTag(relay.url), errorMessage) + Log.d(logTag(relay.url), errorMessage) } } From 6fbcb880dda1bfd899d625536934f108001cb9be Mon Sep 17 00:00:00 2001 From: Vitor Pamplona Date: Wed, 29 Jul 2026 17:58:34 -0400 Subject: [PATCH 2/4] fix(concord): stop pinning entities whose chain crosses a Refounding MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit An entity edited after a CORD-06 Refounding was frozen at its pre-Refounding version and its newer state silently discarded on every refold. Observed on device: entity e83ee182 of a real community held at v1 across 21 consecutive refolds while the current epoch offered v2 citing v1's own hash. `EditionFold.foldEntity` anchored the walk by requiring the offered set to *contain* the floor edition. But a Refounding re-wraps ONE edition per entity (CORD-06 §3, "the last Control Plane state is simply rewrapped"), so an entity edited afterwards has only its successor on the new epoch while the floor edition stays behind on the old one. `prev == floor.hash` is a stronger proof the chain connects than mere presence, and it was being ignored. Worse, the gap made `admissible` — the pre-filter every derived fold shares — keep only `version < floor.version`, so the newer edition was dropped every refold: a role edit, channel rename or banlist entry reverting itself for that user. Checked against Armada (semantics only, AGPLv3) and the canonical spec before changing consensus behaviour. Armada selects an arm per entity, and Amethyst was missing both halves: 1. Its chain-walk arm has three anchor branches to our one; the missing `versions[0] === floor + 1n -> bytesEq(lo.prevHash, floorHash)` is now implemented. 2. Once an entity has been re-wrapped into the epoch being folded it does not chain-walk at all — it anchors on version alone (`bootstrapHead`), because behind a compaction dangling `prev`s are normal and, since seal signatures survive re-wrap, any group-key holder can re-serve a genuine old edition under the current group. A re-wrap cannot raise the version inside the signed seal, so version is what bounds that. This is the half that fixes the observed pin; branch 1 alone would still refuse a floor-v1 entity whose only served edition is v3. Implemented as an optional `snapshot` (the rumor ids of the epoch being folded), defaulting to null = pure chain walk for every other caller. `ConcordCommunityState.fold`/`authorizedHeads` capture it from their own editions argument before `admissible` re-seats older-epoch heads — Amethyst folds exactly one epoch per call, so the argument is the snapshot. `admissible` and `candidates` now ask `foldEntity` whether it gapped rather than re-deriving the test, so the three sites cannot drift apart again. `LOG_GAP` also dedups on (entity, floor, offered): the same refusal was re-reported on every refold, 22 byte-identical warnings a boot, which read as 22 attacks rather than one unchanged state. Deduping is what made the two genuinely distinct refusals visible and led here. Fails open above 4096 distinct refusals — a flood is when the warnings matter most. Anti-rollback is unchanged: all 12 pre-existing floor tests still pass, and three new negative tests cover the fork, the below-floor re-serve, and an entity absent from the snapshot. Device gaps for the pinned entity: 21 -> 0. Co-Authored-By: Claude Opus 5 (1M context) --- .../cord02Community/ConcordCommunityState.kt | 23 ++- .../quartz/concord/cord04Roles/EditionFold.kt | 139 +++++++++++++++--- .../cord04Roles/EditionFoldFloorTest.kt | 78 ++++++++++ 3 files changed, 216 insertions(+), 24 deletions(-) diff --git a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/concord/cord02Community/ConcordCommunityState.kt b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/concord/cord02Community/ConcordCommunityState.kt index 31c74caa7e..b2c8db0179 100644 --- a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/concord/cord02Community/ConcordCommunityState.kt +++ b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/concord/cord02Community/ConcordCommunityState.kt @@ -89,7 +89,13 @@ data class ConcordCommunityState( ownerPubKey: String, floors: Map = emptyMap(), ): Map { - val pool = EditionFold.admissible(editions, floors) + // This call folds exactly one epoch's editions, so they ARE the snapshot: an entity + // appearing here has been re-wrapped into this epoch and must anchor on version, not + // on a `prev` that necessarily dangles back into the epoch the floor came from. The + // known heads `admissible` re-seats are not in the set, so an entity this epoch never + // mentioned correctly keeps chain-walk semantics. + val snapshot = editions.mapTo(HashSet(editions.size)) { it.rumorId } + val pool = EditionFold.admissible(editions, floors, snapshot = snapshot) val authority = AuthorityResolver.resolve(pool, ownerPubKey) val out = HashMap(floors) for ((kind, list) in pool.groupBy { it.entityKind }) { @@ -97,7 +103,7 @@ data class ConcordCommunityState( // Gate the CANDIDATES, don't pre-filter the chain: a rejected edition mid-chain must // stay inert instead of orphaning the authorized editions above it (EditionFold.candidates). val heads = - EditionFold.foldGated(list, floors) { + EditionFold.foldGated(list, floors, snapshot = snapshot) { authority.isOwner(it.author) || (bit != null && authority.hasPermission(it.author, bit)) } for ((entity, head) in heads) { @@ -119,10 +125,15 @@ data class ConcordCommunityState( // authority chains, the per-kind gated folds), so the anti-rollback floor is applied // once, up front, on the shared pool: a rolled-back edition is never seen by any of // them, and the head we already folded is re-seated so the entity keeps its state. - @Suppress("NAME_SHADOWING") - val editions = EditionFold.admissible(editions, floors) + // The editions handed in are one epoch's — the current one — so they are the + // snapshot that selects the compaction arm. Captured BEFORE `admissible` re-seats + // known heads from older epochs, which must not be mistaken for this epoch's. + val snapshot = editions.mapTo(HashSet(editions.size)) { it.rumorId } - val heads = EditionFold.fold(editions, floors).values + @Suppress("NAME_SHADOWING") + val editions = EditionFold.admissible(editions, floors, snapshot = snapshot) + + val heads = EditionFold.fold(editions, floors, snapshot = snapshot).values // Resolve authority from the FULL edition set (not the structural heads): the resolver // folds each role/grant chain through authorized editions only, so a rogue higher-version // edition can't supersede a legit one before authority is even judged. @@ -142,7 +153,7 @@ data class ConcordCommunityState( kind: ControlEntityKind, bit: Int, ): Map = - EditionFold.foldGated(editions.filter { it.entityKind == kind }, floors) { + EditionFold.foldGated(editions.filter { it.entityKind == kind }, floors, snapshot = snapshot) { authority.isOwner(it.author) || authority.hasPermission(it.author, bit) } diff --git a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/concord/cord04Roles/EditionFold.kt b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/concord/cord04Roles/EditionFold.kt index 5d37555d66..4e5b8fa72c 100644 --- a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/concord/cord04Roles/EditionFold.kt +++ b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/concord/cord04Roles/EditionFold.kt @@ -22,6 +22,7 @@ package com.vitorpamplona.quartz.concord.cord04Roles import com.vitorpamplona.quartz.nip01Core.core.toHexKey import com.vitorpamplona.quartz.utils.Log +import com.vitorpamplona.quartz.utils.concurrent.ConcurrentSet /** * The anti-rollback floor for one Control Plane entity: the [version] and @@ -97,16 +98,61 @@ typealias GapReporter = (entityIdHex: String, floorVersion: Long, offeredVersion object EditionFold { private const val TAG = "ConcordEditionFold" + /** + * Rollback refusals already reported by [LOG_GAP], keyed by the exact refusal + * (entity + floor + offered version) rather than by entity, so a *new* rollback + * attempt against the same entity is still reported. + * + * Bounded in practice: a key is only ever added when an entity is offered a chain + * it already refused at a version pair it has not seen, which happens once per real + * rotation, not once per fold. Deliberately never cleared and deliberately + * fail-open — see [LOG_GAP]. + */ + private val reportedGaps = ConcurrentSet() + + /** Above this many distinct refusals, stop deduplicating and just warn. See [LOG_GAP]. */ + private const val MAX_TRACKED_GAPS = 4096 + /** * The default [GapReporter]: a rollback refusal is security-relevant (a rotator * tried to revert an entity), so it is warned, never swallowed. + * + * Warned **once per distinct refusal**, though. Amethyst re-folds the whole buffer + * from scratch on every control-plane change, so an entity stuck refusing a rollback + * re-reports the identical refusal on every refold — 22 byte-identical warnings in an + * 80s cold start, which reads as 22 attacks rather than one unchanged state. The + * dedup is on the message's own contents, so nothing a reader could act on is lost. + * + * Fails **open**: past [MAX_TRACKED_GAPS] distinct refusals it reverts to warning + * every time. A flood of distinct rollback attempts is exactly when the warnings + * matter most, so the failure mode is a noisy log, never a silenced one. */ val LOG_GAP: GapReporter = { entityIdHex, floorVersion, offeredVersion -> - Log.w(TAG) { - "Control-plane rollback refused for entity $entityIdHex: already folded v$floorVersion, offered chain tops out at v$offeredVersion and does not connect to it" + val firstReport = + reportedGaps.size() >= MAX_TRACKED_GAPS || + reportedGaps.add("$entityIdHex@$floorVersion<-$offeredVersion") + + if (firstReport) { + Log.w(TAG) { + "Control-plane rollback refused for entity $entityIdHex: already folded v$floorVersion, offered chain tops out at v$offeredVersion and does not connect to it" + } } } + /** + * The compaction-era head: the highest-version edition at or above [floorVersion], ties + * broken by the lower rumor id — no `prev`, no hash, no contiguity. See the compaction arm + * in [foldEntity] for why version is the right (and only sound) anchor behind a Refounding. + * Null when nothing at or above the floor was offered, which is the only gap this arm has. + */ + private fun bootstrapHead( + editions: List, + floorVersion: Long, + ): ControlEdition? = + editions + .filter { it.version >= floorVersion } + .minWithOrNull(compareByDescending { it.version }.thenBy { it.rumorId }) + /** * Groups mixed [editions] by entity id and folds each to its head, honoring the * per-entity anti-rollback [floors] (keyed by [ControlEdition.entityIdHex]). @@ -119,12 +165,13 @@ object EditionFold { fun fold( editions: Collection, floors: Map = emptyMap(), + snapshot: Set? = null, onGap: GapReporter = LOG_GAP, ): Map { val byEntity = editions.groupBy { it.entityIdHex } val out = HashMap(byEntity.size) for ((entity, list) in byEntity) { - foldEntity(list, floors[entity], onGap)?.let { out[entity] = it } + foldEntity(list, floors[entity], snapshot, onGap)?.let { out[entity] = it } } return out } @@ -134,18 +181,44 @@ object EditionFold { * * With no [floor] this is the fresh-joiner fold: genesis-anchored, falling back * to the lowest-version edition present (the compaction bootstrap). With a - * [floor] the walk is anchored at the exact edition already folded; if that - * edition is not among [editions] the chain is **gapped** and nothing above the - * floor is adopted — [EntityFloor.known] is kept instead (or null when we no - * longer hold it). A head is therefore never below the floor version. + * [floor] the walk is anchored at the edition already folded **or** at its + * immediate successor when that successor cites the floor's hash; failing both + * the chain is **gapped** and nothing above the floor is adopted — + * [EntityFloor.known] is kept instead (or null when we no longer hold it). A head + * is therefore never below the floor version. + * + * [snapshot] is the set of [ControlEdition.rumorId]s belonging to the epoch being + * folded, supplied once a community has Refounded. An entity present in it takes + * the version-anchored compaction arm instead of the chain walk — see the arm + * itself for why. Null (the default) keeps the pure chain walk, which is right for + * a single-epoch fold and for every caller that has no epoch to speak of. */ fun foldEntity( editions: List, floor: EntityFloor? = null, + snapshot: Set? = null, onGap: GapReporter = LOG_GAP, ): ControlEdition? { if (editions.isEmpty()) return floor?.known + // Compaction arm (CORD-06 §3). Once this entity has been re-wrapped into the epoch + // being folded, `prev` chaining across the epoch boundary is meaningless: a Refounding + // trims history and re-wraps the head alone, so the predecessor our floor names stays + // behind on the older epoch and every offered `prev` dangles by design. Anchor on + // VERSION instead — a re-wrap preserves the original author's signature but cannot + // raise the version inside the signed seal, so a re-served stale edition always loses + // to the compacted head. Presence of the entity in the snapshot selects the ARM; + // version selects the HEAD, over every edition we hold and not just the subset. + if (floor != null && snapshot != null && editions.any { it.rumorId in snapshot }) { + return bootstrapHead(editions, floor.version) + ?: run { + // Nothing at or above the floor was served: the head we already accepted + // vanished from the offered set — withheld, so fail closed. + onGap(editions[0].entityIdHex, floor.version, editions.maxOf { it.version }) + floor.known + } + } + // Index editions by version, keeping the tie-break winner where several // share a version (lower rumor id wins). val byVersion = HashMap>() @@ -153,12 +226,25 @@ object EditionFold { var head = if (floor != null) { - // Anchored at what we already folded: the offered set MUST contain that exact - // edition (same version AND same hash — a same-version sibling is a fork, not - // our chain). Failing that, refuse to move at all rather than accept an - // unverifiable jump; walking up from the floor also makes a head below the - // floor version structurally impossible. - editions.firstOrNull { it.version == floor.version && it.hashHex == floor.hashHex } + // Anchored at what we already folded. Below the floor is history we absorbed, so + // the anchor is the lowest offered version at or above it, and only two shapes + // connect: that edition IS the floor (same version AND hash — a same-version + // sibling is a fork, not our chain), or it is the floor's immediate successor and + // cites the floor's hash. The latter is the ordinary cross-epoch shape and is a + // STRONGER proof of connection than mere presence. Anything else is a jump we + // refuse; walking up from the anchor also makes a head below the floor version + // structurally impossible. + val lowest = byVersion.keys.filter { it >= floor.version }.minOrNull() + val winner = lowest?.let { v -> byVersion[v]?.minByOrNull { it.rumorId } } + val anchor = + when { + winner == null -> null + lowest == floor.version -> winner.takeIf { it.hashHex == floor.hashHex } + lowest == floor.version + 1 -> + winner.takeIf { it.prevHash != null && it.prevHash.toHexKey() == floor.hashHex } + else -> null + } + anchor ?: run { onGap(editions[0].entityIdHex, floor.version, editions.maxOf { it.version }) return floor.known @@ -222,12 +308,21 @@ object EditionFold { fun candidates( editions: List, floor: EntityFloor? = null, + snapshot: Set? = null, onGap: GapReporter = LOG_GAP, ): List { - val head = foldEntity(editions, floor, onGap) ?: return emptyList() + // Ask the fold whether it gapped rather than re-deriving the condition here: with the + // compaction arm and the successor anchor there are three ways to connect, and a second + // copy of that test is a bug waiting to drift out of sync with the first. + var gapped = false + val head = + foldEntity(editions, floor, snapshot) { e, f, o -> + gapped = true + onGap(e, f, o) + } ?: return emptyList() // A gap re-seated the known head: nothing from the offered set is admissible above // the floor, so the known edition is the only candidate. - if (floor != null && editions.none { it.version == floor.version && it.hashHex == floor.hashHex }) { + if (floor != null && gapped) { return listOf(head) } val out = ArrayList(editions.size) @@ -247,9 +342,10 @@ object EditionFold { fun foldEntityGated( editions: List, floor: EntityFloor? = null, + snapshot: Set? = null, onGap: GapReporter = LOG_GAP, gate: (ControlEdition) -> Boolean, - ): ControlEdition? = candidates(editions, floor, onGap).firstOrNull(gate) + ): ControlEdition? = candidates(editions, floor, snapshot, onGap).firstOrNull(gate) /** * Groups mixed [editions] by entity id and folds each to the highest-priority @@ -258,13 +354,14 @@ object EditionFold { fun foldGated( editions: Collection, floors: Map = emptyMap(), + snapshot: Set? = null, onGap: GapReporter = LOG_GAP, gate: (ControlEdition) -> Boolean, ): Map { val byEntity = editions.groupBy { it.entityIdHex } val out = HashMap(byEntity.size) for ((entity, list) in byEntity) { - foldEntityGated(list, floors[entity], onGap, gate)?.let { out[entity] = it } + foldEntityGated(list, floors[entity], snapshot, onGap, gate)?.let { out[entity] = it } } return out } @@ -285,6 +382,7 @@ object EditionFold { fun admissible( editions: Collection, floors: Map, + snapshot: Set? = null, onGap: GapReporter = LOG_GAP, ): List { if (floors.isEmpty()) return editions.toList() @@ -298,7 +396,12 @@ object EditionFold { out.addAll(list) continue } - if (list.any { it.version == floor.version && it.hashHex == floor.hashHex }) { + // Same three-way connection test as the fold, asked of the fold itself so the two + // can't drift apart: present at the floor, a successor citing it, or the compaction + // arm's version anchor. + var gapped = false + foldEntity(list, floor, snapshot) { _, _, _ -> gapped = true } + if (!gapped) { out.addAll(list) continue } diff --git a/quartz/src/commonTest/kotlin/com/vitorpamplona/quartz/concord/cord04Roles/EditionFoldFloorTest.kt b/quartz/src/commonTest/kotlin/com/vitorpamplona/quartz/concord/cord04Roles/EditionFoldFloorTest.kt index 186311dea5..4876b089ef 100644 --- a/quartz/src/commonTest/kotlin/com/vitorpamplona/quartz/concord/cord04Roles/EditionFoldFloorTest.kt +++ b/quartz/src/commonTest/kotlin/com/vitorpamplona/quartz/concord/cord04Roles/EditionFoldFloorTest.kt @@ -110,6 +110,84 @@ class EditionFoldFloorTest { assertEquals(v3.rumorId, head?.rumorId) } + /** + * The cross-epoch case, observed on device: a CORD-06 Refounding re-wraps ONE edition per + * entity, so an entity edited *after* the refounding has its successor alone on the new epoch + * while the floor edition stays behind on the old one. The offered set therefore never contains + * the floor edition — but v3 cites its hash, which is a *stronger* proof the chain connects than + * mere presence. Refusing here pins the entity at the floor forever and silently discards the + * newer state (a role edit, a channel rename, a banlist entry) on every refold. + * + * Regression guard: reproduced on device 2026-07-29 (entity e83ee182 pinned at v1 across 21 + * consecutive refolds while epoch 1 offered v2 citing v1's hash). Mirrors Armada's third + * anchor branch, `versions[0] === floor + 1n → bytesEq(lo.prevHash, floorHash)`. + */ + @Test + fun advancesWhenOnlyTheConnectingSuccessorIsOffered() { + val gaps = mutableListOf>() + val head = EditionFold.foldEntity(listOf(v3), floorAtV2) { e, f, o -> gaps += Triple(e, f, o) } + + assertEquals(v3.rumorId, head?.rumorId, "v3.prev == floor.hash, so the chain connects") + assertTrue(gaps.isEmpty(), "a successor citing the floor is not a rollback") + } + + /** But a successor that cites something else is still a fork, and still refused. */ + @Test + fun stillRefusesASuccessorThatDoesNotCiteTheFloor() { + val forked = edition(3, ByteArray(32) { 0x11 }, """{"member":"a","role_ids":["owner-ish"]}""", rumorId = "id-forked") + val gaps = mutableListOf>() + val head = EditionFold.foldEntity(listOf(forked), floorAtV2) { e, f, o -> gaps += Triple(e, f, o) } + + assertEquals(v2.rumorId, head?.rumorId, "an unconnected successor must not be adopted") + assertEquals(listOf(Triple(v2.entityIdHex, 2L, 3L)), gaps, "and the refusal must still be reported") + } + + // ---- the compaction arm (CORD-06 §3) -------------------------------------- + + /** + * Behind a Refounding the predecessor is trimmed, so a `prev` that reaches back to the floor + * is NOT guaranteed — the compacted head can sit any distance above it. Once the entity is in + * the epoch's snapshot the anchor is the version alone, so v3 is adopted over a floor of v1 + * even though nothing links them. This is the case part 1 alone cannot handle. + */ + @Test + fun compactionArmAdoptsTheHighestVersionWithoutAChain() { + val gaps = mutableListOf>() + val head = + EditionFold.foldEntity( + listOf(v3), + v1.asFloor(), + snapshot = setOf(v3.rumorId), + ) { e, f, o -> gaps += Triple(e, f, o) } + + assertEquals(v3.rumorId, head?.rumorId, "version anchors the compaction arm; prev is ignored") + assertTrue(gaps.isEmpty(), "a compacted head above the floor is not a gap") + } + + /** The floor still holds in the compaction arm: a re-served stale edition cannot downgrade us. */ + @Test + fun compactionArmStillRefusesEverythingBelowTheFloor() { + val gaps = mutableListOf>() + val head = + EditionFold.foldEntity( + listOf(v0, v1), + floorAtV2, + snapshot = setOf(v0.rumorId, v1.rumorId), + ) { e, f, o -> gaps += Triple(e, f, o) } + + assertEquals(v2.rumorId, head?.rumorId, "nothing at or above the floor: keep what we knew") + assertEquals(listOf(Triple(v2.entityIdHex, 2L, 1L)), gaps, "and report the refusal") + } + + /** An entity this epoch never re-wrapped is not in the snapshot, so it keeps chain-walk semantics. */ + @Test + fun entityAbsentFromTheSnapshotStillChainWalks() { + val forked = edition(3, ByteArray(32) { 0x11 }, """{"member":"a","role_ids":["owner-ish"]}""", rumorId = "id-forked") + val head = EditionFold.foldEntity(listOf(forked), floorAtV2, snapshot = setOf("some-other-rumor")) { _, _, _ -> } + + assertEquals(v2.rumorId, head?.rumorId, "no snapshot membership -> the chain walk still refuses the fork") + } + /** A floor whose known edition we no longer hold still refuses to move down — it adopts nothing. */ @Test fun refusesRollbackWithNoKnownEditionToFallBackOn() { From 2d7ef2fd936ab14d358d660cfe36d94d1e5a2919 Mon Sep 17 00:00:00 2001 From: Vitor Pamplona Date: Wed, 29 Jul 2026 18:26:05 -0400 Subject: [PATCH 3/4] feat(logs): give the default log a boot narrative MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The INFO default landed a readable log but an incomplete one: only the boot census came from our own code, so the default read as "warnings + census" with nothing between process start and the 20s mark. The first four seconds — the expensive part — were silent. Adds the missing spine, ten INFO lines a boot: - `AmethystApp`: version, process and effective log level at start. The napplet-sandbox skip is promoted too — it is the one line that explains why `instance` is unset and `LocalCache` empty in that process, which otherwise reads as a broken app rather than a deliberately secret-free sandbox. - `LocalPreferences`: how many accounts are saved (nearly every per-account subsystem multiplies by this), then each account's load with its elapsed ms. Decrypting one account's settings is among the most expensive things a cold start does and "which account was slow" is the first question when a boot drags. The six intermediate steps stay at DEBUG. - `TorService`: every status transition, with time since bootstrap started. All status writes now go through one `setStatus` helper instead of nine scattered assignments, so a transition is logged exactly once; self-transitions are skipped because the reset paths reassign `Off` defensively. A stuck `Connecting`, an `Active` that took 40s and a silent drop to `Off` are three different bugs that used to look identical. - `BootRelayDiagnostics`: adds a census at 5s. The pool is assembled and dialling well before 20s, and the early datapoint is what separates "slow to connect" from "connected fine, slow to serve" — on device it reads pool=21 at 5s against pool=359 at 20s. Paid for by folding the `=====` banners down to DEBUG, so a census is 3 INFO lines instead of 5. Reads on device as: I AmethystApp: Amethyst 1.13.1-DEBUG starting in main process (log level INFO) I TorService: Off -> Connecting I LocalPreferences: Found 4 saved account(s) I LocalPreferences: Loaded account npub1gcx… in 394ms I LocalPreferences: Loaded account npub142g… in 760ms I BootRelayDiag: census @5s pool=21 opened=17 served_events=14 … I TorService: Connecting -> Active after 9910ms I BootRelayDiag: census @20s pool=359 opened=158 served_events=78 … Verified by tag on a cold start: +10 INFO lines from our code, no other change to volume. (Raw totals moved more, but that run happened to autoplay video, so 15 extra INFO lines came from Android's media/codec stack — not from this.) Co-Authored-By: Claude Opus 5 (1M context) --- .../com/vitorpamplona/amethyst/Amethyst.kt | 7 +++- .../amethyst/LocalPreferences.kt | 11 +++++- .../diagnostics/BootRelayDiagnostics.kt | 15 ++++---- .../amethyst/ui/tor/TorService.kt | 34 ++++++++++++++----- 4 files changed, 51 insertions(+), 16 deletions(-) diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/Amethyst.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/Amethyst.kt index a8a45a5ccf..45c757c32b 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/Amethyst.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/Amethyst.kt @@ -108,10 +108,15 @@ class Amethyst : Application() { // is self-contained (WebView + IPC), so we skip all app init there and // leave `instance` unset; any accidental use fails fast. if (isNappletSandbox) { - Log.d("AmethystApp") { "Skipping AppModules init in sandbox process" } + // Milestone, not chatter: this is the one line that explains why `instance` is unset + // and `LocalCache` is empty in this process. Without it a napplet-process log looks + // like a broken app rather than a deliberately secret-free sandbox. + Log.i("AmethystApp") { "Napplet sandbox process starting — no account, no AppModules" } return } + Log.i("AmethystApp") { "Amethyst ${BuildConfig.VERSION_NAME} starting in main process (log level ${Log.minLevel})" } + instance = AppModules(this) // Hydrate the device-local favorite-apps list (main process only; the sandbox never reads it). diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/LocalPreferences.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/LocalPreferences.kt index 7ec8e71e50..90c9d1ce8a 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/LocalPreferences.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/LocalPreferences.kt @@ -73,6 +73,7 @@ import com.vitorpamplona.quartz.nip78AppData.AppSpecificDataEvent import com.vitorpamplona.quartz.nip85TrustedAssertions.list.TrustProviderListEvent import com.vitorpamplona.quartz.nipB1Bolt12Zaps.offer.Bolt12OfferListEvent import com.vitorpamplona.quartz.utils.Log +import com.vitorpamplona.quartz.utils.TimeUtils import kotlinx.coroutines.CancellationException import kotlinx.coroutines.Dispatchers import kotlinx.coroutines.async @@ -325,6 +326,9 @@ object LocalPreferences { } if (!newSystemOfAccounts.isNullOrEmpty()) { + // How many accounts are in play is the first thing you need when reading any + // boot log: nearly every per-account subsystem below multiplies by this number. + Log.i("LocalPreferences") { "Found ${newSystemOfAccounts.size} saved account(s)" } newSystemOfAccounts } else { val oldAccounts = getString(PrefKeys.SAVED_ACCOUNTS, null)?.split(COMMA) ?: listOf() @@ -712,6 +716,7 @@ object LocalPreferences { private suspend fun innerLoadCurrentAccountFromEncryptedStorage(npub: String?): AccountSettings? { Log.d("LocalPreferences") { "Load account from file $npub" } + val startedAtMs = TimeUtils.nowMillis() val result = withContext(Dispatchers.IO) { return@withContext with(encryptedPreferences(npub)) { @@ -1017,7 +1022,11 @@ object LocalPreferences { ) } } - Log.d("LocalPreferences") { "Loaded account from file $npub" } + // Milestone with its cost attached. Decrypting and parsing one account's settings is one of + // the most expensive things a cold start does (it resolves a fan of backup events), it runs + // once per account, and "which account was slow" is the first question when a boot drags. + // The six intermediate steps above stay at DEBUG. + Log.i("LocalPreferences") { "Loaded account $npub in ${TimeUtils.nowMillis() - startedAtMs}ms" } return result } diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/relayClient/diagnostics/BootRelayDiagnostics.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/relayClient/diagnostics/BootRelayDiagnostics.kt index 2e9506d6ef..1966bac786 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/relayClient/diagnostics/BootRelayDiagnostics.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/relayClient/diagnostics/BootRelayDiagnostics.kt @@ -56,7 +56,10 @@ import kotlin.concurrent.thread */ class BootRelayDiagnostics( val client: INostrClient, - val dumpAtSeconds: List = listOf(20, 45, 90), + // 5s first: the pool is assembled and dialling well before 20s, and the early datapoint is what + // distinguishes "slow to connect" from "connected fine, slow to serve". Affordable because the + // rollup is now 3 INFO lines rather than 5 — the ===== banners moved to DEBUG. + val dumpAtSeconds: List = listOf(5, 20, 45, 90), ) { companion object { const val TAG = "BootRelayDiag" @@ -219,17 +222,17 @@ class BootRelayDiagnostics( r.closed.forEach { (k, v) -> closedTotals[k] = (closedTotals[k] ?: 0) + v.get() } } - Log.i(TAG, "===== boot census @${atSeconds}s =====") + Log.d(TAG, "===== boot census @${atSeconds}s =====") Log.i( TAG, - "pool=${snapshot.size} opened=${opened.size} served_events=${served.size} never_opened=${neverOpened.size} " + + "census @${atSeconds}s pool=${snapshot.size} opened=${opened.size} served_events=${served.size} never_opened=${neverOpened.size} " + "dials=${snapshot.values.sumOf { it.tentatives.get() }} " + "events=${snapshot.values.sumOf { it.events.get() }} " + "reqs=${snapshot.values.sumOf { it.reqsSent.get() }} " + "auths=${snapshot.values.sumOf { it.authsSent.get() }}", ) - Log.i(TAG, "failures_by_cause=" + causeTotals.entries.sortedByDescending { it.value }.joinToString { "${it.key}:${it.value}" }) - Log.i(TAG, "closed_by_prefix=" + closedTotals.entries.sortedByDescending { it.value }.joinToString { "${it.key}:${it.value}" }) + Log.i(TAG, "census @${atSeconds}s failures_by_cause=" + causeTotals.entries.sortedByDescending { it.value }.joinToString { "${it.key}:${it.value}" }) + Log.i(TAG, "census @${atSeconds}s closed_by_prefix=" + closedTotals.entries.sortedByDescending { it.value }.joinToString { "${it.key}:${it.value}" }) // Relays that cost us dials and gave nothing back, worst first: the wasted-effort list. Log.d(TAG, "--- top wasted dials (no events received) ---") @@ -261,6 +264,6 @@ class BootRelayDiagnostics( "openMs=${r.firstOpenAtMs.get()} eoseMs=${r.firstEoseAtMs.get()} dials=${r.tentatives.get()}", ) } - Log.i(TAG, "===== end census @${atSeconds}s =====") + Log.d(TAG, "===== end census @${atSeconds}s =====") } } diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/ui/tor/TorService.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/ui/tor/TorService.kt index 80fe1eacb7..d270967de4 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/ui/tor/TorService.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/ui/tor/TorService.kt @@ -98,6 +98,24 @@ class TorService( private val _status = MutableStateFlow(TorServiceStatus.Off) override val status: StateFlow = _status.asStateFlow() + /** + * Every status change goes through here so the transition is logged exactly once, at INFO, with + * the time since bootstrap started. + * + * Tor state is the single biggest determinant of whether a boot works — a stuck `Connecting`, + * an `Active` that took 40s, and a silent drop back to `Off` are three completely different + * bugs that used to look identical in the log, because the per-status detail lived only in + * Arti's own DEBUG chatter. Self-transitions are not logged: the reset paths reassign `Off` + * defensively and repeating it adds nothing. + */ + private fun setStatus(next: TorServiceStatus) { + val prev = _status.value + _status.value = next + if (prev::class == next::class && prev.toString() == next.toString()) return + val since = if (bootstrapStartedAtMs > 0) " after ${System.currentTimeMillis() - bootstrapStartedAtMs}ms" else "" + Log.i("TorService") { "${prev::class.simpleName} -> ${next::class.simpleName}$since" } + } + /** * Runtime detector for a rotten guard sample. Arti logs [ALL_GUARDS_DOWN_MARKER] every time it * fails to find a usable guard; [GUARDS_DOWN_THRESHOLD] of those inside [GUARDS_DOWN_WINDOW_MS] @@ -218,11 +236,11 @@ class TorService( lifecycleMutex.withLock { if (proxyRunning.get()) { if (_status.value is TorServiceStatus.Active) return@withLock - _status.value = TorServiceStatus.Connecting + setStatus(TorServiceStatus.Connecting) return@withLock } - _status.value = TorServiceStatus.Connecting + setStatus(TorServiceStatus.Connecting) withContext(Dispatchers.IO) { // Initialize TorClient once — this bootstraps the Tor network. @@ -292,7 +310,7 @@ class TorService( if (initResult != 0) { Log.e("TorService") { "Failed to initialize Arti on retry: error $initResult" } initialized.set(false) - _status.value = TorServiceStatus.Off + setStatus(TorServiceStatus.Off) return@withContext } } @@ -313,7 +331,7 @@ class TorService( if (!started) { Log.e("TorService") { "Failed to start SOCKS proxy after $MAX_PORT_RETRIES attempts" } - _status.value = TorServiceStatus.Off + setStatus(TorServiceStatus.Off) return@withContext } @@ -332,7 +350,7 @@ class TorService( // reset/stop can't clobber it. val startedAt = bootstrapStartedAtMs val elapsed = if (startedAt > 0) System.currentTimeMillis() - startedAt else -1 - _status.value = TorServiceStatus.Active(socksPort) + setStatus(TorServiceStatus.Active(socksPort)) Log.d("TorService") { "Arti SOCKS proxy active on port $socksPort (bootstrap took ${elapsed}ms)" } } } @@ -350,7 +368,7 @@ class TorService( Log.d("TorService") { "SOCKS proxy stopped" } } - _status.value = TorServiceStatus.Off + setStatus(TorServiceStatus.Off) } } @@ -365,7 +383,7 @@ class TorService( lifecycleMutex.withLock { resetLocked() } - _status.value = TorServiceStatus.Off + setStatus(TorServiceStatus.Off) } /** @@ -381,7 +399,7 @@ class TorService( clearAllArtiData() } } - _status.value = TorServiceStatus.Off + setStatus(TorServiceStatus.Off) } /** From edd36b467c671ce91abab4018235c19e1db91260 Mon Sep 17 00:00:00 2001 From: Vitor Pamplona Date: Wed, 29 Jul 2026 21:25:20 -0400 Subject: [PATCH 4/4] test(commons): deflake FeedMetadataCoordinatorTest MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `loadMetadataBatched follows the same retry semantics` failed on the macOS build-desktop runner (1431 tests in the module, 1 failed). The coordinator is fine; the test was wall-clock coupled. It fired call 1 with `timeoutMs = 200`, waited a flat `delay(350)`, then asserted that call 2 re-subscribed. That leaves a 150ms budget for `scope.launch` to be scheduled, subscribe, `awaitAll(200)`, unsubscribe and roll the pubkeys out of `inFlightBatchedMetadata`. On a loaded runner the launch itself can be queued past the margin, so the roll-back lands late, call 2 short-circuits by design, and the assertion fails on healthy code. Every test in the file had the same shape. "Has call 1 finished?" is a question about the job tree, not the clock, and the test owns the scope — so it can just ask. `awaitCoordinatorIdle()` waits until no child of the test scope is active; `waitUntil {}` polls the few preconditions that aren't expressible that way (listener registered before EOSEs are fired). Both carry a generous deadline and fail with a message rather than hanging. Safe here because the coordinator launches nothing at construction and `BatchEoseGate` closes and joins its consumer inside `awaitAll`, so the scope does reach idle. Also made the test fake thread-safe. `subscriptions` and `subscribeCalls` were a plain map and list, written from the coordinator's `Dispatchers.Default` coroutines (and `Dispatchers.IO` in the concurrent-EOSE test) and read from the test thread: an unsynchronized `size` read can be stale, and `fireEose` iterating `subscriptions.values` while a coordinator coroutine calls `unsubscribe` can throw ConcurrentModificationException. Concurrency is the thing under test, so the fake shouldn't be the weak link. Now ConcurrentHashMap + synchronizedList + AtomicInteger, with a snapshot in `fireEose`. Verified deterministic rather than just green: - 3/3 idle, 4/4 under 24 busy loops on 12 cores (the old shape needed the margin; the new one is load-independent). - Still catches its regression: reintroducing the original mark-on-send bug (`eosedRelays > 0` -> `>= 0`) fails exactly this test. A deflaked test that no longer detects the fault would be worse than the flake. This is a pre-existing flake (test dates from 5217035f94, 2026-07-07) unrelated to the rest of this branch, which touches no commons code — fixed here because it blocks the branch's CI. Co-Authored-By: Claude Opus 5 (1M context) --- .../assemblers/FeedMetadataCoordinatorTest.kt | 96 ++++++++++++++----- 1 file changed, 72 insertions(+), 24 deletions(-) diff --git a/commons/src/jvmTest/kotlin/com/vitorpamplona/amethyst/commons/relayClient/assemblers/FeedMetadataCoordinatorTest.kt b/commons/src/jvmTest/kotlin/com/vitorpamplona/amethyst/commons/relayClient/assemblers/FeedMetadataCoordinatorTest.kt index c0f8a609d4..4dc8837e8d 100644 --- a/commons/src/jvmTest/kotlin/com/vitorpamplona/amethyst/commons/relayClient/assemblers/FeedMetadataCoordinatorTest.kt +++ b/commons/src/jvmTest/kotlin/com/vitorpamplona/amethyst/commons/relayClient/assemblers/FeedMetadataCoordinatorTest.kt @@ -31,6 +31,7 @@ import kotlinx.coroutines.Dispatchers import kotlinx.coroutines.SupervisorJob import kotlinx.coroutines.cancel import kotlinx.coroutines.delay +import kotlinx.coroutines.job import kotlinx.coroutines.launch import kotlinx.coroutines.runBlocking import org.junit.After @@ -38,6 +39,9 @@ import org.junit.Assert.assertEquals import org.junit.Assert.assertTrue import org.junit.Before import org.junit.Test +import java.util.Collections +import java.util.concurrent.ConcurrentHashMap +import java.util.concurrent.atomic.AtomicInteger /** * Regression tests for PR #3483 review findings on FeedMetadataCoordinator: @@ -73,34 +77,78 @@ class FeedMetadataCoordinatorTest { private fun pubkey(seed: Int): HexKey = seed.toString(16).padStart(64, '0') + /** + * Suspends until every coroutine the coordinator launched into [scope] has finished. + * + * This is what makes the assertions deterministic. The coordinator does its work in + * `scope.launch { subscribe(); gate.awaitAll(timeout); unsubscribe(); promote-or-roll-back }`, + * so "has call 1 finished?" is a question about the job tree, not about the clock. The tests + * used to answer it with `delay(timeoutMs + margin)` and assert straight after — which holds + * only while the dispatcher is free to start that coroutine promptly. On a loaded runner + * (macOS CI, 1431 tests in the same module) the launch itself can be queued past the margin, + * the roll-back lands late, the next call short-circuits, and the assertion fails on a + * perfectly healthy coordinator. Waiting on the jobs removes the margin entirely. + */ + private suspend fun awaitCoordinatorIdle(timeoutMs: Long = 30_000) { + val deadline = System.currentTimeMillis() + timeoutMs + while (scope.coroutineContext.job.children + .any { it.isActive } + ) { + check(System.currentTimeMillis() < deadline) { "coordinator work did not settle within ${timeoutMs}ms" } + delay(2) + } + } + + /** Polls [predicate] to a deadline. For preconditions we cannot express as job completion. */ + private suspend fun waitUntil( + message: String, + timeoutMs: Long = 30_000, + predicate: () -> Boolean, + ) { + val deadline = System.currentTimeMillis() + timeoutMs + while (!predicate()) { + check(System.currentTimeMillis() < deadline) { "timed out waiting for: $message" } + delay(2) + } + } + /** * Fake client that captures subscribe/unsubscribe and lets the test * drive EOSE notifications on any dispatcher we choose. + * + * Every collection here is written from the coordinator's coroutines (`Dispatchers.Default`, + * and `Dispatchers.IO` for the concurrent-EOSE test) and read from the test thread, so plain + * `mutableMapOf`/`mutableListOf` were two more races: an unsynchronized `size` read can be + * stale, and `fireEose` iterating `subscriptions.values` while a coordinator coroutine calls + * `unsubscribe` can throw ConcurrentModificationException. Concurrency is the thing under + * test here, so the fake must not be the weak link. */ private class ControllableClient( private val delegate: INostrClient = EmptyNostrClient(), ) : INostrClient by delegate { - val subscriptions = mutableMapOf() - val subscribeCalls = mutableListOf>>() - var unsubscribeCallCount = 0 - private set + val subscriptions = ConcurrentHashMap() + val subscribeCalls: MutableList>> = + Collections.synchronizedList(mutableListOf()) + private val unsubscribes = AtomicInteger(0) + val unsubscribeCallCount: Int get() = unsubscribes.get() override fun subscribe( subId: String, filters: Map>, listener: SubscriptionListener?, ) { - subscriptions[subId] = listener + listener?.let { subscriptions[subId] = it } subscribeCalls.add(filters) } override fun unsubscribe(subId: String) { subscriptions.remove(subId) - unsubscribeCallCount++ + unsubscribes.incrementAndGet() } fun fireEose(relay: NormalizedRelayUrl) { - subscriptions.values.filterNotNull().forEach { it.onEose(relay, forFilters = null) } + // Snapshot: a coordinator coroutine may unsubscribe concurrently. + subscriptions.values.toList().forEach { it.onEose(relay, forFilters = null) } } } @@ -119,13 +167,13 @@ class FeedMetadataCoordinatorTest { // Call 1 — no relay EOSEs; must time out. coordinator.loadKind3Batched(pubkeys, timeoutMs = 200) - delay(350) // exceed the timeout + awaitCoordinatorIdle() // call 1 timed out and rolled back // Call 2 — the same pubkeys must be re-subscribed since call 1 // never got a successful EOSE. The old code would silently // short-circuit here. coordinator.loadKind3Batched(pubkeys, timeoutMs = 200) - delay(50) // let the launcher run + awaitCoordinatorIdle() assertEquals( "Zero-EOSE timeout must not permanently dedup pubkeys", @@ -158,13 +206,13 @@ class FeedMetadataCoordinatorTest { val pubkeys = listOf(pubkey(1), pubkey(2)) coordinator.loadKind3Batched(pubkeys, timeoutMs = 1_000) - // Give the launcher time to register the listener before we fire. - delay(50) + // The listener must be registered before we fire, or the EOSEs go nowhere. + waitUntil("subscription registered") { client.subscriptions.isNotEmpty() } indexRelays.forEach(client::fireEose) - delay(200) // let the coordinator finish + promote to queued + awaitCoordinatorIdle() // coordinator finished + promoted to queued coordinator.loadKind3Batched(pubkeys, timeoutMs = 200) - delay(50) + awaitCoordinatorIdle() assertEquals( "Successful call must dedup subsequent identical calls", @@ -187,13 +235,13 @@ class FeedMetadataCoordinatorTest { val pubkeys = listOf(pubkey(1)) coordinator.loadKind3Batched(pubkeys, timeoutMs = 300) - delay(30) + waitUntil("subscription registered") { client.subscriptions.isNotEmpty() } // Only 1 of 3 EOSEs — timeout still fires but we made progress. client.fireEose(relay1) - delay(400) + awaitCoordinatorIdle() coordinator.loadKind3Batched(pubkeys, timeoutMs = 200) - delay(50) + awaitCoordinatorIdle() assertEquals( "≥1 EOSE = progress = promote to queued (avoid re-asking)", @@ -222,7 +270,7 @@ class FeedMetadataCoordinatorTest { ) coordinator.loadKind3Batched(listOf(pubkey(1)), timeoutMs = 2_000) - delay(50) // wait for subscription + waitUntil("subscription registered") { client.subscriptions.isNotEmpty() } // Fire EOSEs concurrently from many dispatchers. val jobs = @@ -235,9 +283,9 @@ class FeedMetadataCoordinatorTest { // The 2nd call must short-circuit — every relay EOSE'd, so // pubkey(1) is now in queuedKind3Pubkeys. - delay(100) + awaitCoordinatorIdle() coordinator.loadKind3Batched(listOf(pubkey(1)), timeoutMs = 200) - delay(50) + awaitCoordinatorIdle() assertEquals( "Under concurrent EOSE from all relays, aggregator must reach target", @@ -261,10 +309,10 @@ class FeedMetadataCoordinatorTest { // Call 1 — zero EOSE, timeout. coordinator.loadMetadataBatched(pubkeys, timeoutMs = 200) - delay(350) + awaitCoordinatorIdle() // Call 2 — must re-subscribe. coordinator.loadMetadataBatched(pubkeys, timeoutMs = 200) - delay(50) + awaitCoordinatorIdle() assertTrue( "Metadata batch also retries on zero-EOSE timeout", @@ -284,13 +332,13 @@ class FeedMetadataCoordinatorTest { ) coordinator.loadKind3Batched(listOf(pubkey(1)), timeoutMs = 200) - delay(50) + waitUntil("subscription registered") { client.subscriptions.isNotEmpty() } // clear() must drop the in-flight tracker even mid-request. coordinator.clear() - delay(300) // let call 1 finish + roll back + awaitCoordinatorIdle() // call 1 finished + rolled back coordinator.loadKind3Batched(listOf(pubkey(1)), timeoutMs = 200) - delay(50) + awaitCoordinatorIdle() assertTrue(client.subscribeCalls.size >= 2) }