Skip to content

Commit 49c01ee

Browse files
halter73halter73
authored
Log clearer handshake failures in SignalR .NET client (#10433)
1 parent 54fff2b commit 49c01ee

File tree

7 files changed

+1035
-872
lines changed

7 files changed

+1035
-872
lines changed

‎src/SignalR/clients/csharp/Client.Core/src/HubConnection.Log.cs

Lines changed: 25 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -103,7 +103,7 @@ private static class Log
103103
LoggerMessage.Define<string>(LogLevel.Error, new EventId(34, "ErrorInvokingClientSideMethod"), "Invoking client side method '{MethodName}' failed.");
104104

105105
private static readonly Action<ILogger, Exception> _errorProcessingHandshakeResponse =
106-
LoggerMessage.Define(LogLevel.Error, new EventId(35, "ErrorReceivingHandshakeResponse"), "Error processing the handshake response.");
106+
LoggerMessage.Define(LogLevel.Error, new EventId(35, "ErrorReceivingHandshakeResponse"), "The underlying connection closed while processing the handshake response. See exception for details.");
107107

108108
private static readonly Action<ILogger, string, Exception> _handshakeServerError =
109109
LoggerMessage.Define<string>(LogLevel.Error, new EventId(36, "HandshakeServerError"), "Server returned handshake error: {Error}");
@@ -240,6 +240,15 @@ private static class Log
240240
private static readonly Action<ILogger, HubConnectionState, HubConnectionState, Exception> _attemptingStateTransition =
241241
LoggerMessage.Define<HubConnectionState, HubConnectionState>(LogLevel.Trace, new EventId(80, "AttemptingStateTransition"), "The HubConnection is attempting to transition from the {ExpectedState} state to the {NewState} state.");
242242

243+
private static readonly Action<ILogger, Exception> _errorInvalidHandshakeResponse =
244+
LoggerMessage.Define(LogLevel.Error, new EventId(81, "ErrorInvalidHandshakeResponse"), "Received an invalid handshake response.");
245+
246+
private static readonly Action<ILogger, double, Exception> _errorHandshakeTimedOut =
247+
LoggerMessage.Define<double>(LogLevel.Error, new EventId(82, "ErrorHandshakeTimedOut"), "The handshake timed out after {HandshakeTimeoutSeconds} seconds.");
248+
249+
private static readonly Action<ILogger, Exception> _errorHandshakeCanceled =
250+
LoggerMessage.Define(LogLevel.Error, new EventId(83, "ErrorHandshakeCanceled"), "The handshake was canceled by the client.");
251+
243252
public static void PreparingNonBlockingInvocation(ILogger logger, string target, int count)
244253
{
245254
_preparingNonBlockingInvocation(logger, target, count, null);
@@ -640,6 +649,21 @@ public static void AttemptingStateTransition(ILogger logger, HubConnectionState
640649
{
641650
_attemptingStateTransition(logger, expectedState, newState, null);
642651
}
652+
653+
public static void ErrorInvalidHandshakeResponse(ILogger logger, Exception exception)
654+
{
655+
_errorInvalidHandshakeResponse(logger, exception);
656+
}
657+
658+
public static void ErrorHandshakeTimedOut(ILogger logger, TimeSpan handshakeTimeout, Exception exception)
659+
{
660+
_errorHandshakeTimedOut(logger, handshakeTimeout.TotalSeconds, exception);
661+
}
662+
663+
public static void ErrorHandshakeCanceled(ILogger logger, Exception exception)
664+
{
665+
_errorHandshakeCanceled(logger, exception);
666+
}
643667
}
644668
}
645669
}

‎src/SignalR/clients/csharp/Client.Core/src/HubConnection.cs

Lines changed: 53 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -253,9 +253,9 @@ private async Task StartAsyncInner(CancellationToken cancellationToken = default
253253
throw new InvalidOperationException($"The {nameof(HubConnection)} cannot be started while {nameof(StopAsync)} is running.");
254254
}
255255

