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) } }