Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

alpha7 websocket issues #436

Closed
JustArchi opened this issue Aug 30, 2017 · 8 comments
Closed

alpha7 websocket issues #436

JustArchi opened this issue Aug 30, 2017 · 8 comments
Labels
bug
Milestone
2.0.0

Comments

@JustArchi
Copy link
Contributor

JustArchi commented Aug 30, 2017 •
edited
Loading

Unique ones:

2017-08-29 20:11:21|dotnet-5404|FATAL|ASF|OnUnobservedTaskException() System.AggregateException: A Task's exception(s) were not observed either by Waiting on the Task or accessing its Exception property. As a result, the unobserved exception was rethrown by the finalizer thread. (The remote party closed the WebSocket connection without completing the close handshake.) ---> System.Net.WebSockets.WebSocketException: The remote party closed the WebSocket connection without completing the close handshake. ---> System.IO.IOException: Unable to transfer data on the transport connection: Broken pipe. ---> System.Net.Sockets.SocketException: Broken pipe
   --- End of inner exception stack trace ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Net.Security.SslStreamInternal.StartWriting(Byte[] buffer, Int32 offset, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslStreamInternal.ProcessWrite(Byte[] buffer, Int32 offset, Int32 count, LazyAsyncResult asyncResult)
   at System.Net.Security.SslStream.BeginWrite(Byte[] buffer, Int32 offset, Int32 count, AsyncCallback asyncCallback, Object asyncState)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncTrim[TInstance,TArgs](TInstance thisRef, TArgs args, Func`5 beginMethod, Func`3 endMethod)
   at System.IO.Stream.BeginEndWriteAsync(Byte[] buffer, Int32 offset, Int32 count)
   at System.IO.Stream.WriteAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
   at System.Net.WebSockets.ManagedWebSocket.SendFrameLockAcquiredNonCancelableAsync(MessageOpcode opcode, Boolean endOfMessage, ArraySegment`1 payloadBuffer)
   --- End of inner exception stack trace ---
   --- End of inner exception stack trace ---
---> (Inner Exception #0) System.Net.WebSockets.WebSocketException (0x80004005): The remote party closed the WebSocket connection without completing the close handshake. ---> System.IO.IOException: Unable to transfer data on the transport connection: Broken pipe. ---> System.Net.Sockets.SocketException: Broken pipe
   --- End of inner exception stack trace ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Net.Security.SslStreamInternal.StartWriting(Byte[] buffer, Int32 offset, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security.SslStreamInternal.ProcessWrite(Byte[] buffer, Int32 offset, Int32 count, LazyAsyncResult asyncResult)
   at System.Net.Security.SslStream.BeginWrite(Byte[] buffer, Int32 offset, Int32 count, AsyncCallback asyncCallback, Object asyncState)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncTrim[TInstance,TArgs](TInstance thisRef, TArgs args, Func`5 beginMethod, Func`3 endMethod)
   at System.IO.Stream.BeginEndWriteAsync(Byte[] buffer, Int32 offset, Int32 count)
   at System.IO.Stream.WriteAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
   at System.Net.WebSockets.ManagedWebSocket.SendFrameLockAcquiredNonCancelableAsync(MessageOpcode opcode, Boolean endOfMessage, ArraySegment`1 payloadBuffer)<---

2017-08-29 20:11:21|dotnet-5404|FATAL|ASF|OnUnobservedTaskException() System.AggregateException: A Task's exception(s) were not observed either by Waiting on the Task or accessing its Exception property. As a result, the unobserved exception was rethrown by the finalizer thread. (Destination array is not long enough to copy all the items in the collection. Check array index and length.
Parameter name: value) ---> System.ArgumentException: Destination array is not long enough to copy all the items in the collection. Check array index and length.
Parameter name: value
   at System.ThrowHelper.ThrowArgumentException(ExceptionResource resource, ExceptionArgument argument)
   at System.BitConverter.ReadInt32(Byte[] value, Int32 startIndex)
   at SteamKit2.Internal.CMClient.GetPacketMsg(Byte[] data)
   at SteamKit2.Internal.CMClient.NetMsgReceived(Object sender, NetMsgEventArgs e)
   at SteamKit2.WebSocketConnection.WebSocketContext.<RunCore>d__11.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at SteamKit2.WebSocketConnection.WebSocketContext.Dispose()
   at SteamKit2.WebSocketConnection.DisconnectCore(Boolean userInitiated, WebSocketContext specificContext)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
   --- End of inner exception stack trace ---
