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