256-
using (var cts = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken, _state.StopCts.Token))
256+
using (CreateLinkedToken(cancellationToken, _state.StopCts.Token, out var linkedToken))
257257
{
258-
await StartAsyncCore(cancellationToken);
258+
await StartAsyncCore(linkedToken);
259259
}
260260

261261
_state.ChangeState(HubConnectionState.Connecting, HubConnectionState.Connected);
@@ -1018,20 +1018,23 @@ private async Task HandshakeAsync(ConnectionState startingConnectionState, Cance
10181018
if (sendHandshakeResult.IsCompleted)
10191019
{
10201020
// The other side disconnected
1021-
throw new InvalidOperationException("The server disconnected before the handshake was completed");
1021+
var ex = new IOException("The server disconnected before the handshake could be started.");
1022+
Log.ErrorReceivingHandshakeResponse(_logger, ex);
1023+
throw ex;
10221024
}
10231025

10241026
var input = startingConnectionState.Connection.Transport.Input;
10251027

1028+
using var handshakeCts = new CancellationTokenSource(HandshakeTimeout);
1029+
10261030
try
10271031
{
1028-
using (var handshakeCts = new CancellationTokenSource(HandshakeTimeout))
10291032
// cancellationToken already contains _state.StopCts.Token, so we don't have to link it again
1030-
using (var cts = CancellationTokenSource.CreateLinkedTokenSource(cancellationToken, handshakeCts.Token))
1033+
using (CreateLinkedToken(cancellationToken, handshakeCts.Token, out var linkedToken))
10311034
{
10321035
while (true)
10331036
{
1034-
var result = await input.ReadAsync(cts.Token);
1037+
var result = await input.ReadAsync(linkedToken);
10351038

10361039
var buffer = result.Buffer;
10371040
var consumed = buffer.Start;
@@ -1057,6 +1060,7 @@ private async Task HandshakeAsync(ConnectionState startingConnectionState, Cance
10571060
$"Unable to complete handshake with the server due to an error: {message.Error}");
10581061
}
10591062

1063+
Log.HandshakeComplete(_logger);
10601064
break;
10611065
}
10621066
}
@@ -1075,17 +1079,34 @@ private async Task HandshakeAsync(ConnectionState startingConnectionState, Cance
10751079
}
10761080
}
10771081
}
1082+
catch (HubException)
1083+
{
1084+
// This was already logged as a HandshakeServerError
1085+
throw;
1086+
}
1087+
catch (InvalidDataException ex)
1088+
{
1089+
Log.ErrorInvalidHandshakeResponse(_logger, ex);
1090+
throw;
1091+
}
1092+
catch (OperationCanceledException ex)
1093+
{
1094+
if (handshakeCts.IsCancellationRequested)
1095+
{
1096+
Log.ErrorHandshakeTimedOut(_logger, HandshakeTimeout, ex);
1097+
}
1098+
else
1099+
{
1100+
Log.ErrorHandshakeCanceled(_logger, ex);
1101+
}
10781102

1079-
// shutdown if we're unable to read handshake
1080-
// Ignore HubException because we throw it when we receive a handshake response with an error
1081-
// And because we already have the error, we don't need to log that the handshake failed
1082-
catch (Exception ex) when (!(ex is HubException))
1103+
throw;
1104+
}
1105+
catch (Exception ex)
10831106
{
10841107
Log.ErrorReceivingHandshakeResponse(_logger, ex);
10851108
throw;
10861109
}
1087-
1088-
Log.HandshakeComplete(_logger);
10891110
}
10901111

10911112
private async Task ReceiveLoop(ConnectionState connectionState)
@@ -1485,6 +1506,26 @@ async Task RunReconnectedEventAsync()
14851506
}
14861507
}
14871508

