Signalr: Intermittent Error: Cannot access a disposed object

[MisterAcoustic]

Description

Hello,

Our application undergoes automated testing after each commit/build. Once every two or three hundred tests, the testing will fail due to an exception in SignalR.

Apologies that I cannot adhere to the guidelines very closely due to the nature of the error. I do not know know how to reproduce the problem on demand. We are using version 2.2.2 of SignalR, testing on Windows Server 2016, IIS version 10.0.14393.0.

Here is a typical stack trace:

Cannot access a disposed object. Object name: \u0027SERVERNAME\u0027. 
at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.Send(Func2 send, Object state) 
at Microsoft.AspNet.SignalR.Infrastructure.Connection.Send(ConnectionMessage message) 
at Microsoft.AspNet.SignalR.Hubs.HubDispatcher.Outgoing(IHubOutgoingInvokerContext context) 
at Microsoft.AspNet.SignalR.Hubs.HubPipelineModule.\u003c\u003ec__DisplayClass6_0.\u003cBuildOutgoing\u003eb__0(IHubOutgoingInvokerContext context) 
at Microsoft.AspNet.SignalR.Hubs.SignalProxy.TryInvokeMember(InvokeMemberBinder binder, Object[] args, Object\u0026 result) at CallSite.Target(Closure , CallSite , Object , String ) 
at E2SSPro.Web.SignalR.DBUpdateHub.SendMessage(String msg, String signalToken) in D:\\TeamCity\\BuildAgent3\\work\\b28bc0f3a005363e\\E2SSPro.Web\\SignalR\\DBUpdateHub.cs:line 25 
at E2SSPro.Web.Controllers.DBUpdateController.AddProgressMsg(String message) in D:\\TeamCity\\BuildAgent3\\work\\b28bc0f3a005363e\\E2SSPro.Web\\Controllers\\DBUpdateController.cs:line 103 
at E2SSPro.Web.Controllers.DBUpdateController.UpdateStatusDelegate(String message, Boolean messageBox, Boolean logFile) in D:\\TeamCity\\BuildAgent3\\work\\b28bc0f3a005363e\\E2SSPro.Web\\Controllers\\DBUpdateController.cs:line 113 ...

Background

I have a single server vm running 10 copies of our application in IIS. To run a test, a site is chosen, the app pool is shut down, new files are copied in, and the app pool restarted. The system uses a Redis cluster on the back end which handles the SignalR messaging. (I wrote the testing system, not the application, so I will have to ask if more details are needed about Redis.) An application database update process normally uses SignalR to report status to the user in their browser. However, in the automated testing case, there is no actual browser (only a different app sending requests), and therefore there is no client that is actually listening to any of the messages.

As I mentioned, we see this error very infrequently, but it's there, and it never stops happening :). It was also happening prior to upgrading to SignalR version 2.2.2. Any ideas what might be going on?

Thanks for your help.

Expected behavior

Send should function normally, and not throw this error

Actual behavior

Exception is thrown.

Steps to reproduce

As much as is possible, described above.

[moozzyk]

This seems like https://github.com/SignalR/SignalR/issues/3718 and/or https://github.com/SignalR/SignalR/issues/3093. It was supposed to be fixed in 2.2.2 and yours is the first report of this issue after 2.2.2 was shipped. Can you turn on tracing on the server side that could help figure out what is going on? Here is the configuration to use to get full traces.

[MisterAcoustic]

We upgraded to 2.2.2 in the hope that it would solve this problem.

Yes, I can try to turn on tracing. If it doesn't adversely affect the running of our tests, I will leave it on until the error happens again.

I'll report back when I have the traces.

[MisterAcoustic]

Well, I'm sorry to say that I cannot reproduce the problem when tracing is enabled.

I was unable to simply turn on logging on all of my sites due to the Event Log security restrictions. This means I wasn't able to replicate every step that happens in our testing process.

What I was able to do is enable tracing on 4 sites, each running the same set of application files (which were not updated or copied over during testing). Each test consisted of stopping the app pool, restoring the database (to force the update process that uses SignalR), starting the app pool, and sending the requests needed to trigger the SignalR communication.

I don't have an exact count, but I believe I exceeded 1000 repetitions, without seeing the issue.

Here are my guesses:
1) the problem could be a 'heisenbug', and simply will not appear with tracing enabled. Since it's so rare, this seems like a possibility, since it may be sensitive to timing.
2) the problem may not appear because the site app pools normally run under AppPoolIdentity, but for tracing the identity was changed to LocalSystem.
3) the problem may be related to the swapping out of the files when new code is deployed to the sites (not done during testing).
4) Aliens. Come on, you're thinking it too :)

Thanks for listening. I'm sure this will appear again when we least expect it. I just can't leave all the sites configured for tracing. And, I'm thinking that even if I did, we wouldn't see the issue.

I don't know if you'll find it necessary to close this issue, but I'm convinced the problem is real and still present in 2.2.2.

If this stays open, I will update it when it happens again.

[moozzyk]

Thanks for the follow up. Let's keep this issue open and we can revisit if we have more data.

[MisterAcoustic]

Since the problem did not appear while I had tracing enabled, the only thing I know to do is report on how often we are seeing the problem. The error happened again today during our normal testing. This is in line with the once every two or three hundred frequency I mentioned earlier.

I did notice something, but it could easily be a coincidence. Even though SignalR tracing was off, I checked the Event Logs to see if I could see anything that might have happened around the same time as the error. On my ten sites, each application pool timeout is set to 20 minutes. A previous test run had completed about 25 minutes before the error. So, for each of my app pools (including the site that had the error), there is an event log entry like "A worker process with process id of '20640' serving application pool 'Site_8Pool' was shutdown due to inactivity. Application Pool timeout configuration was set to 20 minutes. A new worker process will be started when needed."

I'll leave it to you to speculate what this might have to do with anything :)

It's been suggested that we change our code to disable the use of SignalR when we are running tests. That would solve all of our issues, but it wouldn't help solve any issue with SignalR.

I hope someone can come along and provide some better information for you at some point.

[MisterAcoustic]

The problem happened twice today, about five seconds apart.

Two different sites were starting to execute two different tests, both of which run the update process that uses SignalR.

I'll stop reporting frequency now - just assume that I'm still seeing the problem regularly. I will post again if there is any change in the behavior, or more information comes to light.

[sreead]

