[release/6.0-rc1] Improve tracing of HTTP/2 PINGs (#57998)

* more HTTP/2 PING logging * test unexpected PING response Co-authored-by: Anton Firszov <[email protected]>
dotnet · Aug 24, 2021 · 2b46720 · 2b46720
1 parent 2170911
commit 2b46720
Show file tree

Hide file tree

Showing 3 changed files with 24 additions and 4 deletions.
diff --git a/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Connection.cs b/src/libraries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2Connection.cs
@@ -915,6 +915,8 @@ private void ProcessPingFrame(FrameHeader frameHeader)
             ReadOnlySpan<byte> pingContent = _incomingBuffer.ActiveSpan.Slice(0, FrameHeader.PingLength);
             long pingContentLong = BinaryPrimitives.ReadInt64BigEndian(pingContent);
 
+            if (NetEventSource.Log.IsEnabled()) Trace($"Received PING frame, content:{pingContentLong} ack: {frameHeader.AckFlag}");
+
             if (frameHeader.AckFlag)
             {
                 ProcessPingAck(pingContentLong);

diff --git a/...raries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2StreamWindowManager.cs b/...raries/System.Net.Http/src/System/Net/Http/SocketsHttpHandler/Http2StreamWindowManager.cs
@@ -213,6 +213,7 @@ internal void OnDataOrHeadersReceived(Http2Connection connection)
 
                     // Send a PING
                     _pingCounter--;
+                    if (NetEventSource.Log.IsEnabled()) connection.Trace($"[FlowControl] Sending RTT PING with payload {_pingCounter}");
                     connection.LogExceptions(connection.SendPingAsync(_pingCounter, isAck: false));
                     _pingSentTimestamp = now;
                     _state = State.PingSent;
@@ -223,6 +224,7 @@ internal void OnPingAckReceived(long payload, Http2Connection connection)
             {
                 if (_state != State.PingSent && _state != State.TerminatingMayReceivePingAck)
                 {
+                    if (NetEventSource.Log.IsEnabled()) connection.Trace($"[FlowControl] Unexpected PING ACK in state {_state}");
                     ThrowProtocolError();
                 }
 
@@ -236,7 +238,10 @@ internal void OnPingAckReceived(long payload, Http2Connection connection)
                 Debug.Assert(payload < 0);
 
                 if (_pingCounter != payload)
+                {
+                    if (NetEventSource.Log.IsEnabled()) connection.Trace($"[FlowControl] Unexpected RTT PING ACK payload {payload}, should be {_pingCounter}.");
                     ThrowProtocolError();
+                }
 
                 RefreshRtt(connection);
                 _state = State.Waiting;

diff --git a/...ibraries/System.Net.Http/tests/FunctionalTests/SocketsHttpHandlerTest.Http2FlowControl.cs b/...ibraries/System.Net.Http/tests/FunctionalTests/SocketsHttpHandlerTest.Http2FlowControl.cs
@@ -51,8 +51,10 @@ public async Task InitialHttp2StreamWindowSize_SentInSettingsFrame()
             Assert.Equal(WindowSize, (int)entry.Value);
         }
 
-        [Fact]
-        public Task InvalidRttPingResponse_RequestShouldFail()
+        [Theory]
+        [InlineData(0)] // Invalid PING payload
+        [InlineData(1)] // Unexpected PING response
+        public Task BadRttPingResponse_RequestShouldFail(int mode)
         {
             return Http2LoopbackServer.CreateClientAndServerAsync(async uri =>
             {
@@ -67,13 +69,24 @@ public Task InvalidRttPingResponse_RequestShouldFail()
                 (int streamId, _) = await connection.ReadAndParseRequestHeaderAsync();
                 await connection.SendDefaultResponseHeadersAsync(streamId);
                 PingFrame pingFrame = await connection.ReadPingAsync(); // expect an RTT PING
-                await connection.SendPingAckAsync(-6666); // send an invalid PING response
+
+                if (mode == 0)
+                {
+                    // Invalid PING payload
+                    await connection.SendPingAckAsync(-6666); // send an invalid PING response
+                }
+                else
+                {
+                    // Unexpected PING response
+                    await connection.SendPingAckAsync(pingFrame.Data); // send an valid PING response
+                    await connection.SendPingAckAsync(pingFrame.Data - 1); // send a second unexpected PING response
+                }
+
                 await connection.SendResponseDataAsync(streamId, new byte[] { 1, 2, 3 }, true); // otherwise fine response
             },
             NoAutoPingResponseHttp2Options);
         }
 
-
         [OuterLoop("Runs long")]
         [Fact]
         public async Task HighBandwidthDelayProduct_ClientStreamReceiveWindowWindowScalesUp()