Merge pull request #3843 from vitorpamplona/fix/rtt-open-from-handshake

rtt-open is the transport's handshake, not our own queueing

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()
     }
 

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()