search

dotnet / aspnetcore

ASP.NET Core is a cross-platform .NET framework for building modern cloud-based web applications on Windows, Mac, or Linux.
https://asp.net
MIT License
35.59k stars 10.06k forks source link

SignalR: `Error when dispatching '"OnDisconnectedAsync"' on hub` and `Failed disposing connection` #6149

Open fabiano opened 5 years ago

fabiano commented 5 years ago

Describe the bug

After migrating my application from ASP.NET Core 2.1 (net471) to ASP.NET Core 2.2 (netcoreapp2.2 and InProcess hosting model) I found some exceptions in our log system related to SignalR.

These exceptions are always happening after IIS shutting down the application.

And I have some errors logged in the Event Viewer at the same time.

Additional context

09:12:07.250 ERR Error when dispatching '"OnDisconnectedAsync"' on hub.
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'IServiceProvider'.
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ThrowHelper.ThrowObjectDisposedException()
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngine.CreateScope()
   at Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher`1.OnDisconnectedAsync(HubConnectionContext connection, Exception exception)
   at Microsoft.AspNetCore.SignalR.HubConnectionHandler`1.HubOnDisconnectedAsync(HubConnectionContext connection, Exception exception)
09:12:07.939 ERR Error when dispatching '"OnDisconnectedAsync"' on hub.
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'IServiceProvider'.
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ThrowHelper.ThrowObjectDisposedException()
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngine.CreateScope()
   at Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher`1.OnDisconnectedAsync(HubConnectionContext connection, Exception exception)
   at Microsoft.AspNetCore.SignalR.HubConnectionHandler`1.HubOnDisconnectedAsync(HubConnectionContext connection, Exception exception)
