Skip to content

Commit 98c4546

Browse files
JamesNKJamesNK
authored
Add more logging to StreamPool_ManyConcurrentStreams_StreamPoolFull (#56570)
1 parent 7390ce7 commit 98c4546

File tree

3 files changed

+70
-40
lines changed

3 files changed

+70
-40
lines changed

‎src/Servers/Kestrel/Transport.Quic/test/QuicConnectionContextTests.cs

Lines changed: 64 additions & 34 deletions
Original file line numberDiff line numberDiff line change
@@ -8,8 +8,8 @@
88
using Microsoft.AspNetCore.Connections;
99
using Microsoft.AspNetCore.Connections.Features;
1010
using Microsoft.AspNetCore.Internal;
11-
using Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal;
1211
using Microsoft.AspNetCore.InternalTesting;
12+
using Microsoft.AspNetCore.Server.Kestrel.Transport.Quic.Internal;
1313
using Microsoft.Extensions.Logging;
1414
using Microsoft.Extensions.Time.Testing;
1515

@@ -325,7 +325,7 @@ public async Task StreamPool_StreamAbortedOnServer_NotPooled()
325325
var quicConnectionContext = Assert.IsType<QuicConnectionContext>(serverConnection);
326326
Assert.Equal(0, quicConnectionContext.StreamPool.Count);
327327

328-
var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
328+
await using var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
329329
await clientStream.WriteAsync(TestData, completeWrites: true).DefaultTimeout();
330330
var serverStream = await serverConnection.AcceptAsync().DefaultTimeout();
331331
var readResult = await serverStream.Transport.Input.ReadAtLeastAsync(TestData.Length).DefaultTimeout();
@@ -368,7 +368,7 @@ public async Task StreamPool_StreamAbortedOnServerAfterComplete_NotPooled()
368368
var quicConnectionContext = Assert.IsType<QuicConnectionContext>(serverConnection);
369369
Assert.Equal(0, quicConnectionContext.StreamPool.Count);
370370

371-
var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
371+
await using var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
372372
await clientStream.WriteAsync(TestData, completeWrites: true).DefaultTimeout();
373373
var serverStream = await serverConnection.AcceptAsync().DefaultTimeout();
374374
var readResult = await serverStream.Transport.Input.ReadAtLeastAsync(TestData.Length).DefaultTimeout();
@@ -413,7 +413,7 @@ public async Task StreamPool_StreamAbortedOnClient_NotPooled()
413413
var quicConnectionContext = Assert.IsType<QuicConnectionContext>(serverConnection);
414414
Assert.Equal(0, quicConnectionContext.StreamPool.Count);
415415

416-
var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
416+
await using var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
417417
await clientStream.WriteAsync(TestData).DefaultTimeout();
418418

419419
var serverStream = await serverConnection.AcceptAsync().DefaultTimeout();
@@ -462,7 +462,7 @@ public async Task StreamPool_StreamAbortedOnClientAndServer_NotPooled()
462462
var quicConnectionContext = Assert.IsType<QuicConnectionContext>(serverConnection);
463463
Assert.Equal(0, quicConnectionContext.StreamPool.Count);
464464

465-
var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
465+
await using var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
466466
await clientStream.WriteAsync(TestData).DefaultTimeout();
467467

468468
var serverStream = await serverConnection.AcceptAsync().DefaultTimeout();
@@ -558,6 +558,8 @@ public async Task StreamPool_Heartbeat_ExpiredStreamRemoved()
558558
public async Task StreamPool_ManyConcurrentStreams_StreamPoolFull()
559559
{
560560
// Arrange
561+
using var httpEventSource = new HttpEventSourceListener(LoggerFactory);
562+
561563
await using var connectionListener = await QuicTestHelpers.CreateConnectionListenerFactory(LoggerFactory);
562564

563565
var options = QuicTestHelpers.CreateClientConnectionOptions(connectionListener.EndPoint);
@@ -580,52 +582,80 @@ public async Task StreamPool_ManyConcurrentStreams_StreamPoolFull()
580582
const int StreamsSent = 101;
581583
for (var i = 0; i < StreamsSent; i++)
582584
{
583-
streamTasks.Add(SendStream(requestState));
585+
streamTasks.Add(SendStream(Logger, streamIndex: i, requestState));
584586
}
585587

588+
Logger.LogInformation("Waiting for all connections to be received by the server.");
586589
await allConnectionsOnServerTcs.Task.DefaultTimeout();
587590
pauseCompleteTcs.SetResult();
588591

592+
Logger.LogInformation("Waiting for all stream tasks.");
589593
await Task.WhenAll(streamTasks).DefaultTimeout();
594+
Logger.LogInformation("Stream tasks finished.");
590595

591596
// Assert
592597
// Up to 100 streams are pooled.
593598
Assert.Equal(100, quicConnectionContext.StreamPool.Count);
594599

595-
static async Task SendStream(RequestState requestState)
600+
static async Task SendStream(ILogger logger, int streamIndex, RequestState requestState)
596601
{
597-
var clientStream = await requestState.QuicConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
598-
await clientStream.WriteAsync(TestData, completeWrites: true).DefaultTimeout();
599-
var serverStream = await requestState.ServerConnection.AcceptAsync().DefaultTimeout();
600-
var readResult = await serverStream.Transport.Input.ReadAtLeastAsync(TestData.Length).DefaultTimeout();
601-
serverStream.Transport.Input.AdvanceTo(readResult.Buffer.End);
602-
603-
// Input should be completed.
604-
readResult = await serverStream.Transport.Input.ReadAsync();
605-
Assert.True(readResult.IsCompleted);
606-
607-
lock (requestState)
602+
try
608603
{
609-
requestState.ActiveConcurrentConnections++;
610-
if (requestState.ActiveConcurrentConnections == StreamsSent)
604+
logger.LogInformation($"{StreamId(streamIndex)}: Client opening outbound stream.");
605+
await using var clientStream = await requestState.QuicConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
606+
logger.LogInformation($"{StreamId(streamIndex)}: Client writing to stream.");
607+
await clientStream.WriteAsync(TestData, completeWrites: true).DefaultTimeout();
608+
609+
logger.LogInformation($"{StreamId(streamIndex)}: Server accepting incoming stream.");
610+
var serverStream = await requestState.ServerConnection.AcceptAsync().DefaultTimeout();
611+
logger.LogInformation($"{StreamId(streamIndex)}: Server reading data.");
612+
var readResult = await serverStream.Transport.Input.ReadAtLeastAsync(TestData.Length).DefaultTimeout();
613+
serverStream.Transport.Input.AdvanceTo(readResult.Buffer.End);
614+
615+
// Input should be completed.
616+
logger.LogInformation($"{StreamId(streamIndex)}: Server verifying all data received.");
617+
readResult = await serverStream.Transport.Input.ReadAsync();
618+
Assert.True(readResult.IsCompleted);
619+
620+
lock (requestState)
611621
{
612-
requestState.AllConnectionsOnServerTcs.SetResult();
622+
requestState.ActiveConcurrentConnections++;
623+
624+
logger.LogInformation($"{StreamId(streamIndex)}: Increasing active concurrent connections to {requestState.ActiveConcurrentConnections}.");
625+
if (requestState.ActiveConcurrentConnections == StreamsSent)
626+
{
627+
logger.LogInformation($"{StreamId(streamIndex)}: All connections on server.");
628+
requestState.AllConnectionsOnServerTcs.SetResult();
629+
}
613630
}
614-
}
615631

616-
await requestState.PauseCompleteTask;
632+
await requestState.PauseCompleteTask;
617633

618-
// Complete reading and writing.
619-
await serverStream.Transport.Input.CompleteAsync();
620-
await serverStream.Transport.Output.CompleteAsync();
634+
// Complete reading and writing.
635+
logger.LogInformation($"{StreamId(streamIndex)}: Server completing reading and writing.");
636+
await serverStream.Transport.Input.CompleteAsync();
637+
await serverStream.Transport.Output.CompleteAsync();
621638

622-
var quicStreamContext = Assert.IsType<QuicStreamContext>(serverStream);
639+
logger.LogInformation($"{StreamId(streamIndex)}: Client verifying all data received.");
640+
var count = await clientStream.ReadAsync(new byte[1024]);
641+
Assert.Equal(0, count);
623642

624-
// Both send and receive loops have exited.
625-
await quicStreamContext._processingTask.DefaultTimeout();
626-
await quicStreamContext.DisposeAsync();
627-
quicStreamContext.Dispose();
643+
logger.LogInformation($"{StreamId(streamIndex)}: Diposing {nameof(QuicStreamContext)}.");
644+
var quicStreamContext = Assert.IsType<QuicStreamContext>(serverStream);
645+
646+
// Both send and receive loops have exited.
647+
await quicStreamContext._processingTask.DefaultTimeout();
648+
await quicStreamContext.DisposeAsync();
649+
quicStreamContext.Dispose();
650+
}
651+
catch (Exception ex)
652+
{
653+
logger.LogError(ex, $"{StreamId(streamIndex)}: Error.");
654+
throw;
655+
}
628656
}
657+
658+
static string StreamId(int index) => $"Stream-{index}";
629659
}
630660

