mirror of
https://github.com/vitorpamplona/amethyst.git
synced 2026-07-30 19:46:17 +00:00
fix(logs): make the default log a boot narrative, not a firehose
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) <noreply@anthropic.com>
This commit is contained in:
co-authored by
Claude Opus 5
parent
09902fe470
commit
60e3df72b2
@@ -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
|
||||
}
|
||||
|
||||
@@ -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)
|
||||
|
||||
+15
-10
@@ -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 =====")
|
||||
}
|
||||
}
|
||||
|
||||
+6
-1
@@ -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
|
||||
|
||||
+9
-1
@@ -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)
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
Reference in New Issue
Block a user