Skip to content

Log error when exception occurs during streaming #42283

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 3 commits into from
Jun 22, 2022
Merged

Log error when exception occurs during streaming #42283

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
d9d8153
Log error when exception happens during streaming
campersau Jun 18, 2022
c9bd468
Add test for ChannelClosedException
campersau Jun 19, 2022
d89afa8
Update FailedStreaming logger message
campersau Jun 21, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions src/SignalR/server/Core/src/Internal/DefaultHubDispatcher.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -474,13 +474,15 @@ private async Task StreamAsync(string invocationId, HubConnectionContext connect
catch (ChannelClosedException ex)
{
// If the channel closes from an exception in the streaming method, grab the innerException for the error from the streaming method
Log.FailedStreaming(_logger, invocationId, descriptor.MethodExecutor.MethodInfo.Name, ex.InnerException ?? ex);
error = ErrorMessageHelper.BuildErrorMessage("An error occurred on the server while streaming results.", ex.InnerException ?? ex, _enableDetailedErrors);
}
catch (Exception ex)
{
// If the streaming method was canceled we don't want to send a HubException message - this is not an error case
if (!(ex is OperationCanceledException && streamCts.IsCancellationRequested))
{
Log.FailedStreaming(_logger, invocationId, descriptor.MethodExecutor.MethodInfo.Name, ex);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Not sure should this one. cancellation failures shouldn't be logged as an error, maybe debug.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It isn't see !. Or do you mean other OperationCanceledExceptions when !streamCts.IsCancellationRequested?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You're right, @campersau. There is an !!!

It is surprising that this wasn't logged already. Are we sure this isn't logged anywhere else? This really should just be calling Log.FailedInvokingHubMethod(_logger, hubMethodInvocationMessage.Target, ex) if we observe that an Exception is thrown from a streaming hub method without the client cancelling the invocation.

I would assume the !streamCts.IsCancellationRequested by itself is sufficient to ensure that. I'm not sure about the ChannelClosedException. @BrennanConroy?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah good catch @campersau! I missed the ! too.

For the ChannelClosedException, we should have a test too right?

Copy link
Contributor Author

@campersau campersau Jun 19, 2022 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There isn't currently any test for the ChannelClosedException case, so I have added one which manually throws a ChannelClosedException.
Because from looking at the Channels implementation in runtime it looks like these don't throw ChannelClosedException from within WaitToReadAsync / TryRead but instead always throw the users exception from TryComplete(Exception ex).
Only ReadAsync would throw a ChannelClosedException as far as I can tell.

https://github.com/dotnet/runtime/blob/57bfe474518ab5b7cfe6bf7424a79ce3af9d6657/src/libraries/System.Threading.Channels/src/System/Threading/Channels/BoundedChannel.cs#L208-L210

https://github.com/dotnet/runtime/blob/57bfe474518ab5b7cfe6bf7424a79ce3af9d6657/src/libraries/System.Threading.Channels/src/System/Threading/Channels/UnboundedChannel.cs#L167-L169

For reference AsyncEnumerableAdapters only uses WaitToReadAsync / TryRead:

aspnetcore/src/SignalR/common/Shared/AsyncEnumerableAdapters.cs

Line 55 in 3ea008c

if (await _channel.WaitToReadAsync(_cancellationToken).ConfigureAwait(false) && _channel.TryRead(out var item))

Regarding: Log.FailedInvokingHubMethod
I can change it to use this instead, but maybe a different log might be better to distinguish between those two cases. The case where it would throw immediately vs. the case where it could throw mid reading. (The tests currently throw directly for the first read but it could also happen much later.)
Also Log.FailedInvokingHubMethod does not include the invocationId which might be useful as this exception might be logged much later.
In general the logs are quite inconsistent with the inclusion of the invocationId.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks like ChannelClosedException was relevant many years ago in the first implementation of the feature: https://github.com/dotnet/aspnetcore/blame/1289636c3afa0e5f297df141359e4ba72dac6e70/src/SignalR/common/Shared/AsyncEnumerableAdapters.cs#L28

I'm not against a new log message, it's always helpful to have more specific logs when investigating issues (although you can argue here that the exception stack trace would give you enough information).

I would also be happy with adding the invocation ID to the FailedInvokingHubMethod log.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should we remove the ChannelClosedException case? I guess there could still be custom Channel implementations which do throw a ChannelClosedException, so maybe no?

There are currently three proposed options for logging:

  1. Use a new logger message like FailedStreaming as currently proposed in the PR.
  2. Use the existing logger message FailedInvokingHubMethod.
  3. Use the existing logger message FailedInvokingHubMethod and add the invocationId.

I am fine with either of those, just wanted to bring up the discussion.

If we want to go with (3) then there are some other logger messages which currently don't have an invocationId so we could add it to them too for consistentcy. Here are all of these:

aspnetcore/src/SignalR/server/Core/src/Internal/DefaultHubDispatcher.cs

Line 287 in c9bd468

Log.HubMethodNotAuthorized(_logger, hubMethodInvocationMessage.Target);

aspnetcore/src/SignalR/server/Core/src/Internal/DefaultHubDispatcher.cs

Line 305 in c9bd468

Log.InvalidHubParameters(_logger, hubMethodInvocationMessage.Target, ex);

aspnetcore/src/SignalR/server/Core/src/Internal/DefaultHubDispatcher.cs

Line 349 in c9bd468

Log.FailedInvokingHubMethod(logger, hubMethodInvocationMessage.Target, ex);

aspnetcore/src/SignalR/server/Core/src/Internal/DefaultHubDispatcher.cs

Line 389 in c9bd468

Log.FailedInvokingHubMethod(_logger, hubMethodInvocationMessage.Target, ex);

aspnetcore/src/SignalR/server/Core/src/Internal/DefaultHubDispatcher.cs

Line 395 in c9bd468

Log.FailedInvokingHubMethod(_logger, hubMethodInvocationMessage.Target, ex);

aspnetcore/src/SignalR/server/Core/src/Internal/DefaultHubDispatcher.cs

Line 451 in c9bd468

Log.FailedInvokingHubMethod(_logger, hubMethodInvocationMessage.Target, ex);

aspnetcore/src/SignalR/server/Core/src/Internal/DefaultHubDispatcher.cs

Line 458 in c9bd468

Log.InvalidReturnValueFromStreamingMethod(_logger, descriptor.MethodExecutor.MethodInfo.Name);

aspnetcore/src/SignalR/server/Core/src/Internal/DefaultHubDispatcher.cs

Line 593 in c9bd468

Log.StreamingMethodCalledWithInvoke(_logger, hubMethodInvocationMessage);

aspnetcore/src/SignalR/server/Core/src/Internal/DefaultHubDispatcher.cs

Line 603 in c9bd468

Log.NonStreamingMethodCalledWithStream(_logger, hubMethodInvocationMessage);

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should we remove the ChannelClosedException case?

I don't see any harm in keeping it.

There are currently three proposed options for logging:

I'm going to vote for adding a new log, it's more user friendly to see specific logs.

We can look at adding invocation IDs to existing logs in a separate change.

error = ErrorMessageHelper.BuildErrorMessage("An error occurred on the server while streaming results.", ex, _enableDetailedErrors);
}
}
Expand Down
3 changes: 3 additions & 0 deletions src/SignalR/server/Core/src/Internal/DefaultHubDispatcherLog.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -105,4 +105,7 @@ public static void ClosingStreamWithBindingError(ILogger logger, CompletionMessa

[LoggerMessage(24, LogLevel.Debug, "CompletionMessage for invocation ID '{InvocationId}' received unexpectedly.", EventName = "UnexpectedCompletion")]
public static partial void UnexpectedCompletion(ILogger logger, string invocationId);

[LoggerMessage(25, LogLevel.Error, "Invocation ID {InvocationId}: Failed while sending stream items from hub method {HubMethod}.", EventName = "FailedStreaming")]
public static partial void FailedStreaming(ILogger logger, string invocationId, string hubMethod, Exception exception);
}
23 changes: 23 additions & 0 deletions src/SignalR/server/SignalR/test/HubConnectionHandlerTestUtils/Hubs.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -692,6 +692,15 @@ public async IAsyncEnumerable<string> CounterAsyncEnumerable(int count)
}
}

