[CI] [SKIP TESTS] Add detailed Probe-Agent connection diagnostics

backend/shared/MoShiro.Measurement/Net/MsQuicConnection.cs

@@ -40,7 +40,7 @@ internal sealed class MsQuicConnection : IAsyncDisposable, IDatagramConnection
     private readonly byte[]? _expectedPeerSpki;
     private readonly Action<MsQuicConnection>? _closed;
     private readonly Action<IPEndPoint>? _peerAddressChanged;
-    private readonly INodeLog _log;
+    private readonly ContextNodeLog _log;
     private readonly Dictionary<nint, SendState> _sends = [];
     private nint _registration;
     private nint _configuration;
@@ -51,6 +51,14 @@ internal sealed class MsQuicConnection : IAsyncDisposable, IDatagramConnection
     private double? _handshakeDurationMs;
     private QuicTransportSnapshot? _transportSnapshot;
     private long _statisticsAt;
+    private NativeCounters? _nativeCounters;
+    private readonly long _createdAt = Stopwatch.GetTimestamp();
+    private int _localPort;
+    private int _receivedDatagram;
+    private long _sendRejected;
+    private long _sendRejectedAt;
+
+    private sealed record NativeCounters(ulong Sent, ulong Received, long At);
 
     private MsQuicConnection(
         nint handle,
@@ -67,7 +75,7 @@ internal sealed class MsQuicConnection : IAsyncDisposable, IDatagramConnection
         _configuration = configuration;
         _expectedPeerSpki = expectedPeerSpki;
         DatagramHandler = datagramHandler;
-        _log = log;
+        _log = new ContextNodeLog(log, ("quic_id", DiagnosticId), ("side", expectedPeerSpki is null ? "agent" : "probe"));
         _closed = closed;
         _peerAddressChanged = peerAddressChanged;
         _self = GCHandle.Alloc(this);
@@ -75,6 +83,8 @@ internal sealed class MsQuicConnection : IAsyncDisposable, IDatagramConnection
 
     public MsQuicDatagramCallback? DatagramHandler { get; set; }
 
+    internal string DiagnosticId { get; } = Guid.NewGuid().ToString("N");
+
     public IPEndPoint? RemoteEndPoint { get; private set; }
 
     public IPEndPoint? LocalEndPoint => Volatile.Read(ref _handle) is nint handle && handle != 0
@@ -131,6 +141,7 @@ internal sealed class MsQuicConnection : IAsyncDisposable, IDatagramConnection
             double? loss = stats.SendTotalPackets > 0 ? lost * 100.0 / stats.SendTotalPackets : null;
             Volatile.Write(ref _transportSnapshot, new QuicTransportSnapshot(loss, stats.SendTotalPackets,
                 stats.SendCongestionCount, stats.SendEcnCongestionCount, stats.SendPathMtu));
+            Volatile.Write(ref _nativeCounters, new NativeCounters(stats.SendTotalPackets, stats.RecvTotalPackets, now));
         }
         catch (InvalidOperationException)
         {
@@ -153,11 +164,8 @@ internal sealed class MsQuicConnection : IAsyncDisposable, IDatagramConnection
         long handshakeStarted = 0;
         try
         {
-            log.Info("opening MsQuic client registration");
             registration = MsQuicApi.RegistrationOpen("moshiro-probe");
-            log.Info("opening MsQuic client configuration");
             configuration = MsQuicApi.ConfigurationOpen(registration, QuicAlpn.Value);
-            log.Info("loading MsQuic client credentials");
             LoadClientCredentials(configuration);
             var endpoint = new IPEndPoint(address.AddressFamily == AddressFamily.InterNetworkV6 ? IPAddress.IPv6Any : IPAddress.Any, localPort);
             SocketAddress serialized = endpoint.Serialize();
@@ -171,19 +179,18 @@ internal sealed class MsQuicConnection : IAsyncDisposable, IDatagramConnection
             try
             {
                 nint handle = MsQuicApi.ConnectionOpen(registration, s_callback, 0);
-                log.Info("opened MsQuic client connection");
                 connection = new MsQuicConnection(handle, registration, configuration, expectedPeerSpki, datagramHandler, log, null, null);
+                connection.RemoteEndPoint = new IPEndPoint(address, port);
+                connection._localPort = localPort;
                 registration = 0;
                 configuration = 0;
                 MsQuicApi.SetContext(handle, GCHandle.ToIntPtr(connection._self));
-                log.Info("enabling MsQuic datagram receive");
                 MsQuicApi.SetParam(handle, DatagramReceiveEnabled, 1);
-                log.Info("binding MsQuic local address", ("local_port", localPort));
                 MsQuicApi.ConnectionBind(handle, localAddress);
-                log.Info("starting MsQuic QUIC handshake", ("remote", address), ("port", port), ("local_port", localPort));
+                connection._log.Info("starting MsQuic QUIC handshake", ("phase", "quic_handshake"), ("remote", connection.RemoteEndPoint),
+                    ("local_port", localPort), ("timeout_ms", 10_000));
                 handshakeStarted = Stopwatch.GetTimestamp();
                 MsQuicApi.ConnectionStart(handle, connection._configuration, nativeFamily, name, checked((ushort)port));
-                log.Info("MsQuic connection start returned");
             }
             finally
             {
@@ -194,10 +201,14 @@ internal sealed class MsQuicConnection : IAsyncDisposable, IDatagramConnection
             connection._handshakeDurationMs = Stopwatch.GetElapsedTime(handshakeStarted).TotalMilliseconds;
             return connection;
         }
-        catch
+        catch (Exception ex)
         {
             if (connection is not null)
             {
+                if (!ct.IsCancellationRequested)
+                {
+                    connection.LogState(NodeLogLevel.Warn, "QUIC handshake failed", ("exception", ex.GetType().Name));
+                }
                 await connection.DisposeAsync();
             }
 
@@ -211,6 +222,10 @@ internal sealed class MsQuicConnection : IAsyncDisposable, IDatagramConnection
                 MsQuicApi.RegistrationClose(registration);
             }
 
+            if (ex is TimeoutException)
+            {
+                throw new TimeoutException($"QUIC handshake timed out after 10000 ms: remote={address}:{port}, local_udp_port={localPort}", ex);
+            }
             throw;
         }
     }