---> (Inner Exception #0) System.ArgumentException: Destination array is not long enough to copy all the items in the collection. Check array index and length.
Parameter name: value
   at System.ThrowHelper.ThrowArgumentException(ExceptionResource resource, ExceptionArgument argument)
   at System.BitConverter.ReadInt32(Byte[] value, Int32 startIndex)
   at SteamKit2.Internal.CMClient.GetPacketMsg(Byte[] data)
   at SteamKit2.Internal.CMClient.NetMsgReceived(Object sender, NetMsgEventArgs e)
   at SteamKit2.WebSocketConnection.WebSocketContext.<RunCore>d__11.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at SteamKit2.WebSocketConnection.WebSocketContext.Dispose()
   at SteamKit2.WebSocketConnection.DisconnectCore(Boolean userInitiated, WebSocketContext specificContext)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)<---

Extra notes - seems like triggered exclusively by Steam maintenance this time.

Full log (dirty): https://gist.githubusercontent.com/GUiHKX/6c82462161895a699e0a7744b822a76e/raw/592687b3c1dc7c65c208b3c4a93e982cfe885e6a/log.txt

Original issue: JustArchiNET/ArchiSteamFarm#612 (comment)
@ObsidianMinor
Copy link

Sounds like Steam just doesn't care about formally closing connections to go down for maintenance.

@yaakov-h
Copy link
Member

First one is strange, I'll have to dig in a bit deeper. I'm pretty sure we're not leaving tasks unobserved.

Second one I'll have to add more logging around to see what's going on.

@JustArchi
Copy link
Contributor Author

Two more to the collection:

2017-08-30 22:59:06|dotnet-7144|FATAL|ASF|OnUnobservedTaskException() System.AggregateException: A Task's exception(s) were not observed either by Waiting on the Task or accessing its Exception property. As a result, the unobserved exception was rethrown by the finalizer thread. (There is already one outstanding 'ReceiveAsync' call for this WebSocket instance. ReceiveAsync and SendAsync can be called simultaneously, but at most one outstanding operation for each of them is allowed at the same time.) ---> System.InvalidOperationException: There is already one outstanding 'ReceiveAsync' call for this WebSocket instance. ReceiveAsync and SendAsync can be called simultaneously, but at most one outstanding operation for each of them is allowed at the same time.
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
   at System.Net.WebSockets.WinHttpWebSocket.<ReceiveAsync>d__27.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at SteamKit2.WebSocketConnection.WebSocketContext.<ReadMessageAsync>d__14.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at SteamKit2.WebSocketConnection.WebSocketContext.<RunCore>d__11.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at SteamKit2.WebSocketConnection.WebSocketContext.Dispose()
   at SteamKit2.WebSocketConnection.DisconnectCore(Boolean userInitiated, WebSocketContext specificContext)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
   --- End of inner exception stack trace ---
---> (Inner Exception #0) System.InvalidOperationException: There is already one outstanding 'ReceiveAsync' call for this WebSocket instance. ReceiveAsync and SendAsync can be called simultaneously, but at most one outstanding operation for each of them is allowed at the same time.
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1.ConfiguredTaskAwaiter.GetResult()
   at System.Net.WebSockets.WinHttpWebSocket.<ReceiveAsync>d__27.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at SteamKit2.WebSocketConnection.WebSocketContext.<ReadMessageAsync>d__14.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at SteamKit2.WebSocketConnection.WebSocketContext.<RunCore>d__11.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at SteamKit2.WebSocketConnection.WebSocketContext.Dispose()
   at SteamKit2.WebSocketConnection.DisconnectCore(Boolean userInitiated, WebSocketContext specificContext)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)<---

2017-08-31 00:33:41|dotnet-7144|FATAL|ASF|OnUnobservedTaskException() System.AggregateException: A Task's exception(s) were not observed either by Waiting on the Task or accessing its Exception property. As a result, the unobserved exception was rethrown by the finalizer thread. (The timeout of the operation has been reached) ---> System.Net.Http.WinHttpException: The timeout of the operation has been reached
   at System.Net.WebSockets.WinHttpWebSocket.InternalCloseAsync(WebSocketCloseStatus closeStatus, String statusDescription)
   at System.Net.WebSockets.WinHttpWebSocket.<CloseAsync>d__30.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at SteamKit2.WebSocketConnection.WebSocketContext.<RunCore>d__11.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at SteamKit2.WebSocketConnection.WebSocketContext.Dispose()
   at SteamKit2.WebSocketConnection.DisconnectCore(Boolean userInitiated, WebSocketContext specificContext)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)
   --- End of inner exception stack trace ---
