[Bug] SteamClient in UDP mode

[JustArchi]

Noticed below crash from one of my ASF users:

29/03/2016 23:36:04 [!] EXCEPTION: UnhandledExceptionHandler() <Main> Unable to decrypt incoming packet
29/03/2016 23:36:06 [!] StackTrace:
   em SteamKit2.NetFilterEncryptionWithHMAC.ProcessIncoming(Byte[] data)
   em SteamKit2.UdpConnection.DispatchMessage()
   em SteamKit2.UdpConnection.ReceiveData(UdpPacket packet)
   em SteamKit2.UdpConnection.ReceivePacket(UdpPacket packet)
   em SteamKit2.UdpConnection.NetLoop()
   em System.Threading.ThreadHelper.ThreadStart_Context(Object state)
   em System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   em System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
   em System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   em System.Threading.ThreadHelper.ThreadStart()
29/03/2016 23:36:06 [!] EXCEPTION: UnhandledExceptionHandler() <Main> O comprimento dos dados a desencriptar é inválido (Translation: The length of the data to decrypt is invalid).
29/03/2016 23:36:06 [!] StackTrace:
   em System.Security.Cryptography.RijndaelManagedTransform.TransformFinalBlock(Byte[] inputBuffer, Int32 inputOffset, Int32 inputCount)
   em System.Security.Cryptography.CryptoStream.FlushFinalBlock()
   em System.Security.Cryptography.CryptoStream.Dispose(Boolean disposing)
   em System.IO.Stream.Close()
   em System.IO.Stream.Dispose()
   em SteamKit2.CryptoHelper.SymmetricDecrypt(Byte[] input, Byte[] key, Byte[]& iv)
   em SteamKit2.CryptoHelper.SymmetricDecryptHMACIV(Byte[] input, Byte[] key, Byte[] hmacSecret)
   em SteamKit2.NetFilterEncryptionWithHMAC.ProcessIncoming(Byte[] data)

(This is complete stacktrace, my logger logs exception and every inner exception recursively)

Crash is actually random, so it's probably because of network malfunctions, but can't say for sure.

As you can see from the stacktrace, this is the case only with SteamClient running in UDP protocol - #256

Let me know if you need DebugLog for this issue.

[Netshroud]

I tried to reproduce by changing Sample7_ServerList to use UDP (edit line 41) and it logs in as expected, no crash.

It may simply be that UdpConnection doesn't handle exceptions as gracefully as TcpConnection.

We catch SocketException in UdpConnection.NetLoop on line 407, but don't handle IOException or others.

@azuisleet?

[JustArchi]

Possible, as I noted, this exception is random, probably because of network malfunctions, so reproducing it can be quite difficult as well.

[JustArchi]

If you need to reproduce the bug, it should be enough to launch Steam, then launch a bot based on SK2 on the same machine in UDP mode (remember to set my newly introduced LoginID to something custom, so you won't get a session replace), then start any Valve game using UDP protocol such as CS:GO, Dota 2 or TF. Crash should come up soon.

[Revadike]

Is this similar to this issue I am having? If not, I'll make a separate issue thread and tell you all about the details.

[JustArchi]

Got new one from SK 2.0.

2017-12-17 01:07:17|ArchiSteamFarm-10483|FATAL|ASF|OnUnhandledException() System.NullReferenceException: Object reference not set to an instance of an object.
at SteamKit2.EnvelopeEncryptedConnection.OnNetMsgReceived(Object sender, NetMsgEventArgs e)
at SteamKit2.UdpConnection.DispatchMessage()
at SteamKit2.UdpConnection.ReceiveData(UdpPacket packet)
at SteamKit2.UdpConnection.ReceivePacket(UdpPacket packet)
at SteamKit2.UdpConnection.NetLoop(Object param)
at System.Threading.Thread.ThreadMain_ParameterizedThreadStart(Object parameter)
at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)

I wonder how this was possible. Stacktrace is very similar, I'm quite sure this is the same issue, just now reproduced on SK 2.0.

https://github.com/SteamRE/SteamKit/blob/master/SteamKit2/SteamKit2/Networking/Steam3/EnvelopeEncryptedConnection.cs#L69

Perhaps e.Data is null? I don't see other possibility for NRE there, and it'd match initial old stacktrace.

[yaakov-h]

Could be something that was inlined, as well.

Can you reproduce this on a platform that gives you line numbers from the PDBs?

[JustArchi]

I couldn't run into this bug myself under any circumstance, everything I forwarded here was users running into it, ref.

I've compiled latest SK2 in Release mode and I'll try to get more info from the PDBs from the user, but without guarantees if he wants to help 🙂. Just replacing SteamKit2.dll in published app and adding .pdb file next to it should do, right? It worked for me, just making sure 🙂.

Debug.zip

[yaakov-h]

I believe so.

[JustArchi]