09:12:08.114 ERR Failed disposing connection "hV2ao8YCcPSDKOtG6K0B4g".
System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'IServiceProvider'.
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ThrowHelper.ThrowObjectDisposedException()
   at Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceProviderEngine.CreateScope()
   at Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher`1.OnDisconnectedAsync(HubConnectionContext connection, Exception exception)
   at Microsoft.AspNetCore.SignalR.HubConnectionHandler`1.HubOnDisconnectedAsync(HubConnectionContext connection, Exception exception)
   at Microsoft.AspNetCore.SignalR.HubConnectionHandler`1.RunHubAsync(HubConnectionContext connection)
   at Microsoft.AspNetCore.SignalR.HubConnectionHandler`1.OnConnectedAsync(ConnectionContext connection)
   at Microsoft.AspNetCore.SignalR.HubConnectionHandler`1.OnConnectedAsync(ConnectionContext connection)
   at Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionDispatcher.ExecuteApplication(ConnectionDelegate connectionDelegate, HttpConnectionContext connection)
   at Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionContext.WaitOnTasks(Task applicationTask, Task transportTask, Boolean closeGracefully)
   at Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionManager.DisposeAndRemoveAsync(HttpConnectionContext connection, Boolean closeGracefully)
   at Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionContext.DisposeAsync(Boolean closeGracefully)
   at Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionManager.DisposeAndRemoveAsync(HttpConnectionContext connection, Boolean closeGracefully)

Event Viewer logs

Log Name:      Application
Source:        IIS AspNetCore Module V2
Date:          12/25/2018 9:12:06 AM
Event ID:      1033
Task Category: None
Level:         Information
Keywords:      Classic
User:          N/A
Computer:      THE_SERVER
Description:
Application 'MACHINE/WEBROOT/APPHOST/THE_APP' has shutdown.
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
  <System>
    <Provider Name="IIS AspNetCore Module V2" />
    <EventID Qualifiers="0">1033</EventID>
    <Level>4</Level>
    <Task>0</Task>
    <Keywords>0x80000000000000</Keywords>
    <TimeCreated SystemTime="2018-12-25T14:12:06.000000000Z" />
    <EventRecordID>1336018</EventRecordID>
    <Channel>Application</Channel>
    <Computer>THE_SERVER</Computer>
    <Security />
  </System>
  <EventData>
    <Data>Application 'MACHINE/WEBROOT/APPHOST/THE_APP' has shutdown.</Data>
    <Data>Process Id: 21132.</Data>
    <Data>File Version: 12.2.18316.0. Description: IIS ASP.NET Core Module V2 Request Handler. Commit: ce8cf65589734f82b0536c543aba5bd60d0a5a98</Data>
  </EventData>
</Event>
Log Name:      Application
Source:        Application Error
Date:          12/25/2018 9:12:07 AM
Event ID:      1000
Task Category: (100)
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      THE_SERVER
Description:
Faulting application name: w3wp.exe, version: 8.5.9600.16384, time stamp: 0x5215df96
Faulting module name: KERNELBASE.dll, version: 6.3.9600.18938, time stamp: 0x5a7ddf0a
Exception code: 0xe0455858
Fault offset: 0x0000000000008eac
Faulting process id: 0x528c
Faulting application start time: 0x01d49b68baf0ffe9
Faulting application path: c:\windows\system32\inetsrv\w3wp.exe
Faulting module path: C:\windows\system32\KERNELBASE.dll
Report Id: 0f5a2200-084f-11e9-80d8-ac1f6b222a7d
Faulting package full name: 
Faulting package-relative application ID: 
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
  <System>
    <Provider Name="Application Error" />
    <EventID Qualifiers="0">1000</EventID>
    <Level>2</Level>
    <Task>100</Task>
    <Keywords>0x80000000000000</Keywords>
    <TimeCreated SystemTime="2018-12-25T14:12:07.000000000Z" />
    <EventRecordID>1336019</EventRecordID>
    <Channel>Application</Channel>
    <Computer>THE_SERVER</Computer>
    <Security />
  </System>
  <EventData>
    <Data>w3wp.exe</Data>
    <Data>8.5.9600.16384</Data>
    <Data>5215df96</Data>
    <Data>KERNELBASE.dll</Data>
    <Data>6.3.9600.18938</Data>
    <Data>5a7ddf0a</Data>
    <Data>e0455858</Data>
    <Data>0000000000008eac</Data>
    <Data>528c</Data>
    <Data>01d49b68baf0ffe9</Data>
    <Data>c:\windows\system32\inetsrv\w3wp.exe</Data>
    <Data>C:\windows\system32\KERNELBASE.dll</Data>
    <Data>0f5a2200-084f-11e9-80d8-ac1f6b222a7d</Data>
    <Data>
    </Data>
    <Data>
    </Data>
  </EventData>
</Event>
Log Name:      Application
Source:        Windows Error Reporting
Date:          12/25/2018 9:12:07 AM
Event ID:      1001
Task Category: None
Level:         Information
Keywords:      Classic
User:          N/A
Computer:      THE_SERVER
Description:
Fault bucket , type 0
Event Name: APPCRASH
Response: Not available
Cab Id: 0

Problem signature:
P1: w3wp.exe
P2: 8.5.9600.16384
P3: 5215df96
P4: KERNELBASE.dll
P5: 6.3.9600.18938
P6: 5a7ddf0a
P7: e0455858
P8: 0000000000008eac
P9: 
P10: 

Attached files:

These files may be available here:

Analysis symbol: 
Rechecking for solution: 0
Report Id: 0f5a2200-084f-11e9-80d8-ac1f6b222a7d
Report Status: 0
Hashed bucket: 
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
  <System>
    <Provider Name="Windows Error Reporting" />
    <EventID Qualifiers="0">1001</EventID>
    <Level>4</Level>
    <Task>0</Task>
    <Keywords>0x80000000000000</Keywords>
    <TimeCreated SystemTime="2018-12-25T14:12:07.000000000Z" />
    <EventRecordID>1336020</EventRecordID>
    <Channel>Application</Channel>
    <Computer>THE_SERVER</Computer>
    <Security />
  </System>
  <EventData>
    <Data>
    </Data>
    <Data>0</Data>
    <Data>APPCRASH</Data>
    <Data>Not available</Data>
    <Data>0</Data>
    <Data>w3wp.exe</Data>
    <Data>8.5.9600.16384</Data>
    <Data>5215df96</Data>
    <Data>KERNELBASE.dll</Data>
    <Data>6.3.9600.18938</Data>
    <Data>5a7ddf0a</Data>
    <Data>e0455858</Data>
    <Data>0000000000008eac</Data>
    <Data>
    </Data>
    <Data>
    </Data>
    <Data>
    </Data>
    <Data>
    </Data>
    <Data>
    </Data>
    <Data>0</Data>
    <Data>0f5a2200-084f-11e9-80d8-ac1f6b222a7d</Data>
    <Data>0</Data>
    <Data>
    </Data>
  </EventData>
</Event>

dotnet --info

Host (useful for support):
  Version: 2.2.0
  Commit:  1249f08fed

.NET Core SDKs installed:
  No SDKs were found.

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.1.2 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.2.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.2 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.2.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.0.6 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.2 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.2.0 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
fabiano commented 5 years ago

I did a test here and dropped an app_offline.htm file in the application's folder. After some seconds the w3wp.exe process crashed.

Then I removed the attribute hostingModel="InProcess" from my web.config file and repeated the test. This time the w3wp.exe process didn't crash.

BrennanConroy commented 5 years ago

@pakrym @jkotalik Could you guys take a quick look?

gschuager commented 5 years ago

I get this exception when updating Microsoft.AspNetCore.SignalR from 1.0.4 to 1.1.0:

System.ObjectDisposedException: Instances cannot be resolved and nested lifetimes cannot be created from this LifetimeScope as it has already been disposed.
    at Autofac.Core.Lifetime.LifetimeScope.CheckNotDisposed()
    at Autofac.Core.Lifetime.LifetimeScope.BeginLifetimeScope(Object tag)
    at Autofac.Extensions.DependencyInjection.AutofacServiceScopeFactory.CreateScope() in C:\projects\autofac-extensions-dependencyinjection\src\Autofac.Extensions.DependencyInjection\AutofacServiceScopeFactory.cs:line 62
    at Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher`1.OnDisconnectedAsync(HubConnectionContext connection, Exception exception)
    at Microsoft.AspNetCore.SignalR.HubConnectionHandler`1.HubOnDisconnectedAsync(HubConnectionContext connection, Exception exception)
    at Microsoft.AspNetCore.SignalR.HubConnectionHandler`1.RunHubAsync(HubConnectionContext connection)
    at Microsoft.AspNetCore.SignalR.HubConnectionHandler`1.OnConnectedAsync(ConnectionContext connection)
    at Microsoft.AspNetCore.SignalR.HubConnectionHandler`1.OnConnectedAsync(ConnectionContext connection)
    at Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionDispatcher.ExecuteApplication(ConnectionDelegate connectionDelegate, HttpConnectionContext connection)
    at Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionContext.WaitOnTasks(Task applicationTask, Task transportTask, Boolean closeGracefully)
    at Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionContext.DisposeAsync(Boolean closeGracefully)
    at Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionManager.DisposeAndRemoveAsync(HttpConnectionContext connection, Boolean closeGracefully)
    at Microsoft.AspNetCore.Http.Connections.Internal.HttpConnectionManager.DisposeAndRemoveAsync(HttpConnectionContext connection, Boolean closeGracefully)
