Connection state is not changed to Open from Connecting

[sharok]

Hello. I see a lot of exceptions in my log files and they are pretty the same:

System.OperationCanceledException: The operation was canceled.
   at System.Collections.Concurrent.BlockingCollection`1.TryTakeWithNoTimeValidation(T& item, Int32 millisecondsTimeout, CancellationToken cancellationToken, CancellationTokenSource combinedTokenSource)
   at System.Collections.Concurrent.BlockingCollection`1.TryTake(T& item, Int32 millisecondsTimeout, CancellationToken cancellationToken)
   at System.Collections.Concurrent.BlockingCollection`1.Take(CancellationToken cancellationToken)
   at PureWebSockets.PureWebSocket.<StartSender>b__59_0()

Why does it happen?

But, it's not a big problem. Recconection strategy usually handles it. BUT, not always, the library is stuck in Connecting state:

2019-07-12 08:03:48.762 -04:00 [ERR] Stocks WS error
System.OperationCanceledException: The operation was canceled.
   at System.Collections.Concurrent.BlockingCollection`1.TryTakeWithNoTimeValidation(T& item, Int32 millisecondsTimeout, CancellationToken cancellationToken, CancellationTokenSource combinedTokenSource)
   at System.Collections.Concurrent.BlockingCollection`1.TryTake(T& item, Int32 millisecondsTimeout, CancellationToken cancellationToken)
   at System.Collections.Concurrent.BlockingCollection`1.Take(CancellationToken cancellationToken)
   at PureWebSockets.PureWebSocket.<StartSender>b__59_0()
2019-07-12 08:03:48.763 -04:00 [INF] Stocks state: Aborted => Connecting
2019-07-12 08:03:48.966 -04:00 [INF] Stocks state: Connecting => Open
2019-07-12 09:30:10.254 -04:00 [ERR] 
System.OperationCanceledException: The operation was canceled.
   at System.Collections.Concurrent.BlockingCollection`1.TryTakeWithNoTimeValidation(T& item, Int32 millisecondsTimeout, CancellationToken cancellationToken, CancellationTokenSource combinedTokenSource)
   at System.Collections.Concurrent.BlockingCollection`1.TryTake(T& item, Int32 millisecondsTimeout, CancellationToken cancellationToken)
   at System.Collections.Concurrent.BlockingCollection`1.Take(CancellationToken cancellationToken)
   at PureWebSockets.PureWebSocket.<StartSender>b__59_0()
2019-07-12 09:30:10.254 -04:00 [ERR] Stocks WS error
System.OperationCanceledException: The operation was canceled.
   at System.Collections.Concurrent.BlockingCollection`1.TryTakeWithNoTimeValidation(T& item, Int32 millisecondsTimeout, CancellationToken cancellationToken, CancellationTokenSource combinedTokenSource)
   at System.Collections.Concurrent.BlockingCollection`1.TryTake(T& item, Int32 millisecondsTimeout, CancellationToken cancellationToken)
   at System.Collections.Concurrent.BlockingCollection`1.Take(CancellationToken cancellationToken)
   at PureWebSockets.PureWebSocket.<StartSender>b__59_0()
2019-07-12 09:30:10.255 -04:00 [INF] Stocks state: Aborted => Connecting

As you can see in the logs above, there was error and the library reconnected Aborted => Connecting => Open, but sometimes the library just change state to Connecting and that's it. There is no any messages/errors after that.

PS. I use standard reconection strategy:
new ReconnectStrategy(2000, 4000)

[ByronAP]

interesting do you have a reproduction case?

[sharok]

Unfortunately, no. I have no idea why it's happening. It's completely random and happens one-two times per week.

…

On Mon, Jul 15, 2019, 22:31 Allen Byron Penner ***@***.***> wrote: interesting do you have a reproduction case? — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#21?email_source=notifications&email_token=ACTEAILXOJ2NKSM54J7FC6LP7SQ63A5CNFSM4IDS64TKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGODZ6HVQY#issuecomment-511474371>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ACTEAINMSMLU5MEYAOZ5HRLP7SQ63ANCNFSM4IDS64TA> .

[sharok]

Some additional info. I am trying to reproduce this error, Looks like it impossible, because I cannot create the state when it happens. But I have some additional logs:
Logs when the lib is trying to recconect. Everything looks fine:

2019-08-21T14:29:23.9764001+06:00 PureWebSocket.DoReconnect: Attempting connect.
2019-08-21T14:29:23.9763990+06:00 PureWebSocket.DoReconnect: Creating new websocket.
2019-08-21T14:29:23.9854182+06:00 PureWebSocket.DoReconnect: Processing reconnect strategy.
2019-08-21T14:29:23.9854102+06:00 PureWebSocket.DoReconnect: Reconnect threw an error: One or more errors occurred. (Unable to connect to the remote server
).
2019-08-21T14:29:23.9859100+06:00 PureWebSocket.DoReconnect: Disposing of current websocket.
2019-08-21T14:29:27.9865187+06:00 PureWebSocket.DoReconnect: Creating new websocket.

When everything goes fine then I see the following in the log:

2019-08-21T14:32:25.0055161+06:00 PureWebSocket.StartListener: Message fully received: [{"ev":"status","status":"connected","message":"Connected Successful
ly"}]
2019-08-21T14:32:25.1185750+06:00 PureWebSocket.StartMonitor: State changed from Connecting to Open.
2019-08-21T14:32:25.1222041+06:00 PureWebSocket.Send: Adding item to send queue: Data {"action":"auth","params":"XXXX"}

As you can see there is connected message and after that you can see that state was changed.

But, below you can see the case when the lib could reconnect but the state didn't change:

2019-08-21T14:36:23.5432752+06:00 PureWebSocket.DoReconnect: Connect result: True
2019-08-21T14:36:23.5432957+06:00 PureWebSocket.DoReconnect: Reconnect success, restarting tasks.
2019-08-21T14:36:23.5907397+06:00 PureWebSocket.StartListener: Entering listener loop.
2019-08-21T14:36:23.5433358+06:00 PureWebSocket.StartListener: Starting listener.
2019-08-21T14:36:23.5434243+06:00 PureWebSocket.StartSender: Starting sender.
2019-08-21T14:36:23.6139690+06:00 PureWebSocket.StartListener: Message fully received: [{"ev":"status","status":"connected","message":"Connected Successful
ly"}]
2019-08-21T14:36:23.5435446+06:00 PureWebSocket.StartSender: Entering sender loop.

So, we can see connected message. But state has not been changed and no any logs after that.

[ByronAP]

good work thank that gives me some good places to look