631661
[ConditionalFact]
@@ -644,7 +674,7 @@ public async Task PersistentState_StreamsReused_StatePersisted()
644674

645675
// Act
646676
Logger.LogInformation("Client starting stream 1");
647-
var clientStream1 = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
677+
await using var clientStream1 = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
648678
await clientStream1.WriteAsync(TestData, completeWrites: true).DefaultTimeout();
649679

650680
Logger.LogInformation("Server accept stream 1");
@@ -672,7 +702,7 @@ public async Task PersistentState_StreamsReused_StatePersisted()
672702
quicStreamContext1.Dispose();
673703

674704
Logger.LogInformation("Client starting stream 2");
675-
var clientStream2 = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
705+
await using var clientStream2 = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
676706
await clientStream2.WriteAsync(TestData, completeWrites: true).DefaultTimeout();
677707

678708
Logger.LogInformation("Server accept stream 2");
@@ -722,7 +752,7 @@ public async Task IProtocolErrorFeature_InvalidErrorCode(long errorCode)
722752
await using var serverConnection = await connectionListener.AcceptAndAddFeatureAsync().DefaultTimeout();
723753

724754
// Act
725-
var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
755+
await using var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
726756
await clientStream.WriteAsync(TestData).DefaultTimeout();
727757

728758
var serverStream = await serverConnection.AcceptAsync().DefaultTimeout();