1509+
private IDisposable CreateLinkedToken(CancellationToken token1, CancellationToken token2, out CancellationToken linkedToken)
1510+
{
1511+
if (!token1.CanBeCanceled)
1512+
{
1513+
linkedToken = token2;
1514+
return null;
1515+
}
1516+
else if (!token2.CanBeCanceled)
1517+
{
1518+
linkedToken = token1;
1519+
return null;
1520+
}
1521+
else
1522+
{
1523+
var cts = CancellationTokenSource.CreateLinkedTokenSource(token1, token2);
1524+
linkedToken = cts.Token;
1525+
return cts;
1526+
}
1527+
}
1528+
14881529
// Debug.Assert plays havoc with Unit Tests. But I want something that I can "assert" only in Debug builds.
14891530
[Conditional("DEBUG")]
14901531
private static void SafeAssert(bool condition, string message, [CallerMemberName] string memberName = null, [CallerFilePath] string fileName = null, [CallerLineNumber] int lineNumber = 0)
@@ -1495,7 +1536,6 @@ private static void SafeAssert(bool condition, string message, [CallerMemberName
14951536
}
14961537
}
14971538

1498-
14991539
private class Subscription : IDisposable
15001540
{
15011541
private readonly InvocationHandler _handler;

‎src/SignalR/clients/csharp/Client/test/UnitTests/HttpConnectionTests.ConnectionLifecycle.cs

Lines changed: 20 additions & 21 deletions
Original file line numberDiff line numberDiff line change
@@ -43,13 +43,13 @@ await WithConnectionAsync(
4343
CreateConnection(loggerFactory: LoggerFactory, transport: new TestTransport(onTransportStart: SyncPoint.Create(out var syncPoint))),
4444
async (connection) =>
4545
{
46-
var firstStart = connection.StartAsync(TransferFormat.Text).OrTimeout();
47-
await syncPoint.WaitForSyncPoint();
48-
var secondStart = connection.StartAsync(TransferFormat.Text).OrTimeout();
46+
var firstStart = connection.StartAsync(TransferFormat.Text);
47+
await syncPoint.WaitForSyncPoint().OrTimeout();
48+
var secondStart = connection.StartAsync(TransferFormat.Text);
4949
syncPoint.Continue();
5050

51-
await firstStart;
52-
await secondStart;
51+
await firstStart.OrTimeout();
52+
await secondStart.OrTimeout();
5353
});
5454
}
5555
}
@@ -64,10 +64,10 @@ await WithConnectionAsync(
6464
async (connection) =>
6565
{
6666
await connection.StartAsync(TransferFormat.Text).OrTimeout();
67-
await connection.DisposeAsync();
67+
await connection.DisposeAsync().OrTimeout();
6868
var exception =
6969
await Assert.ThrowsAsync<ObjectDisposedException>(
70-
async () => await connection.StartAsync(TransferFormat.Text).OrTimeout());
70+
async () => await connection.StartAsync(TransferFormat.Text)).OrTimeout();
7171

7272
Assert.Equal(nameof(HttpConnection), exception.ObjectName);
7373
});
@@ -121,7 +121,7 @@ await WithConnectionAsync(
121121
async (connection) =>
122122
{
123123
Assert.Equal(0, startCounter);
124-
await connection.StartAsync(TransferFormat.Text);
124+
await connection.StartAsync(TransferFormat.Text).OrTimeout();
125125
Assert.Equal(passThreshold, startCounter);
126126
});
127127
}
@@ -154,7 +154,7 @@ await WithConnectionAsync(
154154
transport: new TestTransport(onTransportStart: OnTransportStart)),
155155
async (connection) =>
156156
{
157-
var ex = await Assert.ThrowsAsync<AggregateException>(() => connection.StartAsync(TransferFormat.Text));
157+
var ex = await Assert.ThrowsAsync<AggregateException>(() => connection.StartAsync(TransferFormat.Text)).OrTimeout();
158158
Assert.Equal("Unable to connect to the server with any of the available transports. " +
159159
"(WebSockets failed: Transport failed to start) (ServerSentEvents failed: Transport failed to start) (LongPolling failed: Transport failed to start)",
160160
ex.Message);
@@ -179,8 +179,7 @@ await WithConnectionAsync(
179179
CreateConnection(loggerFactory: LoggerFactory),
180180
async (connection) =>
181181
{
182-
await connection.DisposeAsync();
183-
182+
await connection.DisposeAsync().OrTimeout();
184183
});
185184
}
186185
}
@@ -203,7 +202,7 @@ await WithConnectionAsync(
203202
await transportStart.WaitForSyncPoint().OrTimeout();
204203

205204
// While the transport is starting, dispose the connection
206-
var disposeTask = connection.DisposeAsync().OrTimeout();
205+
var disposeTask = connection.DisposeAsync();
207206
transportStart.Continue(); // We need to release StartAsync, because Dispose waits for it.
208207

209208
// Wait for start to finish, as that has to finish before the transport will be stopped.
@@ -214,7 +213,7 @@ await WithConnectionAsync(
214213
transportStop.Continue();
215214

216215
// Dispose should finish
217-
await disposeTask;
216+
await disposeTask.OrTimeout();
218217
});
219218
}
220219
}
@@ -234,22 +233,22 @@ await WithConnectionAsync(
234233
await connection.StartAsync(TransferFormat.Text).OrTimeout();
235234

236235
// Dispose the connection
237-
var stopTask = connection.DisposeAsync().OrTimeout();
236+
var stopTask = connection.DisposeAsync();
238237

239238
// Once the transport starts shutting down
240-
await transportStop.WaitForSyncPoint();
239+
await transportStop.WaitForSyncPoint().OrTimeout();
241240
Assert.False(stopTask.IsCompleted);
242241

243242
// Start disposing again, and then let the first dispose continue
244-
var disposeTask = connection.DisposeAsync().OrTimeout();
243+
var disposeTask = connection.DisposeAsync();
245244
transportStop.Continue();
246245

247246
// Wait for the tasks to complete
248247
await stopTask.OrTimeout();
249248
await disposeTask.OrTimeout();
250249

251250
// We should be disposed and thus unable to restart.
252-
await AssertDisposedAsync(connection);
251+
await AssertDisposedAsync(connection).OrTimeout();
253252
});
254253
}
255254
}
@@ -316,7 +315,7 @@ await WithConnectionAsync(
316315
await connection.Transport.Output.WriteAsync(new byte[] { 0x42 }).OrTimeout();
317316

318317
// We should get the exception in the transport input completion.
319-
await Assert.ThrowsAsync<HttpRequestException>(() => connection.Transport.Input.WaitForWriterToComplete());
318+
await Assert.ThrowsAsync<HttpRequestException>(() => connection.Transport.Input.WaitForWriterToComplete()).OrTimeout();
320319
});
321320
}
322321
}
@@ -371,19 +370,19 @@ await WithConnectionAsync(
371370
CreateConnection(httpHandler, loggerFactory: LoggerFactory, transport: sse),
372371
async (connection) =>
373372
{
374-
var startTask = connection.StartAsync(TransferFormat.Text).OrTimeout();
373+
var startTask = connection.StartAsync(TransferFormat.Text);
375374
Assert.False(connectResponseTcs.Task.IsCompleted);
376375
Assert.False(startTask.IsCompleted);
377376
connectResponseTcs.TrySetResult(null);
378-
await startTask;
377+
await startTask.OrTimeout();
379378
});
380379
}
381380
}
382381

383382
private static async Task AssertDisposedAsync(HttpConnection connection)
384383
{
385384
var exception =
386-
await Assert.ThrowsAsync<ObjectDisposedException>(() => connection.StartAsync(TransferFormat.Text).OrTimeout());
385+
await Assert.ThrowsAsync<ObjectDisposedException>(() => connection.StartAsync(TransferFormat.Text));
387386
Assert.Equal(nameof(HttpConnection), exception.ObjectName);
388387
}
389388
}

0 commit comments

Comments
 (0)