I'm quite sure the issue here is with e.Data being null, this would also match original stacktrace we got from pre-SK2.0 times. I'll make sure to confirm this with appropriate log once we get one from the user.

At least this time I can be sure it's not just some Mono bug 😄

[yaakov-h]

I don't think that can be null, and I did also do a by-hand audit of the codebase for nullability for SK 2.0. I may have missed something though, but I don't think it's e.Data.

SteamKit/SteamKit2/SteamKit2/Networking/Steam3/UdpConnection.cs

Line 345 in 49e857b

byte[] data = payload.ToArray();

[yaakov-h]

Do you have DebugLog output?

CMClient.GetPacketMsg can return null, which would have us promptly crash here in that case.

[JustArchi]

Sadly getting code line numbers turned out to be too hard (looks like self-contained apps have serious issues with portable PDB files, and even more problems with full ones, and we can't really install SDK there to run generic app).

But of course I got debug log, perhaps it'll help. I included output from last 5 seconds before crash.

2017-12-18 21:29:08|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | Sequenced packet resend required
2017-12-18 21:29:08|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | Sent -> Data Seq 9 Ack 17; 48 bytes; Message: 48 bytes 1 packets
2017-12-18 21:29:08|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | Sent -> Data Seq 10 Ack 17; 80 bytes; Message: 80 bytes 1 packets
2017-12-18 21:29:08|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | Sent -> Data Seq 11 Ack 17; 48 bytes; Message: 48 bytes 1 packets
2017-12-18 21:29:09|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | Sent -> Data Seq 12 Ack 17; 80 bytes; Message: 80 bytes 1 packets
2017-12-18 21:29:09|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | Sent -> Data Seq 13 Ack 17; 48 bytes; Message: 48 bytes 1 packets
2017-12-18 21:29:10|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | <- Recv'd Data Seq 13 Ack 9; 160 bytes; Message: 160 bytes 1 packets
2017-12-18 21:29:10|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | <- Recv'd Data Seq 27 Ack 15; 176 bytes; Message: 176 bytes 1 packets
2017-12-18 21:29:10|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | Sequenced packet resend required
2017-12-18 21:29:10|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | Sent -> Disconnect Seq 10 Ack 13; 0 bytes; Message: 0 bytes 1 packets
2017-12-18 21:29:10|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | <- Recv'd Data Seq 28 Ack 15; 96 bytes; Message: 96 bytes 1 packets
2017-12-18 21:29:10|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | Dispatching message; 96 bytes
2017-12-18 21:29:10|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() CMClient | <- Recv'd EMsg: Multi (1) (Proto: True)
2017-12-18 21:29:10|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() CMClient | <- Recv'd EMsg: ClientClanState (822) (Proto: True)
2017-12-18 21:29:10|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | Sequenced packet resend required
2017-12-18 21:29:10|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | Sent -> Data Seq 16 Ack 28; 48 bytes; Message: 48 bytes 1 packets
2017-12-18 21:29:10|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | Sent -> Data Seq 17 Ack 28; 48 bytes; Message: 48 bytes 1 packets
2017-12-18 21:29:10|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | Sent -> Data Seq 18 Ack 28; 48 bytes; Message: 48 bytes 1 packets
2017-12-18 21:29:11|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | <- Recv'd Data Seq 14 Ack 9; 96 bytes; Message: 96 bytes 1 packets
2017-12-18 21:29:11|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() UdpConnection | Dispatching message; 96 bytes
2017-12-18 21:29:11|ArchiSteamFarm-27083|DEBUG|ASF|WriteLine() CMClient | Exception deserializing emsg 1740662045 (True).
System.ArgumentOutOfRangeException: Non-negative number required.
Parameter name: count
   at System.IO.BinaryReader.ReadBytes(Int32 count)
   at SteamKit2.Internal.MsgHdrProtoBuf.Deserialize(Stream stream)
   at SteamKit2.PacketClientMsgProtobuf..ctor(EMsg eMsg, Byte[] data)
   at SteamKit2.Internal.CMClient.GetPacketMsg(Byte[] data)
2017-12-18 21:29:11|ArchiSteamFarm-27083|FATAL|ASF|OnUnhandledException() System.NullReferenceException: Object reference not set to an instance of an object.
   at SteamKit2.EnvelopeEncryptedConnection.OnNetMsgReceived(Object sender, NetMsgEventArgs e)
   at SteamKit2.UdpConnection.DispatchMessage()
   at SteamKit2.UdpConnection.ReceiveData(UdpPacket packet)
   at SteamKit2.UdpConnection.ReceivePacket(UdpPacket packet)
   at SteamKit2.UdpConnection.NetLoop(Object param)
   at System.Threading.Thread.ThreadMain_ParameterizedThreadStart(Object parameter)
   at System.Threading.ThreadHelper.ThreadStart_Context(Object state)
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)

I can't guarantee if everything is related though, ASF uses several steam clients there.

[yaakov-h]

Looks like it's CMClient.GetPacketMsg then 😄