From 2d7ef2fd936ab14d358d660cfe36d94d1e5a2919 Mon Sep 17 00:00:00 2001 From: Vitor Pamplona Date: Wed, 29 Jul 2026 18:26:05 -0400 Subject: [PATCH] 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) } /**