public async IAsyncEnumerable<string> ExceptionAsyncEnumerable()
{
await Task.Yield();
throw new Exception("Exception from async enumerable");
#pragma warning disable CS0162 // Unreachable code detected
yield break;
#pragma warning restore CS0162 // Unreachable code detected
}

public async Task<IAsyncEnumerable<string>> CounterAsyncEnumerableAsync(int count)
{
await Task.Yield();
Expand Down Expand Up @@ -720,6 +729,20 @@ public ChannelReader<int> ExceptionStream()
return channel.Reader;
}

public ChannelReader<int> ChannelClosedExceptionStream()
{
var channel = Channel.CreateUnbounded<int>();
channel.Writer.TryComplete(new ChannelClosedException("ChannelClosedException from channel"));
return channel.Reader;
}

public ChannelReader<int> ChannelClosedExceptionInnerExceptionStream()
{
var channel = Channel.CreateUnbounded<int>();
channel.Writer.TryComplete(new ChannelClosedException(new Exception("ChannelClosedException from channel")));
return channel.Reader;
}

public ChannelReader<int> ThrowStream()
{
throw new Exception("Throw from hub method");
Expand Down
28 changes: 20 additions & 8 deletions src/SignalR/server/SignalR/test/HubConnectionHandlerTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2066,16 +2066,28 @@ public async Task NonErrorCompletionSentWhenStreamCanceledFromClient()
}

