Log error when exception occurs during streaming #42283

campersau · 2022-06-18T20:40:10Z

Log error when exception occurs during streaming

Logs the exception when there is an exception during streaming on the server.

Fixes #42050

ghost · 2022-06-18T20:40:19Z

Thanks for your PR, @campersau. Someone from the team will get assigned to your PR shortly and we'll get it reviewed.

davidfowl · 2022-06-18T21:08:48Z

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

            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);


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

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

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?

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

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

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.

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.

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:

Use a new logger message like FailedStreaming as currently proposed in the PR.

Use the existing logger message FailedInvokingHubMethod.

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);

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.

Kahbazi · 2022-06-20T08:07:46Z

src/SignalR/server/Core/src/Internal/DefaultHubDispatcherLog.cs

@@ -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, "InvocationId {InvocationId}: Failed during streaming '{HubMethod}'.", EventName = "FailedStreaming")]


nit:

Suggested change

[LoggerMessage(25, LogLevel.Error, "InvocationId {InvocationId}: Failed during streaming '{HubMethod}'.", EventName = "FailedStreaming")]

[LoggerMessage(25, LogLevel.Error, "InvocationId '{InvocationId}': Failed during streaming '{HubMethod}'.", EventName = "FailedStreaming")]

Some have quotes:

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

Line 103 in c9bd468

[LoggerMessage(23, LogLevel.Debug, "Invocation ID '{InvocationId}' is already in use.", EventName = "InvocationIdInUse")]

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

Line 106 in c9bd468

[LoggerMessage(24, LogLevel.Debug, "CompletionMessage for invocation ID '{InvocationId}' received unexpectedly.", EventName = "UnexpectedCompletion")]

And some have no quotes:

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

Line 35 in c9bd468

[LoggerMessage(6, LogLevel.Trace, "InvocationId {InvocationId}: Streaming result of type '{ResultType}'.", EventName = "StreamingResult", SkipEnabledCheck = true)]

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

Line 47 in c9bd468

[LoggerMessage(7, LogLevel.Trace, "InvocationId {InvocationId}: Sending result of type '{ResultType}'.", EventName = "SendingResult", SkipEnabledCheck = true)]

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

Line 56 in c9bd468

[LoggerMessage(10, LogLevel.Debug, "Canceling stream for invocation {InvocationId}.", EventName = "CancelStream")]

I copied it from the ones without quotes :)
Let's wait if a new LoggerMessage is even needed based on the ongoing discussion above.

Bike-shed time.

"Invocation ID {InvocationId}: Failed while sending stream items from hub method {HubMethod}."

BrennanConroy · 2022-06-22T18:00:40Z

Thanks @campersau you're on a roll!

Log error when exception happens during streaming

d9d8153

campersau requested review from BrennanConroy and halter73 as code owners June 18, 2022 20:40

ghost added area-signalr Includes: SignalR clients and servers community-contribution Indicates that the PR has been added by a community member labels Jun 18, 2022

davidfowl reviewed Jun 18, 2022

View reviewed changes

Add test for ChannelClosedException

c9bd468

mkArtakMSFT assigned rafikiassumani-msft Jun 19, 2022

BrennanConroy unassigned rafikiassumani-msft Jun 20, 2022

Kahbazi reviewed Jun 20, 2022

View reviewed changes

mkArtakMSFT assigned rafikiassumani-msft Jun 20, 2022

Update FailedStreaming logger message

d89afa8

BrennanConroy approved these changes Jun 22, 2022

View reviewed changes

BrennanConroy merged commit 7c68e77 into dotnet:main Jun 22, 2022

ghost added this to the 7.0-preview6 milestone Jun 22, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Log error when exception occurs during streaming #42283

Log error when exception occurs during streaming #42283

Uh oh!

campersau commented Jun 18, 2022

Uh oh!

ghost commented Jun 18, 2022

Uh oh!

davidfowl Jun 18, 2022

Uh oh!

campersau Jun 18, 2022

Uh oh!

halter73 Jun 18, 2022

Uh oh!

davidfowl Jun 18, 2022

Uh oh!

campersau Jun 19, 2022 •

edited

Loading

Uh oh!

BrennanConroy Jun 20, 2022

Uh oh!

campersau Jun 21, 2022

Uh oh!

BrennanConroy Jun 21, 2022

Uh oh!

Kahbazi Jun 20, 2022

Uh oh!

campersau Jun 20, 2022

Uh oh!

BrennanConroy Jun 21, 2022

Uh oh!

BrennanConroy commented Jun 22, 2022

Uh oh!

Uh oh!

	[LoggerMessage(25, LogLevel.Error, "InvocationId {InvocationId}: Failed during streaming '{HubMethod}'.", EventName = "FailedStreaming")]
	[LoggerMessage(25, LogLevel.Error, "InvocationId '{InvocationId}': Failed during streaming '{HubMethod}'.", EventName = "FailedStreaming")]

Log error when exception occurs during streaming #42283

Log error when exception occurs during streaming #42283

Uh oh!

Conversation

campersau commented Jun 18, 2022

Log error when exception occurs during streaming

Uh oh!

ghost commented Jun 18, 2022

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

campersau Jun 19, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

BrennanConroy commented Jun 22, 2022

Uh oh!

Uh oh!

campersau Jun 19, 2022 •

edited

Loading