From 7d91931b7579b4b838b4f816049d216a2f68c35e Mon Sep 17 00:00:00 2001 From: Vitor Pamplona Date: Sat, 1 Aug 2026 12:58:01 -0400 Subject: [PATCH] rtt-open is the transport's handshake, not our own queueing MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit It was measured from onConnecting to onConnected, which includes the time the call sat in the client's dispatcher queue. Under a 16,507-relay fan-out that queue dominates everything else: published records showed a median rtt-open of 33.5 SECONDS and a max of 90, against a true minimum of 140ms. That is the field aggregators rank relays by, so it was worse than publishing nothing — a signed claim that healthy relays are slow, when the slowness was ours. pingMillis already carried the right number and was being handed to the listener unused: BasicOkHttpWebSocket computes it as receivedResponseAtMillis - sentRequestAtMillis, so it starts when the upgrade request actually goes out and excludes everything before it. Zero or negative means the transport could not time the handshake, and then no timing is published rather than a fabricated one — the same rule the rest of this class already followed. Co-Authored-By: Claude Opus 5 (1M context) --- .../reachability/RelayObserver.kt | 20 +++++++++++----- .../reachability/RelayObserverTest.kt | 23 +++++++++++++++++++ 2 files changed, 37 insertions(+), 6 deletions(-) diff --git a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip66RelayMonitor/reachability/RelayObserver.kt b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip66RelayMonitor/reachability/RelayObserver.kt index bde310489c..1e293e3d05 100644 --- a/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip66RelayMonitor/reachability/RelayObserver.kt +++ b/quartz/src/commonMain/kotlin/com/vitorpamplona/quartz/nip66RelayMonitor/reachability/RelayObserver.kt @@ -73,10 +73,6 @@ class RelayObserver : RelayConnectionListener { class Observation( val url: NormalizedRelayUrl, ) { - // Monotonic marks, not wall clock: these measure durations, and a clock - // step mid-connection must not produce a negative or wild latency. - @Volatile var connectingAt: TimeSource.Monotonic.ValueTimeMark? = null - @Volatile var rttOpenMs: Long? = null @Volatile var firstReqAt: TimeSource.Monotonic.ValueTimeMark? = null @@ -124,7 +120,6 @@ class RelayObserver : RelayConnectionListener { override fun onConnecting(relay: IRelayClient) { val o = of(relay) - o.connectingAt = TimeSource.Monotonic.markNow() // Cleared, not kept: a reconnect is a fresh attempt, and carrying an old // error forward would report a working relay as broken for as long as the // process lives after one bad minute. @@ -140,7 +135,20 @@ class RelayObserver : RelayConnectionListener { val o = of(relay) o.reachable = true o.error = null - o.connectingAt?.let { o.rttOpenMs = it.elapsedNow().inWholeMilliseconds.coerceAtLeast(0) } + // The TRANSPORT's number, not ours. pingMillis is + // receivedResponseAtMillis - sentRequestAtMillis, so it starts when the + // upgrade request actually goes out and excludes everything before it. + // + // Timing onConnecting -> onConnected instead measures our own dispatcher + // queue as if it were the relay's latency. Under a 16,507-relay fan-out + // that queue dominates: published records showed a median rtt-open of + // 33.5 SECONDS and a max of 90, against a true minimum of 140ms. That is + // the field aggregators rank relays by, so it was worse than publishing + // nothing — a slow-looking relay that is not slow. + // + // Zero or negative means the transport could not time it; no timing is + // published rather than a fabricated one. + o.rttOpenMs = pingMillis.toLong().takeIf { it > 0 } o.touch() } diff --git a/quartz/src/commonTest/kotlin/com/vitorpamplona/quartz/nip66RelayMonitor/reachability/RelayObserverTest.kt b/quartz/src/commonTest/kotlin/com/vitorpamplona/quartz/nip66RelayMonitor/reachability/RelayObserverTest.kt index dbda038e0f..6522dd5c64 100644 --- a/quartz/src/commonTest/kotlin/com/vitorpamplona/quartz/nip66RelayMonitor/reachability/RelayObserverTest.kt +++ b/quartz/src/commonTest/kotlin/com/vitorpamplona/quartz/nip66RelayMonitor/reachability/RelayObserverTest.kt @@ -72,6 +72,29 @@ class RelayObserverTest { // ---- what we measured --------------------------------------------------- + @Test + fun `rtt-open is the transport handshake rather than our own queueing`() { + // pingMillis is receivedResponseAtMillis - sentRequestAtMillis: it starts + // when the upgrade request goes out, so it excludes time the call spent + // queued in the client's dispatcher. Timing the enqueue instead published + // our own backlog as the relay's latency — a median of 33.5 SECONDS on a + // 16,507-relay fan-out, against a true minimum of 140ms — into the field + // aggregators rank relays by. + val o = RelayObserver() + o.onConnected(client(url), 140, false) + assertEquals(140L, o.only().rttOpenMs) + } + + @Test + fun `a handshake the transport could not time publishes no time`() { + val o = RelayObserver() + o.onConnected(client(url), 0, false) + + val obs = o.only() + assertTrue(obs.reachable, "it opened, and that much is known") + assertNull(obs.rttOpenMs, "unmeasurable is not zero") + } + @Test fun `an opened connection is timed rather than assumed`() { val o = RelayObserver()