We are facing this same issue in our Azure webapp currently. We use Microsoft.Aspnet.SignalR.Core 2.2.2 in our application and have come across the exact same problem with the same stacktrace shown in the original problem description of this thread while testing our application. Is there a workaround or a likely solution in near future ?

[muratg]

@anurse @halter73 could you guys take a look when you're back after the holidays?

[anurse]

It's hard to get an idea of what might be happening without seeing the trace from where the error occurs. The stack trace is from a place in ScaleoutStream that rethrows an error that occurred elsewhere (in a background task).

@MisterAcoustic you mentioned EventLog tracing wasn't really feasible in the environment where it repros, could you try one of the other trace systems (like text file logging) from https://docs.microsoft.com/en-us/aspnet/signalr/overview/testing-and-debugging/enabling-signalr-tracing ?

@sreead Similarly, are you able to collect any trace data from SignalR to see the exception logged where it occurs? See https://docs.microsoft.com/en-us/aspnet/signalr/overview/testing-and-debugging/enabling-signalr-tracing for some docs on setting up tracing. If you're able to collect traces from around where the error occurs and post them somewhere to review (preferably to gist.github.com or something similar rather than filling this thread with logs ;)) we can try to work out where the exception is originating from.

[MisterAcoustic]

@anurse Yes, I can do that. I didn't actually realize there was an alternative to the EventLogTraceListeners. I have a bit of work to do to get the config changes into the system. I will do that as soon as possible, and I would expect to see the problem in one to two weeks. Coincidentally, it happened this morning :).

[anurse]

@MisterAcoustic Great! Hopefully that can give us a little more context as to what's going on.

[moozzyk]

AFAIR the configuration in the docs did not have all the events. I created a full list once by looking at the code. You can find it here: https://gist.github.com/moozzyk/5abdc2ff439c179832e143c6a72a3e0a

[MisterAcoustic]

Just an update: I am successfully logging the debugging information for all ten of my test sites. I used the full list of sources from the link provided by moozzyk, and switched to TextWriterTraceListeners.

Hopefully, now it's just a matter of time. Unless, as in my previous testing, the problem never occurs with the debug output turned on - I guess we'll find out.

[MisterAcoustic]

Wow! That was fast. Got it already. This is from the SignalR-Bus log, and probably represents a number of failures as the same site tried to execute different tests. I just included the whole log since it wasn't terribly large. Good Luck!

SignalR.RedisMessageBus Information: 0 : Connecting...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis1.e2shop.local:6379,redis2.e2shop.local:6379,redis3.e2shop.local:6379,password=*****
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connecting redis1.e2shop.local:6379/Interactive...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: BeginConnect: redis1.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connecting redis2.e2shop.local:6379/Interactive...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: BeginConnect: redis2.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connecting redis3.e2shop.local:6379/Interactive...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: BeginConnect: redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: EndConnect: redis1.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connected Interactive/redis1.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Server handshake
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Setting client name: LITEWORLD
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: 3 unique nodes specified
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Requesting tie-break from redis1.e2shop.local:6379 > __Booksleeve_TieBreak...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Auto-configure...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Sending critical tracer: Interactive/redis1.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Requesting tie-break from redis2.e2shop.local:6379 > __Booksleeve_TieBreak...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Requesting tie-break from redis3.e2shop.local:6379 > __Booksleeve_TieBreak...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Allowing endpoints 00:00:05 to respond...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis1.e2shop.local:6379: ECHO
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Flushing outbound buffer
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Starting poll
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Awaiting task completion, IOCP: (Busy=1,Free=999,Min=8,Max=1000), WORKER: (Busy=8,Free=32759,Min=8,Max=32767)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: EndConnect: redis2.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connected Interactive/redis2.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Server handshake
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Setting client name: LITEWORLD
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Auto-configure...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Sending critical tracer: Interactive/redis2.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis2.e2shop.local:6379: ECHO
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Flushing outbound buffer
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Starting poll
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: EndConnect: redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connected Interactive/redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Server handshake
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Setting client name: LITEWORLD
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Auto-configure...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Sending critical tracer: Interactive/redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis3.e2shop.local:6379: ECHO
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Flushing outbound buffer
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Starting poll
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connect complete: redis1.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connect complete: redis2.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connect complete: redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis1.e2shop.local:6379 / ECHO: BulkString: 16 bytes
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis1.e2shop.local:6379: GET __Booksleeve_TieBreak
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis1.e2shop.local:6379: PING
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis2.e2shop.local:6379 / ECHO: BulkString: 16 bytes
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis2.e2shop.local:6379: GET __Booksleeve_TieBreak
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis2.e2shop.local:6379: PING
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis3.e2shop.local:6379 / ECHO: BulkString: 16 bytes
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis3.e2shop.local:6379: GET __Booksleeve_TieBreak
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis3.e2shop.local:6379: PING
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis1.e2shop.local:6379 / GET __Booksleeve_TieBreak: (null)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis1.e2shop.local:6379 / PING: SimpleString: PONG
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis2.e2shop.local:6379 / GET __Booksleeve_TieBreak: (null)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis2.e2shop.local:6379 / PING: SimpleString: PONG
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis3.e2shop.local:6379 / GET __Booksleeve_TieBreak: (null)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis3.e2shop.local:6379 / PING: SimpleString: PONG
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: All tasks completed cleanly, IOCP: (Busy=1,Free=999,Min=8,Max=1000), WORKER: (Busy=6,Free=32761,Min=8,Max=32767)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis1.e2shop.local:6379 returned with success
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis2.e2shop.local:6379 returned with success
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis3.e2shop.local:6379 returned with success
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: All tasks are already complete
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis1.e2shop.local:6379 had no tiebreaker set
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis2.e2shop.local:6379 had no tiebreaker set
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis3.e2shop.local:6379 had no tiebreaker set
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Single master detected: redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis1.e2shop.local:6379: Standalone v3.2.9, slave; 16 databases; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis1.e2shop.local:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, sync=10, async=2, socks=1; sub ops=3, qu=0, qs=0, qc=0, wr=0, subs=1, sync=3, socks=1
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 0+3=3 (0.30 ops/s; spans 10s)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis2.e2shop.local:6379: Standalone v3.2.9, slave; 16 databases; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis2.e2shop.local:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, sync=10, async=2, socks=1; sub ops=3, qu=0, qs=0, qc=0, wr=0, subs=1, sync=3, socks=1
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 0+3=3 (0.30 ops/s; spans 10s)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis3.e2shop.local:6379: Standalone v3.2.9, master; 16 databases; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablishing
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis3.e2shop.local:6379: int ops=12, qu=0, qs=0, qc=1, wr=0, sync=10, socks=1; sub ops=3, qu=0, qs=3, qc=0, wr=0, socks=1
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 0+3=3 (0.30 ops/s; spans 10s)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Sync timeouts: 0; fire and forget: 0; last heartbeat: -1s ago
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Starting heartbeat...
SignalR.RedisMessageBus Information: 0 : Connection opened
SignalR.RedisConnection Information: 0 : Connection restored
SignalR.RedisMessageBus Information: 0 : Connection restored
SignalR.ScaleoutMessageBus Information: 0 : Stream(0) - Changed state from Initial to Open
SignalR.RedisConnection Information: 0 : Subscribing to key: E2Shop.SignalR
SignalR.RedisMessageBus Verbose: 0 : Subscribed to event E2Shop.SignalR
SignalR.RedisMessageBus Error: 0 : Unexpected state.
SignalR.RedisMessageBus Information: 0 : Shutdown()
SignalR.RedisConnection Information: 0 : Closing key: E2Shop.SignalR
SignalR.ScaleoutMessageBus Warning: 0 : Exception thrown by Task: System.AggregateException: One or more errors occurred. ---> System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'LITEWORLD'.
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl[T](Message message, ResultProcessor`1 processor, Object state, ServerEndPoint server)
   at StackExchange.Redis.RedisBase.ExecuteAsync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server)
   at Microsoft.AspNet.SignalR.Redis.RedisConnection.ScriptEvaluateAsync(Int32 database, String script, String key, Byte[] messageArguments)
   at Microsoft.AspNet.SignalR.Redis.RedisMessageBus.Send(Int32 streamIndex, IList`1 messages)
   at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.SendContext.InvokeSend()
   --- End of inner exception stack trace ---
