From 60e3df72b243edf3c5c58feaffa1fd66548c97cc Mon Sep 17 00:00:00 2001 From: Vitor Pamplona Date: Wed, 29 Jul 2026 17:58:11 -0400 Subject: [PATCH] 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) } }