Skip to content

Commit dc70751

Browse files
vicancyvicancy
authored
Fix the current verifiablelog, the previous delegate pattern hide the real issue thrown from the inner code block (#2152)
1 parent 86cb16e commit dc70751

File tree

18 files changed

+182
-234
lines changed

18 files changed

+182
-234
lines changed

‎src/Microsoft.Azure.SignalR.AspNet/HubHost/ServiceMessageBus.cs‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
// Copyright (c) Microsoft. All rights reserved.
1+
// Copyright (c) Microsoft. All rights reserved.
22
// Licensed under the MIT license. See LICENSE file in the project root for full license information.
33

44
using System;
@@ -47,7 +47,7 @@ public override Task Publish(Message message)
4747
return ProcessMessage(messages[0]);
4848
}
4949

50-
return Task.WhenAll(messages.Select(m => ProcessMessage(m)));
50+
return Task.WhenAll(messages.Select(ProcessMessage));
5151
}
5252

5353
private async Task ProcessMessage(AppMessage message)

‎src/Microsoft.Azure.SignalR.AspNet/ServerConnections/ServiceConnection.cs‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -331,9 +331,9 @@ private async Task ProcessMessageAsync(ClientConnectionContext clientContext, Ca
331331
}
332332
}
333333
}
334-
catch (OperationCanceledException e)
334+
catch (OperationCanceledException)
335335
{
336-
Log.SendLoopStopped(Logger, connectionId, e);
336+
// Canceled
337337
}
338338
catch (Exception e)
339339
{

‎test/Microsoft.Azure.SignalR.AspNet.Tests/MultiEndpointServiceConnectionContainerTests.cs‎

Lines changed: 9 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -26,9 +26,9 @@ public class MultiEndpointServiceConnectionContainerTests : VerifiableLoggedTest
2626

2727
private static readonly JoinGroupWithAckMessage DefaultGroupMessage = new JoinGroupWithAckMessage("a", "a");
2828

29-
private readonly string ConnectionString1 = string.Format(ConnectionStringFormatter, Url1);
29+
private static readonly string ConnectionString1 = string.Format(ConnectionStringFormatter, Url1);
3030

31-
private readonly string ConnectionString2 = string.Format(ConnectionStringFormatter, Url2);
31+
private static readonly string ConnectionString2 = string.Format(ConnectionStringFormatter, Url2);
3232

3333
public MultiEndpointServiceConnectionContainerTests(ITestOutputHelper output) : base(output)
3434
{
@@ -309,7 +309,7 @@ public async Task TestContainerWithOneEndpointWithAllDisconnectedAndWriteMessage
309309
[Fact]
310310
public async Task TestContainerWithTwoEndpointWithAllConnectedFailsWithBadRouter()
311311
{
312-
using (StartVerifiableLog(out var loggerFactory, LogLevel.Debug, logChecker: logs => true))
312+
using (StartVerifiableLog(out var loggerFactory, LogLevel.Debug))
313313
{
314314
var sem = new TestServiceEndpointManager(
315315
new ServiceEndpoint(ConnectionString1),
@@ -338,7 +338,7 @@ await Assert.ThrowsAsync<InvalidOperationException>(
338338
[Fact]
339339
public async Task TestContainerWithTwoEndpointWithAllConnectedSucceedsWithGoodRouter()
340340
{
341-
using (StartVerifiableLog(out var loggerFactory, LogLevel.Warning, logChecker: logs => true))
341+
using (StartVerifiableLog(out var loggerFactory, LogLevel.Warning))
342342
{
343343
var sem = new TestServiceEndpointManager(
344344
new ServiceEndpoint(ConnectionString1),
@@ -366,14 +366,7 @@ public async Task TestContainerWithTwoEndpointWithAllConnectedSucceedsWithGoodRo
366366
[Fact]
367367
public async Task TestContainerWithTwoEndpointWithAllOfflineSucceedsWithWarning()
368368
{
369-
using (StartVerifiableLog(out var loggerFactory, LogLevel.Warning, logChecker: logs =>
370-
{
371-
var warns = logs.Where(s => s.Write.LogLevel == LogLevel.Warning).ToList();
372-
373-
Assert.Single(warns);
374-
Assert.Equal("Message JoinGroupWithAckMessage is not sent because no endpoint is returned from the endpoint router.", warns[0].Write.Message);
375-
return true;
376-
}))
369+
using (var logCollector = StartVerifiableLog(out var loggerFactory, LogLevel.Warning))
377370
{
378371
var sem = new TestServiceEndpointManager(
379372
new ServiceEndpoint(ConnectionString1),
@@ -394,6 +387,10 @@ public async Task TestContainerWithTwoEndpointWithAllOfflineSucceedsWithWarning(
394387
_ = container.StartAsync();
395388
await container.ConnectionInitializedTask.OrTimeout();
396389
await container.WriteAsync(DefaultGroupMessage);
390+
var warns = logCollector.ExpectsMany(s => s.Write.LogLevel == LogLevel.Warning).ToList();
391+
392+
Assert.Single(warns);
393+
Assert.Equal("Message JoinGroupWithAckMessage is not sent because no endpoint is returned from the endpoint router.", warns[0].Write.Message);
397394
}
398395
}
399396

‎test/Microsoft.Azure.SignalR.AspNet.Tests/RunAzureSignalRTests.cs‎

Lines changed: 8 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -448,7 +448,7 @@ public async Task TestRunAzureSignalRWithMultipleAppSettingsAndCustomSettingsAnd
448448
[Fact]
449449
public async Task TestRunAzureSignalRWithDefaultRouterNegotiateWithFallback()
450450
{
451-
using (StartVerifiableLog(out var loggerFactory, LogLevel.Warning, expectedErrors: e => true))
451+
using (StartVerifiableLog(out var loggerFactory, LogLevel.Warning))
452452
{
453453
// Prepare the configuration
454454
var hubConfig = Utility.GetTestHubConfig(loggerFactory, "chat");
@@ -830,15 +830,7 @@ public async Task TestRunAzureSignalRRespectValidMaxPollInterval(int timeout)
830830
public async Task TestRunAzureSignalStartsServerConnection()
831831
{
832832
// Prepare the configuration
833-
using (StartVerifiableLog(out var loggerFactory, LogLevel.Debug, logChecker: i =>
834-
{
835-
// the logs should contain start and stop
836-
var names = i.Select(s => s.Write.EventId.Name).ToArray();
837-
return names.Contains("StartingConnection")
838-
&& names.Contains("StartTransport")
839-
&& names.Contains("TransportStopping")
840-
&& names.Contains("FailedToConnect");
841-
}))
833+
using (var logCollector = StartVerifiableLog(out var loggerFactory, LogLevel.Debug))
842834
using (new AppSettingsConfigScope(ConnectionString))
843835
{
844836
var hubConfig = Utility.GetTestHubConfig(loggerFactory);
@@ -854,6 +846,12 @@ public async Task TestRunAzureSignalStartsServerConnection()
854846
// 5 seconds for one websocket failure round
855847
await options.ConnectionInitializedTask.OrTimeout(20000);
856848
}
849+
850+
// the logs should contain start and stop
851+
logCollector.Expects("StartingConnection");
852+
logCollector.Expects("StartTransport");
853+
logCollector.Expects("TransportStopping");
854+
logCollector.Expects("FailedToConnect");
857855
}
858856
}
859857

‎test/Microsoft.Azure.SignalR.AspNet.Tests/ServiceConnectionTests.cs‎

Lines changed: 20 additions & 40 deletions
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,6 @@
99
using Microsoft.AspNet.SignalR;
1010
using Microsoft.AspNet.SignalR.Transports;
1111
using Microsoft.Azure.SignalR.Protocol;
12-
using Microsoft.Azure.SignalR.Tests;
1312
using Microsoft.Azure.SignalR.Tests.Common;
1413
using Microsoft.Extensions.Logging;
1514
using Microsoft.Extensions.Primitives;
@@ -151,14 +150,7 @@ public async Task ServiceConnectionDispatchGroupMessagesTest()
151150
[Fact]
152151
public async Task ServiceConnectionWithErrorConnectHub()
153152
{
154-
using (StartVerifiableLog(out var loggerFactory, LogLevel.Warning, expectedErrors: c => true, logChecker:
155-
logs =>
156-
{
157-
Assert.Equal(2, logs.Count);
158-
Assert.Equal("ErrorExecuteConnected", logs[0].Write.EventId.Name);
159-
Assert.Equal("ConnectedStartingFailed", logs[1].Write.EventId.Name);
160-
return true;
161-
}))
153+
using (var logCollector = StartVerifiableLog(out var loggerFactory, LogLevel.Warning))
162154
{
163155
var hubConfig = Utility.GetActualHubConfig(loggerFactory);
164156
var appName = "app1";
@@ -194,14 +186,16 @@ public async Task ServiceConnectionWithErrorConnectHub()
194186

195187
// cleaned up clearly
196188
Assert.Empty(ccm.ClientConnections);
189+
190+
logCollector.Expects("ErrorExecuteConnected");
191+
logCollector.Expects("ConnectedStartingFailed");
197192
}
198193
}
199194

200-
[RetryFact]
195+
[Fact]
201196
public async Task ServiceConnectionWithErrorDisconnectHub()
202197
{
203-
using (StartVerifiableLog(out var loggerFactory, LogLevel.Debug, expectedErrors: c => true, logChecker:
204-
logs => true))
198+
using (StartVerifiableLog(out var loggerFactory, LogLevel.Debug))
205199
{
206200
var hubConfig = Utility.GetActualHubConfig(loggerFactory);
207201
var appName = "app1";
@@ -259,14 +253,7 @@ public async Task ServiceConnectionWithErrorDisconnectHub()
259253
[Fact]
260254
public async Task ServiceConnectionDispatchOpenConnectionToUnauthorizedHubTest()
261255
{
262-
using (StartVerifiableLog(out var loggerFactory, LogLevel.Warning, expectedErrors: c => true, logChecker:
263-
logs =>
264-
{
265-
Assert.Single(logs);
266-
Assert.Equal("ConnectedStartingFailed", logs[0].Write.EventId.Name);
267-
Assert.Equal("Unable to authorize request", logs[0].Write.Exception.Message);
268-
return true;
269-
}))
256+
using (var logCollector = StartVerifiableLog(out var loggerFactory, LogLevel.Warning))
270257
{
271258
var hubConfig = new HubConfiguration();
272259
var ccm = new ClientConnectionManager(hubConfig, loggerFactory);
@@ -289,20 +276,15 @@ public async Task ServiceConnectionDispatchOpenConnectionToUnauthorizedHubTest()
289276

290277
// Verify client connection is not created due to authorized failure.
291278
Assert.False(ccm.TryGetClientConnection(connectionId, out var connection));
279+
var log = logCollector.Expects("ConnectedStartingFailed");
280+
Assert.Equal("Unable to authorize request", log.Write.Exception.Message);
292281
}
293282
}
294283

295284
[Fact]
296285
public async Task ServiceConnectionWithNormalClientConnection()
297286
{
298-
using (StartVerifiableLog(out var loggerFactory, LogLevel.Warning, expectedErrors: c => true, logChecker:
299-
logs =>
300-
{
301-
Assert.Single(logs);
302-
Assert.Equal("ConnectedStartingFailed", logs[0].Write.EventId.Name);
303-
Assert.Equal("Unable to authorize request", logs[0].Write.Exception.Message);
304-
return true;
305-
}))
287+
using (var logCollector = StartVerifiableLog(out var loggerFactory, LogLevel.Warning))
306288
{
307289
var hubConfig = new HubConfiguration();
308290
var ccm = new ClientConnectionManager(hubConfig, loggerFactory);
@@ -326,6 +308,8 @@ public async Task ServiceConnectionWithNormalClientConnection()
326308

327309
// Verify client connection is not created due to authorized failure.
328310
Assert.False(ccm.TryGetClientConnection(connectionId, out var connection));
311+
var log = logCollector.Expects("ConnectedStartingFailed");
312+
Assert.Equal("Unable to authorize request", log.Write.Exception.Message);
329313
}
330314
}
331315

@@ -334,7 +318,7 @@ public async Task ServiceConnectionWithNormalClientConnection()
334318
[InlineData("ErrorDisconnect")]
335319
public async Task ServiceConnectionWithTransportLayerClosedShouldCleanupNormalClientConnections(string hub)
336320
{
337-
using (StartVerifiableLog(out var loggerFactory, LogLevel.Debug, expectedErrors: c => true))
321+
using (StartVerifiableLog(out var loggerFactory, LogLevel.Debug))
338322
{
339323
var hubConfig = Utility.GetActualHubConfig(loggerFactory);
340324
var appName = "app1";
@@ -383,15 +367,7 @@ public async Task ServiceConnectionWithTransportLayerClosedShouldCleanupNormalCl
383367
[Fact]
384368
public async Task ServiceConnectionWithTransportLayerClosedShouldCleanupEndlessConnectClientConnections()
385369
{
386-
using (StartVerifiableLog(out var loggerFactory, LogLevel.Debug, expectedErrors: c => true, logChecker:
387-
logs =>
388-
{
389-
var errorLogs = logs.Where(s => s.Write.LogLevel == LogLevel.Error).ToList();
390-
Assert.Single(errorLogs);
391-
Assert.Equal("ApplicationTaskTimedOut", errorLogs[0].Write.EventId.Name);
392-
393-
return true;
394-
}))
370+
using (var logCollector = StartVerifiableLog(out var loggerFactory, LogLevel.Debug))
395371
{
396372
var hubConfig = Utility.GetActualHubConfig(loggerFactory);
397373
var appName = "app1";
@@ -417,7 +393,6 @@ public async Task ServiceConnectionWithTransportLayerClosedShouldCleanupEndlessC
417393
var openConnectionMessage = new OpenConnectionMessage(clientConnection, [], null,
418394
$"?transport=webSockets&connectionToken=conn1&connectionData=%5B%7B%22name%22%3A%22{hub}%22%7D%5D");
419395
await proxy.WriteMessageAsync(openConnectionMessage);
420-
421396
var connectMessage = (await connectTask) as GroupBroadcastDataMessage;
422397
Assert.NotNull(connectMessage);
423398
Assert.Equal($"hg-{hub}.note", connectMessage.GroupName);
@@ -438,13 +413,15 @@ public async Task ServiceConnectionWithTransportLayerClosedShouldCleanupEndlessC
438413

439414
// cleaned up clearly
440415
Assert.Empty(ccm.ClientConnections);
416+
417+
logCollector.Expects("ApplicationTaskTimedOut");
441418
}
442419
}
443420

444421
[Fact]
445422
public async Task ServiceConnectionWithTransportLayerClosedShouldCleanupEndlessInvokeClientConnections()
446423
{
447-
using (StartVerifiableLog(out var loggerFactory, LogLevel.Debug, expectedErrors: c => true))
424+
using (StartVerifiableLog(out var loggerFactory, LogLevel.Debug))
448425
{
449426
var hubConfig = Utility.GetActualHubConfig(loggerFactory);
450427
var appName = "app1";
@@ -490,6 +467,8 @@ public async Task ServiceConnectionWithTransportLayerClosedShouldCleanupEndlessI
490467
Assert.NotNull(broadcastMessage);
491468
Assert.Equal($"hg-{hub}.group1", broadcastMessage.GroupName);
492469

470+
var disconnectTask = scm.WaitForTransportOutputMessageAsync(typeof(GroupBroadcastDataMessage)).OrTimeout();
471+
493472
// close transport layer
494473
proxy.TestConnectionContext.Application.Output.Complete();
495474

@@ -575,6 +554,7 @@ await proxy.WriteMessageAsync(new PingMessage()
575554
// Validate client2 is still connected
576555
Assert.Single(ccm.ClientConnections);
577556
Assert.Equal(connectionId2, ccm.ClientConnections.FirstOrDefault().ConnectionId);
557+
await proxy.WaitForConnectionClose.OrTimeout();
578558
}
579559
}
580560

‎test/Microsoft.Azure.SignalR.AspNet.Tests/TestClasses/TestServiceConnectionHandler.cs‎

Lines changed: 14 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
// Copyright (c) Microsoft. All rights reserved.
1+
// Copyright (c) Microsoft. All rights reserved.
22
// Licensed under the MIT license. See LICENSE file in the project root for full license information.
33

44
using System;
@@ -28,6 +28,10 @@ public override Task WriteAsync(ServiceMessage serviceMessage)
2828
{
2929
tcs.SetResult(serviceMessage);
3030
}
31+
else
32+
{
33+
throw new InvalidOperationException("Not expected to write before tcs is inited");
34+
}
3135

3236
return Task.CompletedTask;
3337
}
@@ -48,18 +52,19 @@ public override Task<bool> WriteAckableMessageAsync(ServiceMessage serviceMessag
4852

4953
public Task<ServiceMessage> WaitForTransportOutputMessageAsync(Type messageType)
5054
{
51-
if (_waitForTransportOutputMessage.TryGetValue(messageType, out var tcs))
52-
{
53-
tcs.TrySetCanceled();
54-
}
55-
5655
// re-init the tcs
57-
tcs = _waitForTransportOutputMessage[messageType] = new TaskCompletionSource<ServiceMessage>(TaskCreationOptions.RunContinuationsAsynchronously);
58-
56+
var tcs = _waitForTransportOutputMessage.AddOrUpdate(messageType, t =>
57+
{
58+
return new TaskCompletionSource<ServiceMessage>(TaskCreationOptions.RunContinuationsAsynchronously);
59+
}, (t, old) =>
60+
{
61+
old.TrySetCanceled();
62+
return new TaskCompletionSource<ServiceMessage>(TaskCreationOptions.RunContinuationsAsynchronously);
63+
});
5964
return tcs.Task;
6065
}
6166

62-
public void DisposeServiceConnection(IServiceConnection connection)
67+
public void DisposeServiceConnection(IServiceConnection _)
6368
{
6469
}
6570
}

‎test/Microsoft.Azure.SignalR.AspNet.Tests/TestClasses/TestServiceConnectionProxy.cs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
// Copyright (c) Microsoft. All rights reserved.
1+
// Copyright (c) Microsoft. All rights reserved.
22
// Licensed under the MIT license. See LICENSE file in the project root for full license information.
33

44
using System;

‎test/Microsoft.Azure.SignalR.Common.Tests/ServiceConnectionContainerBaseTests.cs‎

Lines changed: 4 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -37,13 +37,7 @@ public void TestGetRetryDelay(int count, int minSeconds, int maxSeconds)
3737
[Fact]
3838
public void TestWeakConnectionStatus()
3939
{
40-
using (StartVerifiableLog(out var loggerFactory, LogLevel.Warning, expectedErrors: e => true,
41-
logChecker: s =>
42-
{
43-
Assert.Single(s);
44-
Assert.Equal("EndpointOffline", s[0].Write.EventId.Name);
45-
return true;
46-
}))
40+
using (var logCollector = StartVerifiableLog(out var loggerFactory, LogLevel.Warning))
4741
{
4842
var endpoint1 = new TestHubServiceEndpoint();
4943
var conn1 = new TestServiceConnection();
@@ -68,19 +62,14 @@ public void TestWeakConnectionStatus()
6862

6963
conn1.SetStatus(ServiceConnectionStatus.Connected);
7064
Assert.True(endpoint1.Online);
65+
logCollector.Expects("EndpointOffline");
7166
}
7267
}
7368

7469
[Fact]
7570
public void TestStrongConnectionStatus()
7671
{
77-
using (StartVerifiableLog(out var loggerFactory, LogLevel.Warning, expectedErrors: e => true,
78-
logChecker: s =>
79-
{
80-
Assert.Single(s);
81-
Assert.Equal("EndpointOffline", s[0].Write.EventId.Name);
82-
return true;
83-
}))
72+
using (var logCollector = StartVerifiableLog(out var loggerFactory, LogLevel.Warning))
8473
{
8574
var endpoint1 = new TestHubServiceEndpoint();
8675
var conn1 = new TestServiceConnection();
@@ -105,6 +94,7 @@ public void TestStrongConnectionStatus()
10594

10695
conn1.SetStatus(ServiceConnectionStatus.Connected);
10796
Assert.True(endpoint1.Online);
97+
logCollector.Expects("EndpointOffline");
10898
}
10999
}
110100

‎test/Microsoft.Azure.SignalR.E2ETests/Management/ServiceHubContextE2EFacts.cs‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -755,7 +755,7 @@ internal async Task StopServiceHubContextTest()
755755
[SkipIfConnectionStringNotPresent]
756756
public async Task ServiceHubContextIndependencyTest()
757757
{
758-
using (StartVerifiableLog(out var loggerFactory, LogLevel.Debug, expectedErrors: context => context.EventId == new EventId(2, "EndpointOffline")))
758+
using (var logCollector = StartVerifiableLog(out var loggerFactory, LogLevel.Debug))
759759
{
760760
using var serviceManager = new ServiceManagerBuilder()
761761
.WithOptions(o =>
@@ -771,6 +771,8 @@ public async Task ServiceHubContextIndependencyTest()
771771
await hubContext_1.DisposeAsync();
772772
await hubContext_2.Clients.All.SendAsync(MethodName, Message);
773773
await hubContext_2.DisposeAsync();
774+
775+
logCollector.Expects("EndpointOffline");
774776
}
775777
}
776778

0 commit comments

Comments
 (0)