muratg commented 5 years ago

Triage: This looks like an issue with SignalR or app throwing an exception on a background thread on shutdown. @BrennanConroy can you take another look?

muratg commented 5 years ago

(w3wp crashing is a red herring here.)

muratg commented 5 years ago

@fabiano Can you share your eventlogs when running with out-of-proc. You should be looking for a dotnet.exe crash in that case.

fabiano commented 5 years ago

@muratg The application is not crashing when running with out-of-process. Checked the logs and there is only the entries from IIS AspNetCore Module V2 shutting down the application:

Log Name:      Application
Source:        IIS AspNetCore Module V2
Date:          2/27/2019 1:56:38 PM
Event ID:      1012
Task Category: None
Level:         Information
Keywords:      Classic
User:          N/A
Computer:      THE_SERVER
Description:
Application 'C:\inetpub\wwwroot\the_app\' was recycled after detecting the app_offline file.
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
  <System>
    <Provider Name="IIS AspNetCore Module V2" />
    <EventID Qualifiers="0">1012</EventID>
    <Level>4</Level>
    <Task>0</Task>
    <Keywords>0x80000000000000</Keywords>
    <TimeCreated SystemTime="2019-02-27T18:56:38.000000000Z" />
    <EventRecordID>1410136</EventRecordID>
    <Channel>Application</Channel>
    <Computer>THE_SERVER</Computer>
    <Security />
  </System>
  <EventData>
    <Data>Application 'C:\inetpub\wwwroot\the_app\' was recycled after detecting the app_offline file.</Data>
    <Data>Process Id: 19388.</Data>
    <Data>File Version: 12.2.18346.1. Description: IIS ASP.NET Core Module V2 Request Handler. Commit: 0f9ad16b096ca2535d77efd2ad27645449421b44</Data>
  </EventData>
</Event>
Log Name:      Application
Source:        IIS AspNetCore Module V2
Date:          2/27/2019 1:56:38 PM
Event ID:      1006
Task Category: None
Level:         Information
Keywords:      Classic
User:          N/A
Computer:      THE_SERVER
Description:
Sent shutdown HTTP message to process '29772' and received http status '202'.
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
  <System>
    <Provider Name="IIS AspNetCore Module V2" />
    <EventID Qualifiers="0">1006</EventID>
    <Level>4</Level>
    <Task>0</Task>
    <Keywords>0x80000000000000</Keywords>
    <TimeCreated SystemTime="2019-02-27T18:56:38.000000000Z" />
    <EventRecordID>1410137</EventRecordID>
    <Channel>Application</Channel>
    <Computer>THE_SERVER</Computer>
    <Security />
  </System>
  <EventData>
    <Data>Sent shutdown HTTP message to process '29772' and received http status '202'.</Data>
    <Data>Process Id: 19388.</Data>
    <Data>File Version: 12.2.18346.1. Description: IIS ASP.NET Core Module V2 Request Handler. Commit: 0f9ad16b096ca2535d77efd2ad27645449421b44</Data>
  </EventData>