---> (Inner Exception #0) System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'LITEWORLD'.
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl[T](Message message, ResultProcessor`1 processor, Object state, ServerEndPoint server)
   at StackExchange.Redis.RedisBase.ExecuteAsync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server)
   at Microsoft.AspNet.SignalR.Redis.RedisConnection.ScriptEvaluateAsync(Int32 database, String script, String key, Byte[] messageArguments)
   at Microsoft.AspNet.SignalR.Redis.RedisMessageBus.Send(Int32 streamIndex, IList`1 messages)
   at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.SendContext.InvokeSend()<---

SignalR.ScaleoutMessageBus Error: 0 : Stream(0) - Send failed: System.AggregateException: One or more errors occurred. ---> System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'LITEWORLD'.
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl[T](Message message, ResultProcessor`1 processor, Object state, ServerEndPoint server)
   at StackExchange.Redis.RedisBase.ExecuteAsync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server)
   at Microsoft.AspNet.SignalR.Redis.RedisConnection.ScriptEvaluateAsync(Int32 database, String script, String key, Byte[] messageArguments)
   at Microsoft.AspNet.SignalR.Redis.RedisMessageBus.Send(Int32 streamIndex, IList`1 messages)
   at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.SendContext.InvokeSend()
   --- End of inner exception stack trace ---
---> (Inner Exception #0) System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'LITEWORLD'.
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl[T](Message message, ResultProcessor`1 processor, Object state, ServerEndPoint server)
   at StackExchange.Redis.RedisBase.ExecuteAsync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server)
   at Microsoft.AspNet.SignalR.Redis.RedisConnection.ScriptEvaluateAsync(Int32 database, String script, String key, Byte[] messageArguments)
   at Microsoft.AspNet.SignalR.Redis.RedisMessageBus.Send(Int32 streamIndex, IList`1 messages)
   at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.SendContext.InvokeSend()<---

SignalR.ScaleoutMessageBus Error: 0 : Stream(0) - Error has happened with the following exception: System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'LITEWORLD'.
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl[T](Message message, ResultProcessor`1 processor, Object state, ServerEndPoint server)
   at StackExchange.Redis.RedisBase.ExecuteAsync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server)
   at Microsoft.AspNet.SignalR.Redis.RedisConnection.ScriptEvaluateAsync(Int32 database, String script, String key, Byte[] messageArguments)
   at Microsoft.AspNet.SignalR.Redis.RedisMessageBus.Send(Int32 streamIndex, IList`1 messages)
   at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.SendContext.InvokeSend().
SignalR.ScaleoutMessageBus Information: 0 : Stream(0) - Changed state from Open to Buffering

[anurse]

Ok, so the exception is occurring because the ConnectionMultiplexer has been disposed then. So someone is calling Dispose. It's likely us, somewhere, since I don't think apps should ever been working directly on that type. I need to dig a little bit (this isn't an area of code I'm too familiar with unfortunately; paging @halter73 for any top-of-mind things you can think of).

Thanks for the logs! Very helpful!

[anurse]

Ok, so some new data and context. This series of log messages is suspect:

SignalR.RedisMessageBus Information: 0 : Connection opened
SignalR.RedisConnection Information: 0 : Connection restored
SignalR.RedisMessageBus Information: 0 : Connection restored
SignalR.ScaleoutMessageBus Information: 0 : Stream(0) - Changed state from Initial to Open
SignalR.RedisConnection Information: 0 : Subscribing to key: E2Shop.SignalR
SignalR.RedisMessageBus Verbose: 0 : Subscribed to event E2Shop.SignalR
SignalR.RedisMessageBus Error: 0 : Unexpected state

The first message Connection opened, and the last message Unexpected state are fired during the RedisMessageBus.ConnectWithRetry method (and the methods it calls). Which means the middle messages regarding restoring the connection are occurring during the connect flow. As a result, the connection restoration code in OnConnectionRestored kicks in and ends up setting the state to Connected, in the middle of the connection process. Which means when the connection process concludes and tries to set the state to Connected it triggers that last Error message because it expects the state to be Closed.

I think I can make a fix for this by locking the redisConnectionEventLock lock during ConnectWithRetry, which will force the OnConnectionRestored event to wait until the connection is fully established before running. Tagging some SignalR randos to see if they think my idea is crazy or might actually work ;) (@halter73, I know you don't really have much history in these files but hey, why not; @davidfowl because again, why not)

@MisterAcoustic if I got you a new build of the SignalR Redis DLL with a proposed, would you be able to deploy it and see if it fixes this issue? I can't really seem to repro it (though I have some ideas to try now that I know the problem). I'm also going to throw a bunch more tracing in (at the verbose level). It would be good to try reproing the problem with tracing disabled first (to ensure my tracing isn't just dodging the race) and then enable tracing only if the issue continues to repro.

[MisterAcoustic]

@anurse I should be able to test a candidate fix. The only problem will be knowing when to declare that it works, given that the error is quite rare. Let me know when you have something and I will get it into a branch that we can test repeatedly.

[anurse]

@MisterAcoustic I can provide a fix via a single replacement DLL fairly quickly. Getting a new NuGet package published somewhere is much more difficult. I'll work on getting the DLL ready and let you know when I've got something. Can you email me directly at [email protected] ? I've also got to work out the best way to distribute a fixed DLL to you, and email will be a little easier for that purpose :).

[moozzyk]

@anurse - https://github.com/SignalR/SignalR/issues/3976#issuecomment-317050103

[MisterAcoustic]

@anurse Email sent.

The problem has occurred again. The log is slightly different, so I'll include it here in case it gives any more clues.

SignalR.RedisMessageBus Information: 0 : Connecting...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis1.e2shop.local:6379,redis2.e2shop.local:6379,redis3.e2shop.local:6379,password=*****
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connecting redis1.e2shop.local:6379/Interactive...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: BeginConnect: redis1.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connecting redis2.e2shop.local:6379/Interactive...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: BeginConnect: redis2.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connecting redis3.e2shop.local:6379/Interactive...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: BeginConnect: redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: 3 unique nodes specified
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Requesting tie-break from redis1.e2shop.local:6379 > __Booksleeve_TieBreak...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Requesting tie-break from redis2.e2shop.local:6379 > __Booksleeve_TieBreak...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Requesting tie-break from redis3.e2shop.local:6379 > __Booksleeve_TieBreak...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Allowing endpoints 00:00:05 to respond...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Awaiting task completion, IOCP: (Busy=0,Free=1000,Min=8,Max=1000), WORKER: (Busy=8,Free=32759,Min=8,Max=32767)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: EndConnect: redis1.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connected Interactive/redis1.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Server handshake
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Setting client name: LITEWORLD
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Auto-configure...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Sending critical tracer: Interactive/redis1.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: EndConnect: redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connected Interactive/redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Server handshake
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Setting client name: LITEWORLD
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Auto-configure...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Sending critical tracer: Interactive/redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis3.e2shop.local:6379: ECHO
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Flushing outbound buffer
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Starting poll
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connect complete: redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis1.e2shop.local:6379: ECHO
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Flushing outbound buffer
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Starting poll
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connect complete: redis1.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: EndConnect: redis2.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connected Interactive/redis2.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Server handshake
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Setting client name: LITEWORLD
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Auto-configure...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Sending critical tracer: Interactive/redis2.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis2.e2shop.local:6379: ECHO
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Flushing outbound buffer
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Starting poll
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connect complete: redis2.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis3.e2shop.local:6379 / ECHO: BulkString: 16 bytes
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis1.e2shop.local:6379 / ECHO: BulkString: 16 bytes
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis2.e2shop.local:6379 / ECHO: BulkString: 16 bytes
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis3.e2shop.local:6379: GET __Booksleeve_TieBreak
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis3.e2shop.local:6379: PING
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis1.e2shop.local:6379: GET __Booksleeve_TieBreak
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis1.e2shop.local:6379: PING
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis2.e2shop.local:6379: GET __Booksleeve_TieBreak
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis2.e2shop.local:6379: PING
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis3.e2shop.local:6379 / GET __Booksleeve_TieBreak: (null)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis3.e2shop.local:6379 / PING: SimpleString: PONG
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis1.e2shop.local:6379 / GET __Booksleeve_TieBreak: (null)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis1.e2shop.local:6379 / PING: SimpleString: PONG
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis2.e2shop.local:6379 / GET __Booksleeve_TieBreak: (null)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis2.e2shop.local:6379 / PING: SimpleString: PONG
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: All tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=8,Max=1000), WORKER: (Busy=8,Free=32759,Min=8,Max=32767)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis1.e2shop.local:6379 returned with success
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis2.e2shop.local:6379 returned with success
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis3.e2shop.local:6379 returned with success
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: All tasks are already complete
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis1.e2shop.local:6379 had no tiebreaker set
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis2.e2shop.local:6379 had no tiebreaker set
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis3.e2shop.local:6379 had no tiebreaker set
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Single master detected: redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis1.e2shop.local:6379: Standalone v3.2.9, slave; 16 databases; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis1.e2shop.local:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, sync=10, async=2, socks=1; sub ops=3, qu=0, qs=0, qc=0, wr=0, subs=1, sync=3, socks=1
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 0+3=3 (0.30 ops/s; spans 10s)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis2.e2shop.local:6379: Standalone v3.2.9, slave; 16 databases; keep-alive: 00:01:00; int: ConnectedEstablished; sub: Connecting
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis2.e2shop.local:6379: int ops=12, qu=0, qs=0, qc=1, wr=0, sync=10, socks=1; sub ops=0, qu=0, qs=0, qc=0, wr=0, socks=1
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 0 (0.00 ops/s; spans 10s)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis3.e2shop.local:6379: Standalone v3.2.9, master; 16 databases; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis3.e2shop.local:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, sync=10, async=2, socks=1; sub ops=3, qu=0, qs=0, qc=0, wr=0, subs=1, sync=3, socks=1
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 0+3=3 (0.30 ops/s; spans 10s)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Sync timeouts: 0; fire and forget: 0; last heartbeat: -1s ago
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Starting heartbeat...
SignalR.RedisMessageBus Information: 0 : Connection opened
SignalR.RedisConnection Information: 0 : Subscribing to key: E2Shop.SignalR
SignalR.RedisConnection Information: 0 : Connection restored
SignalR.RedisMessageBus Information: 0 : Connection restored
SignalR.ScaleoutMessageBus Information: 0 : Stream(0) - Changed state from Initial to Open
SignalR.RedisMessageBus Verbose: 0 : Subscribed to event E2Shop.SignalR
SignalR.RedisMessageBus Error: 0 : Unexpected state.
SignalR.RedisMessageBus Information: 0 : Shutdown()
SignalR.RedisConnection Information: 0 : Closing key: E2Shop.SignalR
SignalR.ScaleoutMessageBus Warning: 0 : Exception thrown by Task: System.AggregateException: One or more errors occurred. ---> System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'LITEWORLD'.
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl[T](Message message, ResultProcessor`1 processor, Object state, ServerEndPoint server)
   at StackExchange.Redis.RedisBase.ExecuteAsync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server)
   at Microsoft.AspNet.SignalR.Redis.RedisConnection.ScriptEvaluateAsync(Int32 database, String script, String key, Byte[] messageArguments)
   at Microsoft.AspNet.SignalR.Redis.RedisMessageBus.Send(Int32 streamIndex, IList`1 messages)
   at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.SendContext.InvokeSend()
   --- End of inner exception stack trace ---
---> (Inner Exception #0) System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'LITEWORLD'.
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl[T](Message message, ResultProcessor`1 processor, Object state, ServerEndPoint server)
   at StackExchange.Redis.RedisBase.ExecuteAsync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server)
   at Microsoft.AspNet.SignalR.Redis.RedisConnection.ScriptEvaluateAsync(Int32 database, String script, String key, Byte[] messageArguments)
   at Microsoft.AspNet.SignalR.Redis.RedisMessageBus.Send(Int32 streamIndex, IList`1 messages)
   at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.SendContext.InvokeSend()<---

SignalR.ScaleoutMessageBus Error: 0 : Stream(0) - Send failed: System.AggregateException: One or more errors occurred. ---> System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'LITEWORLD'.
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl[T](Message message, ResultProcessor`1 processor, Object state, ServerEndPoint server)
   at StackExchange.Redis.RedisBase.ExecuteAsync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server)
   at Microsoft.AspNet.SignalR.Redis.RedisConnection.ScriptEvaluateAsync(Int32 database, String script, String key, Byte[] messageArguments)
   at Microsoft.AspNet.SignalR.Redis.RedisMessageBus.Send(Int32 streamIndex, IList`1 messages)
   at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.SendContext.InvokeSend()
   --- End of inner exception stack trace ---
---> (Inner Exception #0) System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'LITEWORLD'.
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl[T](Message message, ResultProcessor`1 processor, Object state, ServerEndPoint server)
   at StackExchange.Redis.RedisBase.ExecuteAsync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server)
   at Microsoft.AspNet.SignalR.Redis.RedisConnection.ScriptEvaluateAsync(Int32 database, String script, String key, Byte[] messageArguments)
   at Microsoft.AspNet.SignalR.Redis.RedisMessageBus.Send(Int32 streamIndex, IList`1 messages)
   at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.SendContext.InvokeSend()<---

SignalR.ScaleoutMessageBus Error: 0 : Stream(0) - Error has happened with the following exception: System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'LITEWORLD'.
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl[T](Message message, ResultProcessor`1 processor, Object state, ServerEndPoint server)
   at StackExchange.Redis.RedisBase.ExecuteAsync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server)
   at Microsoft.AspNet.SignalR.Redis.RedisConnection.ScriptEvaluateAsync(Int32 database, String script, String key, Byte[] messageArguments)
   at Microsoft.AspNet.SignalR.Redis.RedisMessageBus.Send(Int32 streamIndex, IList`1 messages)
   at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.SendContext.InvokeSend().
SignalR.ScaleoutMessageBus Information: 0 : Stream(0) - Changed state from Open to Buffering
SignalR.RedisMessageBus Information: 0 : RedisMessageBus is being disposed
SignalR.ScaleoutMessageBus Information: 0 : Stream(0) - Changed state from Buffering to Closed

[anurse]

Thanks @MisterAcoustic, got your email. It looks like this log, while slightly different, is also exhibiting the issue I resolved in #4059, so hopefully it should be the same thing.

[anurse]

There is a candidate fix for this available on the aspnetwebstacknightly MyGet Feed (NuGet feed URL is https://www.myget.org/F/aspnetwebstacknightly/api/v2). The version containing the fix is 2.2.3-alpha1-180109-b1358. If you're seeing this issue, feel free to try the fix and let us know. However, this release has not been fully verified and should not be used in production environments

[MisterAcoustic]

Just an update from my end. I was delayed getting this integrated into our build - but that's done now, and I plan to get it started doing test runs today. Fingers crossed.

[MisterAcoustic]

Ah well - the second time it ran through testing, I received a different error. Superficial stack trace below. I will turn on tracing and try to get it to reproduce.

The stream has been closed.
   at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.Send(Func`2 send, Object state)
   at Microsoft.AspNet.SignalR.Infrastructure.Connection.Send(ConnectionMessage message)
   at Microsoft.AspNet.SignalR.Hubs.HubDispatcher.Outgoing(IHubOutgoingInvokerContext context)
   at Microsoft.AspNet.SignalR.Hubs.HubPipelineModule.\u003c\u003ec__DisplayClass6_0.\u003cBuildOutgoing\u003eb__0(IHubOutgoingInvokerContext context)
   at Microsoft.AspNet.SignalR.Hubs.SignalProxy.TryInvokeMember(InvokeMemberBinder binder, Object[] args, Object\u0026 result)
   at CallSite.Target(Closure , CallSite , Object , String )
   at E2SSPro.Web.SignalR.DBUpdateHub.SendMessage(String msg, String signalToken) in D:\\TeamCity\\BuildAgent3\\work\\b28bc0f3a005363e\\E2SSPro.Web\\SignalR\\DBUpdateHub.cs:line 21
   at E2SSPro.Web.Controllers.DBUpdateController.AddProgressMsg(String message) in D:\\TeamCity\\BuildAgent3\\work\\b28bc0f3a005363e\\E2SSPro.Web\\Controllers\\DBUpdateController.cs:line 103
   at E2SSPro.Web.Controllers.DBUpdateController.UpdateStatusDelegate(String message, Boolean messageBox, Boolean logFile) in D:\\TeamCity\\BuildAgent3\\work\\b28bc0f3a005363e\\E2SSPro.Web\\Controllers\\DBUpdateController.cs:line 113
   at E2SSPro.Common.UpdateDatabase.ExecuteFile(String filename, String version, Boolean isMaster, Object[] args) in D:\\TeamCity\\BuildAgent3\\work\\b28bc0f3a005363e\\Common\\Classes\\UpdateDatabase.cs:line 1199
   at E2SSPro.Common.UpdateDatabase.UpdateCompany(Boolean suppressSuccess) in D:\\TeamCity\\BuildAgent3\\work\\b28bc0f3a005363e\\Common\\Classes\\UpdateDatabase.cs:line 1010
   at E2SSPro.Common.UpdateDatabase.UpdateAll() in D:\\TeamCity\\BuildAgent3\\work\\b28bc0f3a005363e\\Common\\Classes\\UpdateDatabase.cs:line 823
   at E2SSPro.Web.Controllers.DBUpdateController.PerformUpdate() in D:\\TeamCity\\BuildAgent3\\work\\b28bc0f3a005363e\\E2SSPro.Web\\Controllers\\DBUpdateController.cs:line 124
   at E2SSPro.Web.Controllers.DBUpdateController.Update() in D:\\TeamCity\\BuildAgent3\\work\\b28bc0f3a005363e\\E2SSPro.Web\\Controllers\\DBUpdateController.cs:line 63

[davidfowl]

@anurse we may want to update this code to use ExcetionDispatchInfo:

https://github.com/SignalR/SignalR/blob/ab0e76f4a116c299bde8a89a306c9d2cf003cf8a/src/Microsoft.AspNet.SignalR.Core/Messaging/ScaleoutStream.cs#L137

[anurse]

@MisterAcoustic let me know if you can get tracing information for that. I'll also do as @davidfowl suggests as well and see if we can properly capture the exception context in the next build.

[MisterAcoustic]

Hi, sorry to bring worse news, but we've just had the original disposed object error with the new prerelease code. I had not yet turned on tracing, so I did not catch more details on it. I won't delay any further with turning on the tracing :).

[anurse]

Can you try turning on tracing? I'm curious if it's hitting the same issue. I didn't see any other obvious issues in the traces you sent earlier :(. I also added some additional tracing to the prerelease build and it seems like tracing hasn't been affecting the bug.

[anurse]

I've also got another pre-release package coming soon that should provide additional tracing and exception information. I'll post here when I've got a build number for you.

[anurse]

Version 2.2.3-alpha1-180117-b1368 contains the updated exception handling and tracing. Can you try that in your environment and leave tracing on? Let's stop messing with tracing since it seems like the issue arises regardless of tracing being enabled.

[MisterAcoustic]

I should be able to integrate the new version this afternoon. The previous version has been running through the tests once per hour (16 chances each for the problem to occur), with tracing enabled, but I haven't captured either problem yet. I'll do the same with the new version and let you know what we get.

[MisterAcoustic]

@anurse Here is the new output for the disposed object error. Also, if there is the possibility to add time stamps to the log output, that would help me in some circumstances.

SignalR.RedisMessageBus Information: 0 : Connecting...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis1.e2shop.local:6379,redis2.e2shop.local:6379,redis3.e2shop.local:6379,password=*****
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connecting redis1.e2shop.local:6379/Interactive...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: BeginConnect: redis1.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connecting redis2.e2shop.local:6379/Interactive...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: BeginConnect: redis2.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connecting redis3.e2shop.local:6379/Interactive...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: BeginConnect: redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: 3 unique nodes specified
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Requesting tie-break from redis1.e2shop.local:6379 > __Booksleeve_TieBreak...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Requesting tie-break from redis2.e2shop.local:6379 > __Booksleeve_TieBreak...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Requesting tie-break from redis3.e2shop.local:6379 > __Booksleeve_TieBreak...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Allowing endpoints 00:00:05 to respond...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Awaiting task completion, IOCP: (Busy=0,Free=1000,Min=8,Max=1000), WORKER: (Busy=8,Free=32759,Min=8,Max=32767)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: EndConnect: redis2.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connected Interactive/redis2.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Server handshake
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Setting client name: LITEWORLD
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Auto-configure...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Sending critical tracer: Interactive/redis2.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis2.e2shop.local:6379: ECHO
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Flushing outbound buffer
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Starting poll
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: EndConnect: redis1.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connected Interactive/redis1.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Server handshake
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Setting client name: LITEWORLD
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Auto-configure...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Sending critical tracer: Interactive/redis1.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis1.e2shop.local:6379: ECHO
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Flushing outbound buffer
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Starting poll
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: EndConnect: redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connected Interactive/redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Server handshake
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Setting client name: LITEWORLD
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Auto-configure...
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Sending critical tracer: Interactive/redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis3.e2shop.local:6379: ECHO
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Flushing outbound buffer
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Starting poll
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connect complete: redis2.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connect complete: redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Connect complete: redis1.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis2.e2shop.local:6379 / ECHO: BulkString: 16 bytes
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis3.e2shop.local:6379 / ECHO: BulkString: 16 bytes
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis1.e2shop.local:6379 / ECHO: BulkString: 16 bytes
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis2.e2shop.local:6379: GET __Booksleeve_TieBreak
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis2.e2shop.local:6379: PING
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis3.e2shop.local:6379: GET __Booksleeve_TieBreak
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis3.e2shop.local:6379: PING
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis1.e2shop.local:6379: GET __Booksleeve_TieBreak
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Writing to Interactive/redis1.e2shop.local:6379: PING
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis1.e2shop.local:6379 / GET __Booksleeve_TieBreak: (null)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis1.e2shop.local:6379 / PING: SimpleString: PONG
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis2.e2shop.local:6379 / GET __Booksleeve_TieBreak: (null)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis2.e2shop.local:6379 / PING: SimpleString: PONG
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis3.e2shop.local:6379 / GET __Booksleeve_TieBreak: (null)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Response from Interactive/redis3.e2shop.local:6379 / PING: SimpleString: PONG
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: All tasks completed cleanly, IOCP: (Busy=0,Free=1000,Min=8,Max=1000), WORKER: (Busy=7,Free=32760,Min=8,Max=32767)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis1.e2shop.local:6379 returned with success
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis2.e2shop.local:6379 returned with success
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis3.e2shop.local:6379 returned with success
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: All tasks are already complete
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis1.e2shop.local:6379 had no tiebreaker set
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis2.e2shop.local:6379 had no tiebreaker set
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis3.e2shop.local:6379 had no tiebreaker set
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Single master detected: redis3.e2shop.local:6379
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis1.e2shop.local:6379: Standalone v3.2.9, slave; 16 databases; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablished, 1 active
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis1.e2shop.local:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, sync=10, async=2, socks=1; sub ops=3, qu=0, qs=0, qc=0, wr=0, subs=1, sync=3, socks=1
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 0+3=3 (0.30 ops/s; spans 10s)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis2.e2shop.local:6379: Standalone v3.2.9, slave; 16 databases; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablishing
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis2.e2shop.local:6379: int ops=12, qu=0, qs=0, qc=0, wr=0, sync=10, async=2, socks=1; sub ops=3, qu=0, qs=3, qc=0, wr=0, socks=1
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 0+3=3 (0.30 ops/s; spans 10s)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis3.e2shop.local:6379: Standalone v3.2.9, master; 16 databases; keep-alive: 00:01:00; int: ConnectedEstablished; sub: ConnectedEstablishing
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: redis3.e2shop.local:6379: int ops=12, qu=0, qs=0, qc=1, wr=0, sync=10, socks=1; sub ops=3, qu=0, qs=3, qc=0, wr=0, socks=1
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Circular op-count snapshot; int: 0+12=12 (1.20 ops/s; spans 10s); sub: 0+3=3 (0.30 ops/s; spans 10s)
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Sync timeouts: 0; fire and forget: 0; last heartbeat: -1s ago
SignalR.RedisConnection Verbose: 0 : ConnectionMultiplexer: Starting heartbeat...
SignalR.RedisMessageBus Information: 0 : Connection opened
SignalR.RedisConnection Information: 0 : Subscribing to key: E2Shop.SignalR
SignalR.RedisConnection Information: 0 : Connection restored
SignalR.RedisConnection Information: 0 : Connection restored
SignalR.RedisMessageBus Information: 0 : Connection restored
SignalR.ScaleoutMessageBus Information: 0 : Stream(0) - Changed state from Initial to Open
SignalR.RedisMessageBus Verbose: 0 : Subscribed to event E2Shop.SignalR
SignalR.RedisMessageBus Error: 0 : Unexpected state.
SignalR.RedisMessageBus Information: 0 : Shutdown()
SignalR.RedisConnection Information: 0 : Closing key: E2Shop.SignalR
SignalR.ScaleoutMessageBus Warning: 0 : Exception thrown by Task: System.AggregateException: One or more errors occurred. ---> System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'LITEWORLD'.
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl[T](Message message, ResultProcessor`1 processor, Object state, ServerEndPoint server)
   at StackExchange.Redis.RedisBase.ExecuteAsync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server)
   at Microsoft.AspNet.SignalR.Redis.RedisConnection.ScriptEvaluateAsync(Int32 database, String script, String key, Byte[] messageArguments)
   at Microsoft.AspNet.SignalR.Redis.RedisMessageBus.Send(Int32 streamIndex, IList`1 messages)
   at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.SendContext.InvokeSend()
   --- End of inner exception stack trace ---
---> (Inner Exception #0) System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'LITEWORLD'.
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl[T](Message message, ResultProcessor`1 processor, Object state, ServerEndPoint server)
   at StackExchange.Redis.RedisBase.ExecuteAsync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server)
   at Microsoft.AspNet.SignalR.Redis.RedisConnection.ScriptEvaluateAsync(Int32 database, String script, String key, Byte[] messageArguments)
   at Microsoft.AspNet.SignalR.Redis.RedisMessageBus.Send(Int32 streamIndex, IList`1 messages)
   at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.SendContext.InvokeSend()<---

SignalR.ScaleoutMessageBus Error: 0 : Stream(0) - Send failed: System.AggregateException: One or more errors occurred. ---> System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'LITEWORLD'.
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl[T](Message message, ResultProcessor`1 processor, Object state, ServerEndPoint server)
   at StackExchange.Redis.RedisBase.ExecuteAsync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server)
   at Microsoft.AspNet.SignalR.Redis.RedisConnection.ScriptEvaluateAsync(Int32 database, String script, String key, Byte[] messageArguments)
   at Microsoft.AspNet.SignalR.Redis.RedisMessageBus.Send(Int32 streamIndex, IList`1 messages)
   at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.SendContext.InvokeSend()
   --- End of inner exception stack trace ---
---> (Inner Exception #0) System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'LITEWORLD'.
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl[T](Message message, ResultProcessor`1 processor, Object state, ServerEndPoint server)
   at StackExchange.Redis.RedisBase.ExecuteAsync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server)
   at Microsoft.AspNet.SignalR.Redis.RedisConnection.ScriptEvaluateAsync(Int32 database, String script, String key, Byte[] messageArguments)
   at Microsoft.AspNet.SignalR.Redis.RedisMessageBus.Send(Int32 streamIndex, IList`1 messages)
   at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.SendContext.InvokeSend()<---

SignalR.ScaleoutMessageBus Error: 0 : Stream(0) - Error has happened with the following exception: System.ObjectDisposedException: Cannot access a disposed object.
Object name: 'LITEWORLD'.
   at StackExchange.Redis.ConnectionMultiplexer.ExecuteAsyncImpl[T](Message message, ResultProcessor`1 processor, Object state, ServerEndPoint server)
   at StackExchange.Redis.RedisBase.ExecuteAsync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server)
   at Microsoft.AspNet.SignalR.Redis.RedisConnection.ScriptEvaluateAsync(Int32 database, String script, String key, Byte[] messageArguments)
   at Microsoft.AspNet.SignalR.Redis.RedisMessageBus.Send(Int32 streamIndex, IList`1 messages)
   at Microsoft.AspNet.SignalR.Messaging.ScaleoutStream.SendContext.InvokeSend().
SignalR.ScaleoutMessageBus Information: 0 : Stream(0) - Changed state from Open to Buffering
SignalR.RedisMessageBus Information: 0 : RedisMessageBus is being disposed
SignalR.ScaleoutMessageBus Information: 0 : Stream(0) - Changed state from Buffering to Closed

[anurse]

~Oof, that's a bit hard to read. Could you put it in a gist or something? Or maybe just put a plain text file somewhere?~ Don't worry actually, I can fix it in your comment (contributor powers GO!). For future reference, use the triple-tick syntax

Unfortunately, the backtick symbols in some of the generics are messing with Markdown :).

[anurse]

SignalR.RedisMessageBus Error: 0 : Unexpected state.

This line is suspicious. The new build doesn't even have that trace message anymore: https://github.com/SignalR/SignalR/blob/dev/src/Microsoft.AspNet.SignalR.Redis/RedisMessageBus.cs

Perhaps you aren't actually using the latest build? Verify that the "Product version" value in the properties for Microsoft.AspNet.SignalR.Redis.dll is 2.2.3-alpha1. If you can post a screenshot of the equivalent page for your Redis DLL that would help :)

[MisterAcoustic]

We run a number of different versions through testing - I hope I didn't make a mistake and give you output from a different branch. I've left work for the weekend, but I will double check everything on Monday. If there hadn't been anything strange, I would have been completely confident that I got the correct thing :).

I pasted the output in the same way I did the previous traces, so at least we do know that we got output that we didn't get before, due to the presence of the backticks. It also raises suspicion that perhaps somehow our build/deploy process isn't always delivering the correct .dlls (if, for example, this appears to be output from the previous candidate fix you sent).

I'm fairly sure that my local project will show the correct version - nuget completed successfully and didn't complain about anything when I installed the new version. More info on Monday.

[MisterAcoustic]

Redacting this comment :)

I didn't re-read your message, so I posted the SignalR Core.dll version (which is nearly the same as what you posted - build 1368). It turns out that my SignalR Redis.dll version is not the same at all. Nuget didn't get an update to this .dll when I last updated the packages.

[MisterAcoustic]

I picked up the latest this morning, and ensured that both the SignalR and Redis dlls were updated properly. Testing will begin shortly.

[MisterAcoustic]

@anurse So far, I have not seen the error in the testing scenario. That's good. However, I did just try to run this version of the software like a normal user in a browser, and I believe the current SignalR/Redis dlls are causing it not to work properly. As mentioned previously, the testing system doesn't use a browser to do the testing, even though it's a web app. Normally, a user runs a browser, and an interface is displayed while the database update process happens. The browser hangs when this version of the software is used. So, before we declare the current problem as fixed, I'll need to update again to see if the normal case actually works. We don't want to break everything else while fixing a fairly rare problem.

[anurse]

Hrm. Ok, I wasn't seeing any issues with basic scenarios but I wasn't able to thoroughly verify the fix. I'm going to set something up to try and reproduce what you're seeing.

Can you collect client and server side traces (https://docs.microsoft.com/en-us/aspnet/signalr/overview/testing-and-debugging/enabling-signalr-tracing) to get an idea of what might be happening when it hangs?

[MisterAcoustic]

I'm heading out today, but I'll take a look at the docs tomorrow and see what I can do.

[MisterAcoustic]

@anurse Good morning - you can ignore this problem. As I mentioned, I'm not a developer of the application itself. The javascript files have the version encoded in the name, and I had not updated any of the javascript code when I updated the packages. Bottom line, the requested js file didn't exist. This is also why it still works fine in the testing system, once again because there is no browser requesting the file.

[anurse]

I was trying this out again locally last night and had the same problem and wondered if it might be the cause of your issue :). It's easy to miss!

So to confirm, you are currently seeing the pre-release version working and as of yet have not seen the Redis issue reoccur? That's hopeful news :)

[MisterAcoustic]

@anurse Yes, so far, so good :). We definitely need to give it a while longer though, sometimes we wouldn't see the problem for two weeks. It's hard to know whether we've hit the same circumstances that previously would have caused the error. My confidence is starting to build though :)

[anurse]

Oh, totally agreed :). Just wanted to confirm where we're at right now. I have some other folks who are also seeing this issue and I'm working with them to get more eyes on the preview bits. Fingers crossed!

[tuyen-vuduc]

It might relate to this issue. I am calling to a DbContext inside a Hub method :(

Unhandled Exception: System.ObjectDisposedException: Cannot access a disposed object. A common cause of this error is disposing a context that was resolved from dependency injection and then later trying to use the same context instance elsewhere in your application. This may occur if you are calling Dispose() on the context, or wrapping the context in a using statement. If you are using dependency injection, you should let the dependency injection container take care of disposing context instances.
Object name: 'SampleDbContext'.
   at Microsoft.EntityFrameworkCore.DbContext.CheckDisposed()
   at Microsoft.EntityFrameworkCore.Internal.InternalDbSet`1.get_EntityType()
   at Microsoft.EntityFrameworkCore.Internal.InternalDbSet`1.get_EntityQueryable()
   at Microsoft.EntityFrameworkCore.Internal.InternalDbSet`1.System.Linq.IQueryable.get_Provider()
   at System.Linq.Queryable.Where[TSource](IQueryable`1 source, Expression`1 predicate)

[anurse]

That's not related to this issue, this issue relates to an ObjectDisposedException specifically coming from the Redis scaleout providers. I suggest asking on StackOverflow (as it's likely to be an issue with how you are disposing the DbContext). If it turns out to be a problem with SignalR itself, feel free to file a new issue here :)

