chore(relay): remove diagnostic logging, restore 30s unsubscribe grace

Strips the BgRelayTrace instrumentation added while diagnosing the
background relay-count issues and restores the production grace period.

- LifecycleAwareKeyDataSourceSubscription: UNSUBSCRIBE_GRACE_MILLIS back to
  30s, drop the per-subscription label + logs, refresh the doc to describe
  the LifecycleEventObserver detection.
- RelayPool: drop updatePool trace logs and the now-unused Log import; keep
  the _connectedRelays prune (with a trimmed comment).
- BaseEoseManager: drop the per-assembler relay-count log + Log import.
- SubscriptionController: drop activeRelays(), which only fed that log.

The actual fixes stay: lifecycle-observer teardown detection, the
connected-set prune, and the notification-count throttle + fg/bg wording.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01Ukw6FJPFh3JKGXL532p3ae
This commit is contained in:
Claude
2026-06-18 18:15:32 +00:00
parent dbfd2c4c43
commit 738589fe2f
4 changed files with 15 additions and 50 deletions
@@ -25,7 +25,6 @@ import com.vitorpamplona.quartz.nip01Core.relay.client.INostrClient
import com.vitorpamplona.quartz.nip01Core.relay.client.reqs.SubscriptionListener
import com.vitorpamplona.quartz.nip01Core.relay.client.single.newSubId
import com.vitorpamplona.quartz.nip01Core.relay.client.subscriptions.SubscriptionController
import com.vitorpamplona.quartz.utils.Log
import kotlinx.coroutines.Dispatchers
import kotlinx.coroutines.IO
@@ -54,7 +53,6 @@ abstract class BaseEoseManager<T>(
fun forceInvalidate() {
updateSubscriptions(allKeys())
orchestrator.updateRelays()
Log.d("BgRelayTrace") { "${this::class.simpleName} — keys=${allKeys().size}, relays=${orchestrator.activeRelays().size}" }
}
override fun destroy() {
@@ -28,7 +28,6 @@ import androidx.lifecycle.compose.LocalLifecycleOwner
import com.vitorpamplona.amethyst.commons.relayClient.composeSubscriptionManagers.ComposeSubscriptionManager
import com.vitorpamplona.amethyst.commons.relayClient.composeSubscriptionManagers.MutableComposeSubscriptionManager
import com.vitorpamplona.amethyst.commons.relayClient.composeSubscriptionManagers.MutableQueryState
import com.vitorpamplona.quartz.utils.Log
import kotlinx.coroutines.CoroutineScope
import kotlinx.coroutines.Dispatchers
import kotlinx.coroutines.Job
@@ -37,13 +36,7 @@ import kotlinx.coroutines.cancel
import kotlinx.coroutines.delay
import kotlinx.coroutines.launch
// DIAGNOSTIC: temporarily 0 to test whether unsubscribing the moment the app
// pauses actually disconnects the feed's outbox relays in the background. If the
// 30s grace's delay() was being starved on Dispatchers.Default once backgrounded
// (Doze/app-standby suspends timers), firing immediately on ON_STOP both proves it
// and fixes the leak. Restore to 30_000L (with a wakelock-/foreground-safe timer)
// once confirmed, to keep absorbing short app switches.
private const val UNSUBSCRIBE_GRACE_MILLIS = 0L
private const val UNSUBSCRIBE_GRACE_MILLIS = 30_000L
/**
* A lifecycle-aware version of [KeyDataSourceSubscription] that subscribes
@@ -57,16 +50,14 @@ private const val UNSUBSCRIBE_GRACE_MILLIS = 0L
* rebuilding the relay REQ — which would otherwise lose EOSE state and
* trigger a refetch on return.
*
* The grace timer runs on a dedicated [Dispatchers.Default] scope driven by
* [Lifecycle.currentStateFlow] rather than on the composition's frame-clock
* coupled scope (`rememberCoroutineScope`). On a backgrounded app the UI
* frame clock stops ticking, so a timer scheduled there could be starved and
* the unsubscribe — and therefore the relay disconnect it triggers — might
* never run. This is most visible on the relay feed, whose dedicated one-off
* relay is kept connected by nothing else and would leak forever. Using a
* plain coroutine dispatcher keeps the timer firing while backgrounded;
* [collectLatest] cancels the pending delay automatically the moment the
* lifecycle returns to STARTED.
* Lifecycle transitions are observed with a main-thread [LifecycleEventObserver],
* which fires synchronously during `onStop`/`onStart`. Detecting the transition
* via a background-dispatched flow instead delivered `ON_STOP` up to ~60s late on
* a backgrounded device (the collector only resumed on the next relay keep-alive
* tick), leaving feeds connected long after the app was paused. Only the grace
* *delay* runs on a [Dispatchers.Default] scope, so it isn't gated by the UI
* frame clock (which stops ticking while backgrounded); returning to STARTED
* cancels the pending unsubscribe before it fires.
*
* Use this for heavy feed subscriptions (home, video, discovery, chatroom list)
* that should NOT run when the app is truly in the background. When an
@@ -85,7 +76,6 @@ fun <T> LifecycleAwareKeyDataSourceSubscription(
key = state,
subscribe = { dataSource.subscribe(state) },
unsubscribe = { dataSource.unsubscribe(state) },
label = dataSource::class.simpleName ?: "?",
)
}
@@ -98,7 +88,6 @@ fun <T> LifecycleAwareKeyDataSourceSubscription(
key = states,
subscribe = { dataSource.subscribe(states) },
unsubscribe = { dataSource.unsubscribe(states) },
label = dataSource::class.simpleName ?: "?",
)
}
@@ -111,7 +100,6 @@ fun <T : MutableQueryState> LifecycleAwareKeyDataSourceSubscription(
key = state,
subscribe = { dataSource.subscribe(state) },
unsubscribe = { dataSource.unsubscribe(state) },
label = dataSource::class.simpleName ?: "?",
)
}
@@ -120,19 +108,11 @@ private fun LifecycleAwareSubscription(
key: Any?,
subscribe: () -> Unit,
unsubscribe: () -> Unit,
label: String,
) {
val lifecycle = LocalLifecycleOwner.current.lifecycle
DisposableEffect(key, lifecycle) {
// Detect lifecycle transitions with a main-thread LifecycleEventObserver, NOT by
// collecting currentStateFlow on a background dispatcher. On a real backgrounded
// device the latter delivered ON_STOP ~60s late — it only woke on the next
// NostrClient keep-alive tick — leaving heavy feeds (and ~150 relays) connected
// for that whole minute after the app was paused. A LifecycleEventObserver fires
// synchronously during onStop, so teardown starts immediately.
//
// The grace *delay* still runs on a background scope so it isn't gated by the UI
// Only the grace delay runs on a background scope so it isn't gated by the UI
// frame clock, which stops ticking while the app is backgrounded.
val scope = CoroutineScope(Dispatchers.Default + SupervisorJob())
@@ -147,7 +127,6 @@ private fun LifecycleAwareSubscription(
Lifecycle.Event.ON_START -> {
graceJob?.cancel()
graceJob = null
Log.d("BgRelayTrace") { "subscribe($label)" }
subscribe()
}
@@ -156,7 +135,6 @@ private fun LifecycleAwareSubscription(
graceJob =
scope.launch {
if (UNSUBSCRIBE_GRACE_MILLIS > 0) delay(UNSUBSCRIBE_GRACE_MILLIS)
Log.d("BgRelayTrace") { "unsubscribe($label)" }
unsubscribe()
}
}
@@ -170,7 +148,6 @@ private fun LifecycleAwareSubscription(
onDispose {
lifecycle.removeObserver(observer)
scope.cancel()
Log.d("BgRelayTrace") { "dispose-unsubscribe($label)" }
// Idempotent: removing an absent key is a cheap no-op. Guarantees the
// subscription is released even if the grace timer was still pending.
unsubscribe()
@@ -28,7 +28,6 @@ import com.vitorpamplona.quartz.nip01Core.relay.commands.toClient.Message
import com.vitorpamplona.quartz.nip01Core.relay.commands.toRelay.Command
import com.vitorpamplona.quartz.nip01Core.relay.normalizer.NormalizedRelayUrl
import com.vitorpamplona.quartz.nip01Core.relay.sockets.WebsocketBuilder
import com.vitorpamplona.quartz.utils.Log
import com.vitorpamplona.quartz.utils.cache.LargeCache
import kotlinx.coroutines.flow.MutableStateFlow
import kotlinx.coroutines.flow.asStateFlow
@@ -157,7 +156,6 @@ class RelayPool(
*/
fun updatePool(newRelays: Set<NormalizedRelayUrl>) {
val toRemove = relays.keys() - newRelays
Log.d("BgRelayTrace") { "updatePool — desired=${newRelays.size}, inPool=${relays.size()}, toRemove=${toRemove.size}, connected=${connectedRelaysCount()}" }
var atLeastOne = false
newRelays.forEach { relay ->
@@ -175,7 +173,6 @@ class RelayPool(
if (atLeastOne) {
_availableRelays.update { relays.keys() }
}
Log.d("BgRelayTrace") { "updatePool done — cacheConnected=${connectedRelaysCount()}, flowConnected=${_connectedRelays.value.size}, inPool=${relays.size()}" }
}
fun addRelay(relay: NormalizedRelayUrl): IRelayClient {
@@ -204,11 +201,11 @@ class RelayPool(
relayInPool.disconnect()
// Reflect the disconnect immediately. disconnect() uses OkHttp cancel(),
// whose onClosed/onFailure callback — the only other path that prunes
// _connectedRelays — is async and, when cancelling hundreds of sockets at
// once in the background, frequently never arrives. That left the connected
// set (and the always-on notification's relay count) stale at ~110 while the
// pool itself had already shrunk to the desired ~20. The callback, if it does
// fire later, repeats this subtraction idempotently.
// _connectedRelays — is async and, when cancelling many sockets at once
// (e.g. a feed teardown when the app backgrounds), frequently never arrives.
// That leaves the connected set stale while the pool itself has already
// shrunk. The callback, if it does fire later, repeats this subtraction
// idempotently.
_connectedRelays.update { it - relay }
return true
}
@@ -51,13 +51,6 @@ class SubscriptionController(
fun getSub(subId: String) = subscriptions.get(subId)
/** Distinct relays across all active subscriptions managed by this controller. */
fun activeRelays(): Set<NormalizedRelayUrl> {
val relays = mutableSetOf<NormalizedRelayUrl>()
subscriptions.forEach { _, sub -> sub.filters()?.keys?.let { relays.addAll(it) } }
return relays
}
fun requestNewSubscription(
subId: String,
listener: SubscriptionListener,