</Event>
Log Name:      Application
Source:        IIS AspNetCore Module V2
Date:          2/27/2019 1:56:38 PM
Event ID:      1030
Task Category: None
Level:         Information
Keywords:      Classic
User:          N/A
Computer:      THE_SERVER
Description:
Application '/LM/W3SVC/4/ROOT' with physical root 'C:\inetpub\wwwroot\the_app\' shut down process with Id '29772' listening on port '32531'
Event Xml:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
  <System>
    <Provider Name="IIS AspNetCore Module V2" />
    <EventID Qualifiers="0">1030</EventID>
    <Level>4</Level>
    <Task>0</Task>
    <Keywords>0x80000000000000</Keywords>
    <TimeCreated SystemTime="2019-02-27T18:56:38.000000000Z" />
    <EventRecordID>1410138</EventRecordID>
    <Channel>Application</Channel>
    <Computer>THE_SERVER</Computer>
    <Security />
  </System>
  <EventData>
    <Data>Application '/LM/W3SVC/4/ROOT' with physical root 'C:\inetpub\wwwroot\the_app\' shut down process with Id '29772' listening on port '32531'</Data>
    <Data>Process Id: 19388.</Data>
    <Data>File Version: 12.2.18346.1. Description: IIS ASP.NET Core Module V2 Request Handler. Commit: 0f9ad16b096ca2535d77efd2ad27645449421b44</Data>
  </EventData>
</Event>
analogrelay commented 5 years ago

Triage decisions:

analogrelay commented 5 years ago

Suggest considering this for 3.1. We don't have the capacity to do it in 3.0 given the current list of work.

davidfowl commented 3 years ago

I haven't seen reports of this recently. Is it still happening?

johanknirk commented 2 months ago

We are running default service mode SignalR with app services behind,

We do rolling deploys behind an application gateway and when shutting down a app service instance we get this in logs:

{"message":"Error when dispatching \u0027\u0022OnDisconnectedAsync\u0022\u0027 on hub.","id":"40685953-52b4-4d14-ba84-e7aab10b857b","fields":{"HubMethod":"OnDisconnectedAsync","EventId":"{ Id: 1, Name: \u0022ErrorDispatchingHubEvent\u0022 }","SourceContext":"Microsoft.AspNetCore.SignalR.HubConnectionHandler","NG_ServiceName":"TrumfAppBFF","NG_MachineName":"DW0SDWK000A6R","NG_Environment":"dev","SourceContextName":"HubConnectionHandler"},"messagetype":"structured","logger":"serilog","host":"DW0SDWK000A6R","app":"TrumfAppBFF","level":"ERROR","timestamp":"2024-09-12T16:56:30.413","exception":"System.ObjectDisposedException: Cannot access a disposed object.\r\nObject name: \u0027IServiceProvider\u0027.\r\n at Microsoft.Extensions.DependencyInjection.ServiceLookup.ThrowHelper.ThrowObjectDisposedException()\r\n at Microsoft.Extensions.DependencyInjection.ServiceProvider.CreateScope()\r\n at Microsoft.Extensions.DependencyInjection.ServiceProviderServiceExtensions.CreateAsyncScope(IServiceScopeFactory serviceScopeFactory)\r\n at Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher\u00601.OnDisconnectedAsync(HubConnectionContext connection, Exception exception)\r\n at Microsoft.AspNetCore.SignalR.HubConnectionHandler\u00601.HubOnDisconnectedAsync(HubConnectionContext connection, Exception exception)\r\n at Microsoft.AspNetCore.SignalR.HubConnectionHandler\u00601.RunHubAsync(HubConnectionContext connection)\r\n at Microsoft.AspNetCore.SignalR.HubConnectionHandler\u00601.OnConnectedAsync(ConnectionContext connection)\r\n at Microsoft.AspNetCore.SignalR.HubConnectionHandler\u00601.OnConnectedAsync(ConnectionContext connection)\r\n at Microsoft.Azure.SignalR.ServiceConnection.ProcessApplicationTaskAsyncCore(ClientConnectionContext connection)\r\n at Microsoft.Azure.SignalR.ServiceConnection.ProcessClientConnectionAsync(ClientConnectionContext connection)","templateHash":"9ac2dd74","logversion":"0"}