[Theory]
[InlineData(true)]
[InlineData(false)]
public async Task ReceiveCorrectErrorFromStreamThrowing(bool detailedErrors)
[InlineData(nameof(StreamingHub.ExceptionAsyncEnumerable), "Exception: Exception from async enumerable")]
[InlineData(nameof(StreamingHub.ExceptionAsyncEnumerable), null)]
[InlineData(nameof(StreamingHub.ExceptionStream), "Exception: Exception from channel")]
[InlineData(nameof(StreamingHub.ExceptionStream), null)]
[InlineData(nameof(StreamingHub.ChannelClosedExceptionStream), "ChannelClosedException: ChannelClosedException from channel")]
[InlineData(nameof(StreamingHub.ChannelClosedExceptionStream), null)]
[InlineData(nameof(StreamingHub.ChannelClosedExceptionInnerExceptionStream), "Exception: ChannelClosedException from channel")]
[InlineData(nameof(StreamingHub.ChannelClosedExceptionInnerExceptionStream), null)]
public async Task ReceiveCorrectErrorFromStreamThrowing(string streamMethod, string detailedError)
{
using (StartVerifiableLog())
bool ExpectedErrors(WriteContext writeContext)
{
return writeContext.LoggerName == "Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher" &&
writeContext.EventId.Name == "FailedStreaming";
}

using (StartVerifiableLog(ExpectedErrors))
{
var serviceProvider = HubConnectionHandlerTestUtils.CreateServiceProvider(builder =>
builder.AddSignalR(options =>
{
options.EnableDetailedErrors = detailedErrors;
options.EnableDetailedErrors = detailedError != null;
}), LoggerFactory);
var connectionHandler = serviceProvider.GetService<HubConnectionHandler<StreamingHub>>();

Expand All @@ -2085,14 +2097,14 @@ public async Task ReceiveCorrectErrorFromStreamThrowing(bool detailedErrors)

await client.Connected.DefaultTimeout();

var messages = await client.StreamAsync(nameof(StreamingHub.ExceptionStream));
var messages = await client.StreamAsync(streamMethod);

Assert.Equal(1, messages.Count);
var completion = messages[0] as CompletionMessage;
Assert.NotNull(completion);
if (detailedErrors)
if (detailedError != null)
{
Assert.Equal("An error occurred on the server while streaming results. Exception: Exception from channel", completion.Error);
Assert.Equal($"An error occurred on the server while streaming results. {detailedError}", completion.Error);
}
else
{
Expand Down