@@ -226,12 +241,25 @@ internal sealed class MsQuicConnection : IAsyncDisposable, IDatagramConnection
         var connection = new MsQuicConnection(handle, 0, 0, null, datagramHandler, log, closed, peerAddressChanged);
         MsQuicApi.SetContext(handle, GCHandle.ToIntPtr(connection._self));
         MsQuicApi.SetCallbackHandler(handle, s_callback, GCHandle.ToIntPtr(connection._self));
+        connection.RefreshRemoteEndPoint();
+        connection._log.Info("accepted MsQuic QUIC connection", ("phase", "quic_handshake"), ("remote", connection.RemoteEndPoint));
         MsQuicApi.SetParam(handle, DatagramReceiveEnabled, 1);
         // Transport parameters must be set before SetConfiguration starts TLS.
         MsQuicApi.ConnectionSetConfiguration(handle, configuration);
         return connection;
     }
 
+    private int _authenticatedDatagram;
+
+    internal void NoteAuthenticatedDatagram(string? peerId, uint streamId)
+    {
+        if (Interlocked.Exchange(ref _authenticatedDatagram, 1) == 0)
+        {
+            _log.Info("first authenticated measurement datagram", ("phase", "measurement"),
+                ("peer", peerId), ("remote", RemoteEndPoint), ("stream", streamId));
+        }
+    }
+
     public bool Send(ReadOnlySpan<byte> datagram)
     {
         // ConnectionClose must not free the handle or a pending send while
@@ -247,6 +275,7 @@ internal sealed class MsQuicConnection : IAsyncDisposable, IDatagramConnection
         nint handle = Volatile.Read(ref _handle);
         if (handle == 0 || !IsReady || datagram.Length > MaxDatagramBytes)
         {
+            LogSendRejected(handle == 0 ? "connection_closed" : !IsReady ? "datagram_not_ready" : "datagram_too_large", datagram.Length, null);
             return false;
         }
 
@@ -282,9 +311,50 @@ internal sealed class MsQuicConnection : IAsyncDisposable, IDatagramConnection
         }
 
         ReleaseSend(context);