[tuyen-vuduc]

I guess it is an issue with SignalR. The issue occur if I run multiple SQL queries inside a Task.Run then return the results. When I remove Task.Run, the exception is gone. I think there is something not right when handling tasks within Hub lifecycle.

[anurse]

Can you file a separate issue or ask on StackOverflow please? I don't want to confuse issues and whatever is happening in your example is definitely a different issue from the one discussed here.

[MisterAcoustic]

Update: I'm gaining confidence that the issue has indeed been addressed. Testing has been running hourly now for about nine days, with no occurrences of the problem. Doing the math, that represents over three thousand opportunities for the problem to appear, where previously we would see the issue about once in two to three hundred chances.

If the problem were present, we likely would have seen it ten times by now. I think it's fixed :)

[anurse]

Awesome! Thanks so much for your help @MisterAcoustic ! It's tough to get these hard-to-reproduce issues resolved and I appreciate your willingness to try all the various debugging steps we've put out :). Keep us posted if anything does come up!

[MisterAcoustic]

A final update: I am going to stop testing, both because I believe the problem is fixed, but also because other interested parties are getting tired of all the extra results in our test logging :).

I also wanted to mention that while it has been rare, we have seen the problem on our branches that are not using the new code. This means that neither having the SignalR tracing enabled, nor the constant testing of the modified branch have affected the appearance of the problem. It's still there in the old code, and we still haven't seen it in the new code.

Finally, you're welcome of course, for what little help I've been able to provide. But more importantly, Thank _You_ for taking up the issue and getting is resolved. I've never before had any response from Microsoft regarding any problem - it's a nice change.

[anurse]

Glad it's working out! We're going to try and get this fix fast-tracked into a release as soon as we can (even if the release is literally just this fix ;)).

[anurse]

This should now be resolved in the 2.2.3 release. Please comment further if you encounter this issue in the latest version!