‎src/Servers/Kestrel/Transport.Quic/test/QuicConnectionListenerTests.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -126,7 +126,7 @@ public async Task ClientCertificate_Required_Sent_Populated()
126126
var serverStreamTask = serverConnection.AcceptAsync().DefaultTimeout();
127127

128128
// Client creates stream
129-
using var clientStream = await quicConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
129+
await using var clientStream = await quicConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
130130
await clientStream.WriteAsync(TestData).DefaultTimeout();
131131

132132
// Server finishes accepting

‎src/Servers/Kestrel/Transport.Quic/test/QuicStreamContextTests.cs

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -64,7 +64,7 @@ public async Task BidirectionalStream_ReadAborted_NotPooled()
6464
await using var serverConnection = await connectionListener.AcceptAndAddFeatureAsync().DefaultTimeout();
6565

6666
// Act
67-
var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
67+
await using var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
6868
await clientStream.WriteAsync(TestData).DefaultTimeout();
6969
var serverStream = await serverConnection.AcceptAsync().DefaultTimeout();
7070
var readResult = await serverStream.Transport.Input.ReadAtLeastAsync(TestData.Length).DefaultTimeout();
@@ -113,7 +113,7 @@ public async Task BidirectionalStream_ClientAbortedAfterDisposeCalled_NotPooled(
113113

114114
// Act
115115
Logger.LogInformation("Client starting stream.");
116-
var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
116+
await using var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
117117
await clientStream.WriteAsync(TestData).DefaultTimeout();
118118

119119
var readTask = clientStream.ReadUntilEndAsync();
@@ -181,7 +181,7 @@ public async Task BidirectionalStream_ServerWritesDataAndDisposes_ClientReadsDat
181181

182182
// Act
183183
Logger.LogInformation("Client starting stream.");
184-
var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
184+
await using var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
185185
await clientStream.WriteAsync(TestData, completeWrites: true).DefaultTimeout();
186186
var serverStream = await serverConnection.AcceptAsync().DefaultTimeout();
187187

@@ -542,7 +542,7 @@ public async Task IProtocolErrorFeature_InvalidErrorCode(long errorCode)
542542
await using var serverConnection = await connectionListener.AcceptAndAddFeatureAsync().DefaultTimeout();
543543

544544
// Act
545-
var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
545+
await using var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
546546
await clientStream.WriteAsync(TestData).DefaultTimeout();
547547

548548
var serverStream = await serverConnection.AcceptAsync().DefaultTimeout();
@@ -569,7 +569,7 @@ public async Task IStreamAbortFeature_InvalidErrorCode(long errorCode)
569569
await using var serverConnection = await connectionListener.AcceptAndAddFeatureAsync().DefaultTimeout();
570570

571571
// Act
572-
var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
572+
await using var clientStream = await clientConnection.OpenOutboundStreamAsync(QuicStreamType.Bidirectional);
573573
await clientStream.WriteAsync(TestData).DefaultTimeout();
574574

575575
var serverStream = await serverConnection.AcceptAsync().DefaultTimeout();

0 commit comments

Comments
 (0)