+        LogSendRejected("native_send_failed", datagram.Length, status);
         return false;
     }
 
+    private void LogSendRejected(string reason, int bytes, uint? status)
+    {
+        long rejected = Interlocked.Increment(ref _sendRejected);
+        long now = Stopwatch.GetTimestamp();
+        long previous = Interlocked.Read(ref _sendRejectedAt);
+        if (previous != 0 && Stopwatch.GetElapsedTime(previous, now) < TimeSpan.FromSeconds(30))
+        {
+            return;
+        }
+        if (Interlocked.CompareExchange(ref _sendRejectedAt, now, previous) != previous)
+        {
+            return;
+        }
+
+        _log.Warn("QUIC datagram submission rejected", ("phase", "quic_data"), ("reason", reason), ("remote", RemoteEndPoint),
+            ("bytes", bytes), ("max_datagram", MaxDatagramBytes), ("rejected_total", rejected), ("status", status is { } s ? $"0x{s:X8}" : null));
+    }
+
+    // Diagnostics only read managed snapshots. Never query the native worker from
+    // timeout, heartbeat, or teardown paths: the worker may itself be blocked.
+    private void LogState(NodeLogLevel level, string message, params (string Key, object? Value)[] details)
+    {
+        NativeCounters? counters = Volatile.Read(ref _nativeCounters);
+        _log.Write(level, message, [
+            ("remote", RemoteEndPoint), ("local_port", _localPort),
+            ("phase", _connected.Task.IsCompletedSuccessfully ? "quic_data" : "quic_handshake"),
+            ("elapsed_ms", (long)Stopwatch.GetElapsedTime(_createdAt).TotalMilliseconds),
+            ("handshake_completed", _connected.Task.IsCompletedSuccessfully),
+            ("packets_sent", counters?.Sent), ("packets_received", counters?.Received),
+            ("stats_age_ms", counters is null ? null : (long?)Stopwatch.GetElapsedTime(counters.At).TotalMilliseconds),
+            .. details,
+        ]);
+    }
+
+    internal static string StatusName(uint status) => status == 0 ? "success" : !OperatingSystem.IsLinux() ? "native_error" : status switch
+    {
+        1 => "invalid_state", 22 => "invalid_parameter", 62 => "connection_idle", 103 => "handshake_failure",
+        110 => "connection_timeout", 111 => "connection_refused", 113 => "unreachable", 125 => "aborted", _ => "native_error",
+    };
+
     public async ValueTask DisposeAsync()
     {
         lock (_nativeGate)
@@ -375,22 +445,31 @@ internal sealed class MsQuicConnection : IAsyncDisposable, IDatagramConnection
             switch (eventType)
             {
                 case ConnectionEventConnected:
-                    connection._log.Info("MsQuic QUIC handshake completed");
                     connection.RefreshRemoteEndPoint();
+                    try
+                    {
+                        connection._localPort = connection.LocalEndPoint?.Port ?? connection._localPort;
+                    }
+                    catch (InvalidOperationException)
+                    {
+                        // An unavailable diagnostic address must not fail a successful handshake.
+                    }
                     connection._connected.TrySetResult();
+                    connection.LogState(NodeLogLevel.Info, "MsQuic QUIC handshake completed");
                     break;
                 case ConnectionEventShutdownByTransport:
                 {
                     uint status = unchecked((uint)Marshal.ReadInt32(eventPointer, IntPtr.Size));
                     ulong errorCode = unchecked((ulong)Marshal.ReadInt64(eventPointer, IntPtr.Size * 2));
-                    connection._log.Error("MsQuic QUIC transport shutdown", ("status", $"0x{status:X8}"), ("error_code", errorCode));
+                    connection.LogState(NodeLogLevel.Error, "MsQuic QUIC transport shutdown", ("status", $"0x{status:X8}"),
+                        ("status_name", StatusName(status)), ("error_code", errorCode));
                     connection._connected.TrySetException(new IOException($"QUIC connection closed during handshake (transport status 0x{status:X8}, error code {errorCode})."));
                     break;
                 }
                 case ConnectionEventShutdownByPeer:
                 {
                     ulong errorCode = unchecked((ulong)Marshal.ReadInt64(eventPointer, IntPtr.Size));
-                    connection._log.Warn("MsQuic QUIC peer shutdown", ("error_code", errorCode));
+                    connection.LogState(NodeLogLevel.Warn, "MsQuic QUIC peer shutdown", ("error_code", errorCode));
                     connection._connected.TrySetException(new IOException($"QUIC connection closed during handshake by peer (error code {errorCode})."));
                     break;
                 }
@@ -403,6 +482,7 @@ internal sealed class MsQuicConnection : IAsyncDisposable, IDatagramConnection
                     IPEndPoint? endpoint = ReadEndpoint(address);
                     if (endpoint is not null)
                     {
+                        connection._log.Info("QUIC peer address changed", ("previous", connection.RemoteEndPoint), ("remote", endpoint));
                         connection.RemoteEndPoint = endpoint;
                         connection._peerAddressChanged?.Invoke(endpoint);
                     }
@@ -446,8 +526,13 @@ internal sealed class MsQuicConnection : IAsyncDisposable, IDatagramConnection
     private void OnDatagramStateChanged(nint eventPointer)
     {
         (bool sendEnabled, int maxSendLength) = ReadDatagramState(eventPointer);
-        Volatile.Write(ref _maxDatagramBytes, maxSendLength);
-        Volatile.Write(ref _sendEnabled, sendEnabled ? 1 : 0);
+        int previousMax = Interlocked.Exchange(ref _maxDatagramBytes, maxSendLength);
+        int previousEnabled = Interlocked.Exchange(ref _sendEnabled, sendEnabled ? 1 : 0);
+        if (previousMax != maxSendLength || previousEnabled != (sendEnabled ? 1 : 0))
+        {
+            _log.Info("QUIC datagram negotiation changed", ("phase", "datagram_negotiation"), ("remote", RemoteEndPoint),
+                ("send_enabled", sendEnabled), ("max_datagram", maxSendLength));
+        }
     }
 
     internal static (bool SendEnabled, int MaxSendLength) ReadDatagramState(nint eventPointer)
@@ -475,6 +560,10 @@ internal sealed class MsQuicConnection : IAsyncDisposable, IDatagramConnection
         var buffer = Marshal.PtrToStructure<MsQuicApi.QuicBuffer>(bufferPointer);
         if (buffer.Buffer != 0 && buffer.Length > 0 && buffer.Length <= 65535)
         {
+            if (Interlocked.Exchange(ref _receivedDatagram, 1) == 0)
+            {
+                _log.Info("first QUIC datagram received", ("phase", "quic_data"), ("remote", RemoteEndPoint), ("bytes", buffer.Length));
+            }
             unsafe
             {
             DatagramHandler?.Invoke(this, new ReadOnlySpan<byte>((void*)buffer.Buffer, checked((int)buffer.Length)));
@@ -581,6 +670,8 @@ internal sealed class MsQuicConnection : IAsyncDisposable, IDatagramConnection
 
     private void OnShutdownComplete(nint handle, nint eventPointer)
     {
+        UpdateTransportSnapshot();
+        LogState(NodeLogLevel.Info, "QUIC connection shutdown completed", ("rejected_sends", Interlocked.Read(ref _sendRejected)));
         if (!_connected.Task.IsCompletedSuccessfully)
         {
             byte flags = Marshal.ReadByte(eventPointer, IntPtr.Size);