From 3ca40ca5ef50e02428473c500140cf14cfa9d386 Mon Sep 17 00:00:00 2001 From: Claude Date: Sat, 30 May 2026 16:28:50 +0000 Subject: [PATCH] chore: add DM relay diagnostics timeline (tag: DMPagination) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The reported symptom — messages inside the 7-day window never appear, and the first EOSE takes ~136s on a single-event account — points at the relay/connection path, not the time filter. Nothing currently logs where that time goes or whether a relay is silently rejecting the query (CLOSED "auth-required"/"restricted"). Add DmRelayDiagnosticsLogger, a debug-only RelayConnectionListener that folds the gift-wrap loading timeline into the DMPagination tag with elapsed-time prefixes: - connecting / connected (ping) / disconnected / cannotConnect per relay - REQ sent for gift-wrap subscriptions (kind:1059/1060), with the command - AUTH challenge, NOTICE, and CLOSED (for gift-wrap subs) — the silent-failure tells - gift-wrap EVENT arrivals (relay, sub, createdAt) and their EOSE Wired in AppModules next to the other debug loggers. https://claude.ai/code/session_01B1fmmmX8JjQWH3amMLdvcW --- .../com/vitorpamplona/amethyst/AppModules.kt | 4 + .../diagnostics/DmRelayDiagnosticsLogger.kt | 150 ++++++++++++++++++ 2 files changed, 154 insertions(+) create mode 100644 amethyst/src/main/java/com/vitorpamplona/amethyst/service/relayClient/diagnostics/DmRelayDiagnosticsLogger.kt diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/AppModules.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/AppModules.kt index 7814e880f6..3c81663921 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/AppModules.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/AppModules.kt @@ -69,6 +69,7 @@ import com.vitorpamplona.amethyst.service.playback.service.PlaybackServiceClient import com.vitorpamplona.amethyst.service.relayClient.CacheClientConnector import com.vitorpamplona.amethyst.service.relayClient.RelayProxyClientConnector import com.vitorpamplona.amethyst.service.relayClient.authCommand.model.AuthCoordinator +import com.vitorpamplona.amethyst.service.relayClient.diagnostics.DmRelayDiagnosticsLogger import com.vitorpamplona.amethyst.service.relayClient.notifyCommand.model.NotifyCoordinator import com.vitorpamplona.amethyst.service.relayClient.reqCommand.RelaySubscriptionsCoordinator import com.vitorpamplona.amethyst.service.relayClient.reqCommand.event.EventFinderQueryState @@ -511,6 +512,9 @@ class AppModules( val relayReqStats = if (isDebug) RelayReqStats(client) else null val logger = if (isDebug) RelaySpeedLogger(client) else null + // Focused timeline for the DM / gift-wrap loading path (tag: DMPagination). + val dmDiagnostics = if (isDebug) DmRelayDiagnosticsLogger(client) else null + // Coordinates all subscriptions for the Nostr Client val sources: RelaySubscriptionsCoordinator = RelaySubscriptionsCoordinator( diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/service/relayClient/diagnostics/DmRelayDiagnosticsLogger.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/relayClient/diagnostics/DmRelayDiagnosticsLogger.kt new file mode 100644 index 0000000000..3421d697ea --- /dev/null +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/service/relayClient/diagnostics/DmRelayDiagnosticsLogger.kt @@ -0,0 +1,150 @@ +/* + * Copyright (c) 2025 Vitor Pamplona + * + * Permission is hereby granted, free of charge, to any person obtaining a copy of + * this software and associated documentation files (the "Software"), to deal in + * the Software without restriction, including without limitation the rights to use, + * copy, modify, merge, publish, distribute, sublicense, and/or sell copies of the + * Software, and to permit persons to whom the Software is furnished to do so, + * subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in all + * copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, FITNESS + * FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR + * COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN + * AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION + * WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. + */ +package com.vitorpamplona.amethyst.service.relayClient.diagnostics + +import com.vitorpamplona.quartz.nip01Core.relay.client.INostrClient +import com.vitorpamplona.quartz.nip01Core.relay.client.listeners.RelayConnectionListener +import com.vitorpamplona.quartz.nip01Core.relay.client.single.IRelayClient +import com.vitorpamplona.quartz.nip01Core.relay.commands.toClient.AuthMessage +import com.vitorpamplona.quartz.nip01Core.relay.commands.toClient.ClosedMessage +import com.vitorpamplona.quartz.nip01Core.relay.commands.toClient.EoseMessage +import com.vitorpamplona.quartz.nip01Core.relay.commands.toClient.EventMessage +import com.vitorpamplona.quartz.nip01Core.relay.commands.toClient.Message +import com.vitorpamplona.quartz.nip01Core.relay.commands.toClient.NoticeMessage +import com.vitorpamplona.quartz.nip01Core.relay.commands.toClient.OkMessage +import com.vitorpamplona.quartz.nip01Core.relay.commands.toRelay.Command +import com.vitorpamplona.quartz.nip59Giftwrap.wraps.EphemeralGiftWrapEvent +import com.vitorpamplona.quartz.nip59Giftwrap.wraps.GiftWrapEvent +import com.vitorpamplona.quartz.utils.Log + +/** + * Diagnostic connection listener for the DM / gift-wrap loading path. + * + * It folds the full per-relay timeline — connect, auth challenge, REQ sent, + * gift-wrap events, EOSE, plus any NOTICE/CLOSED rejection — into the single + * `DMPagination` log tag with an elapsed-time prefix, so a slow cold boot can be + * attributed (connection? auth? relay response?) and a silent failure to load + * (e.g. a relay answering CLOSED "auth-required" / "restricted") becomes visible. + * + * Gift-wrap subscriptions are recognised by the kind:1059/1060 filter in the REQ + * we send, so EOSE/CLOSED for those subscriptions can be singled out from the + * rest of the app's relay traffic. + */ +class DmRelayDiagnosticsLogger( + val client: INostrClient, +) { + private val startMs = System.currentTimeMillis() + + private fun at() = System.currentTimeMillis() - startMs + + // Subscription ids whose REQ carried a gift-wrap kind, so we can attribute their EOSE/CLOSED. + private val giftWrapSubIds = mutableSetOf() + + private val listener = + object : RelayConnectionListener { + override fun onConnecting(relay: IRelayClient) { + Log.d(TAG) { "[+${at()}ms] connecting ${relay.url.url}" } + } + + override fun onConnected( + relay: IRelayClient, + pingMillis: Int, + compressed: Boolean, + ) { + Log.d(TAG) { "[+${at()}ms] connected ${relay.url.url} (ping ${pingMillis}ms${if (compressed) ", compressed" else ""})" } + } + + override fun onSent( + relay: IRelayClient, + cmdStr: String, + cmd: Command, + success: Boolean, + ) { + if (!cmdStr.contains("1059") && !cmdStr.contains("1060")) return + reqSubId(cmdStr)?.let { giftWrapSubIds.add(it) } + Log.d(TAG) { "[+${at()}ms] REQ -> ${relay.url.url} success=$success ${cmdStr.take(400)}" } + } + + override fun onIncomingMessage( + relay: IRelayClient, + msgStr: String, + msg: Message, + ) { + when (msg) { + is AuthMessage -> + Log.d(TAG) { "[+${at()}ms] AUTH <- ${relay.url.url} challenge=${msg.challenge.take(12)}…" } + + is NoticeMessage -> + Log.d(TAG) { "[+${at()}ms] NOTICE <- ${relay.url.url} '${msg.message}'" } + + is ClosedMessage -> + if (msg.subId in giftWrapSubIds) { + Log.d(TAG) { "[+${at()}ms] CLOSED <- ${relay.url.url} sub=${msg.subId} reason='${msg.message}'" } + } + + is EoseMessage -> + if (msg.subId in giftWrapSubIds) { + Log.d(TAG) { "[+${at()}ms] EOSE <- ${relay.url.url} sub=${msg.subId}" } + } + + is EventMessage -> + if (msg.event.kind == GiftWrapEvent.KIND || msg.event.kind == EphemeralGiftWrapEvent.KIND) { + Log.d(TAG) { "[+${at()}ms] EVENT <- ${relay.url.url} kind=${msg.event.kind} sub=${msg.subId} createdAt=${msg.event.createdAt}" } + } + + is OkMessage -> + if (!msg.success) { + Log.d(TAG) { "[+${at()}ms] OK(fail) <- ${relay.url.url} '${msg.message}'" } + } + + else -> {} + } + } + + override fun onDisconnected(relay: IRelayClient) { + Log.d(TAG) { "[+${at()}ms] disconnected ${relay.url.url}" } + } + + override fun onCannotConnect( + relay: IRelayClient, + errorMessage: String, + ) { + Log.d(TAG) { "[+${at()}ms] CANNOT CONNECT ${relay.url.url}: $errorMessage" } + } + } + + init { + client.addConnectionListener(listener) + } + + fun destroy() { + client.removeConnectionListener(listener) + } + + companion object { + private const val TAG = "DMPagination" + + // Extracts the subscription id from a `["REQ","",{...}]` command string. + private val REQ_SUB_ID = Regex("^\\[\"REQ\",\"([^\"]+)\"") + + private fun reqSubId(cmdStr: String) = REQ_SUB_ID.find(cmdStr)?.groupValues?.get(1) + } +}