---> (Inner Exception #0) System.Net.Http.WinHttpException (0x80072EE2): O tempo limite da operação foi atingido
   at System.Net.WebSockets.WinHttpWebSocket.InternalCloseAsync(WebSocketCloseStatus closeStatus, String statusDescription)
   at System.Net.WebSockets.WinHttpWebSocket.<CloseAsync>d__30.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at SteamKit2.WebSocketConnection.WebSocketContext.<RunCore>d__11.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at SteamKit2.WebSocketConnection.WebSocketContext.Dispose()
   at SteamKit2.WebSocketConnection.DisconnectCore(Boolean userInitiated, WebSocketContext specificContext)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot)<---

Full log (dirty): https://gist.githubusercontent.com/GUiHKX/1f600e14f6c4826af38e34efe58b618d/raw/49e69d41357ca8ea28cec3dcf4c62beae7b351c2/log.txt

Original issue: JustArchiNET/ArchiSteamFarm#612 (comment)

@yaakov-h yaakov-h added the bug label Sep 3, 2017
@yaakov-h yaakov-h added this to the 2.0.0 milestone Sep 3, 2017
@yaakov-h
Copy link
Member

yaakov-h commented Sep 3, 2017

OK, I've done some more digging.

The unobserved task exception appears to be from calling DisconnectNonBlocking. This uses Task.Run to get off the current thread, but doesn't observe the task.

I cannot for the life of me figure out how you landed up with There is already one outstanding 'ReceiveAsync' call for this WebSocket instance.. Only one thread can call WebSocketContext.Start, which is the only caller of RunCore, which is the only caller of ReadMessageAsync, which is the only caller of WebSocketConnection.ReceiveAsync.

The WinHttpException in another language is CloseAsync throwing a Win32Exception subclass because it somehow timed out.

yaakov-h added a commit that referenced this issue Sep 3, 2017
@yaakov-h
Handle Win32Exception when closing ws connection
676ce74 
Issue #436
yaakov-h added a commit that referenced this issue Sep 3, 2017
@yaakov-h
Log unobserved exception when ws disconnect throws
8dfc6b9 
Issue #436
@JustArchi
Copy link
Contributor Author

I cannot for the life of me figure out how you landed up with There is already one outstanding 'ReceiveAsync' call for this WebSocket instance.. Only one thread can call WebSocketContext.Start, which is the only caller of RunCore, which is the only caller of ReadMessageAsync, which is the only caller of WebSocketConnection.ReceiveAsync.

The only thing that comes to my mind is two SteamClients being in conflict when they happen to connect to exactly the same server and port, but this doesn't really make sense, does it? Every connection has its own local port and communication, so they should not interfere.

Sadly I'm not much of use here, I'm simply forwarding issues I find SK2-related, but due to the nature of those networking hiccups it's hard to make reproducible case that could explain majority of them. It's still awesome to hear that you're keeping up with all of this 💓.

@yaakov-h
Copy link
Member

yaakov-h commented Sep 3, 2017

I'm out of town at the moment but I'll try and stress-test two possible conditions when I get back home:

  1. TCP connection forcibly closed
  2. Packets go nowhere (network blackholed, IP down, firewall etc.)

@JustArchi
Copy link
Contributor Author

Don't worry, you've already did awesome job at fixing nearly everything and we're not in any hurry.

The only thing I'm actually happy about is the fact that I'm not reporting this under any sort of Mono runtime. We both know how good it is to trust runtime to not have major bugs 😆.

@yaakov-h
Copy link
Member

yaakov-h commented Sep 6, 2017

I'll close this for now because the above handling and logging should hopefully fix this, if you see something strange then keep opening issues 😅

@yaakov-h yaakov-h closed this as completed Sep 6, 2017
@JustArchi JustArchi mentioned this issue Sep 13, 2017
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
2.0.0
Development

No branches or pull requests
3 participants
@yaakov-h @JustArchi @ObsidianMinor