search

SteamRE / SteamKit

SteamKit2 is a .NET library designed to interoperate with Valve's Steam network. It aims to provide a simple, yet extensible, interface to perform various actions on the network.
GNU Lesser General Public License v2.1
2.62k stars 497 forks source link

SteamClient.Connect() does nothing sometimes #528

Closed shravan2x closed 6 years ago

shravan2x commented 6 years ago

I have this code that's called when the SteamClient is disoconnected:

private async void OnDisconnected(SteamClient.DisconnectedCallback callback)
{
    IsLoggedOn = false;

    Log.Warn("Disconnected from Steam. Reconnecting in 5s ...");
    await Task.Delay(5000);
    SteamClient.Connect();
}

I have handlers set up for SteamClient.ConnectedCallback and SteamClient.DisconnectedCallback. Usually, when a disconnection occurs, one of these two is called and is handled appropriately. But very rarely (roughly once every few weeks), I see a case where nothing happens after Connect() is called:

[2018/03/12 22:10:36.801 Xenon.Bot.SteamBot] WARN: Disconnected from Steam. Reconnecting in 5s ...
[2018/03/12 22:10:46.811 Xenon.Bot.SteamBot] WARN: Disconnected from Steam. Reconnecting in 5s ...
// nothing happens after this - connect or disconnect

The bot does not complete authentication, and does not log into Steam at all. It just hangs in this intermediate state.

This is all on the latest 2.0.0 release for .NET Core. Any ideas why? Is this an issue with SK2 or Steam itself?

Background: I've been using this code for years without issues, so I'm fairly confident it isn't a change on my end that caused it.

UPDATE: Calling SteamUser.LogOff(); when it has stalled like this results in a long wait of about 2m30s and then another SteamClient.DisconnectedCallback is called.

azuisleet commented 6 years ago

This likely needs more info from DebugLog for TcpConnection. There shouldn't be any path that doesn't return one of those two callbacks. Perhaps SteamDirectory is taking an unusual amount of time? It looks like WebAPI calls time out by default after 100 seconds.

shravan2x commented 6 years ago

Could you tell me how I'd go about grabbing those DebugLogs?

azuisleet commented 6 years ago

You would call DebugLog.AddListener and redirect the TcpConnection group (and any others of interest) to whatever logging you have currently.

shravan2x commented 6 years ago

Okay, I tried adding DebugLogging for CMClient and TcpConnection, but CMClient generates too much output, so I'll stick to TcpConnection. It's pretty rare; I'll just update this thread when I see it again.

On another note, I noticed this exception thrown on shutdown:

[2018/03/13 00:06:47.271 Xenon.Bot.SteamBot] DEBUG: Sk2DebugLog (TcpConnection: Socket exception occurred while reading packet: System.IO.IOException: Connection lost while reading packet header. ---> System.IO.EndOfStreamException: Unable to read beyond the end of the stream.
   at System.IO.__Error.EndOfFile()
   at System.IO.BinaryReader.FillBuffer(Int32 numBytes)
   at System.IO.BinaryReader.ReadUInt32()
   at SteamKit2.TcpConnection.ReadPacket()
   --- End of inner exception stack trace ---
   at SteamKit2.TcpConnection.ReadPacket()
   at SteamKit2.TcpConnection.NetLoop())
[2018/03/13 00:06:47.282 Xenon.Bot.SteamBot] INFO: Disconnected from Steam.

Just letting you know.

yaakov-h commented 6 years ago

Closing due to inactivity.

Feel free to re-open if and when you have more information.

stanriders commented 5 years ago

I have the same issue, SteamKit2 fails right after connecting to the server. DebugLog:

[2018-12-04 11:05:43,224][DEBUG] ServerList: Server list provider had no entries, will query SteamDirectory
[2018-12-04 11:05:43,766][DEBUG] ServerList: Resolved 200 servers
[2018-12-04 11:05:43,778][DEBUG] ServerList: Next server candidiate: 162.254.197.40:27018 (Tcp)
[2018-12-04 11:05:43,780][DEBUG] TcpConnection: Connecting to 162.254.197.40:27018...
[2018-12-04 11:05:43,843][DEBUG] TcpConnection: Connected to 162.254.197.40:27018
[2018-12-04 11:05:43,919][DEBUG] EnvelopeEncryptedConnection: Got encryption request. Universe: Public Protocol ver: 1
[2018-12-04 11:05:43,997][DEBUG] EnvelopeEncryptedConnection: Encryption result: OK
[2018-12-04 11:05:44,074][DEBUG] CMClient: Sent -> EMsg: ClientLogon (Proto: True)
[2018-12-04 11:05:44,641][DEBUG] CMClient: <- Recv'd EMsg: Multi (1) (Proto: True)
[2018-12-04 11:05:44,648][DEBUG] CMClient: <- Recv'd EMsg: ClientServersAvailable (5501) (Proto: True)
[2018-12-04 11:05:44,650][DEBUG] CMClient: <- Recv'd EMsg: ClientServersAvailable (5501) (Proto: True)
[2018-12-04 11:05:44,650][DEBUG] CMClient: <- Recv'd EMsg: ClientLogOnResponse (751) (Proto: True)
[2018-12-04 11:05:44,663][DEBUG] CMClient: Sent -> EMsg: ClientHeartBeat (Proto: True)
[2018-12-04 11:05:44,665][DEBUG] CMClient: <- Recv'd EMsg: ClientAccountInfo (768) (Proto: True)
[2018-12-04 11:05:44,669][DEBUG] CMClient: <- Recv'd EMsg: ClientAccountInfo (768) (Proto: True)
[2018-12-04 11:05:44,670][DEBUG] CMClient: <- Recv'd EMsg: ClientEmailAddrInfo (5456) (Proto: True)
[2018-12-04 11:05:44,670][DEBUG] CMClient: <- Recv'd EMsg: ClientFriendsList (767) (Proto: True)
[2018-12-04 11:05:44,678][DEBUG] CMClient: Sent -> EMsg: ClientRequestFriendData (Proto: True)
[2018-12-04 11:05:44,682][DEBUG] CMClient: <- Recv'd EMsg: ClientPlayerNicknameList (5587) (Proto: True)
[2018-12-04 11:05:44,683][DEBUG] CMClient: <- Recv'd EMsg: ClientLicenseList (780) (Proto: True)
[2018-12-04 11:05:44,693][DEBUG] CMClient: <- Recv'd EMsg: ClientUpdateGuestPassesList (798) (Proto: False)
[2018-12-04 11:05:44,695][DEBUG] CMClient: <- Recv'd EMsg: ClientWalletInfoUpdate (5528) (Proto: True)
[2018-12-04 11:05:44,699][DEBUG] CMClient: <- Recv'd EMsg: ClientGameConnectTokens (779) (Proto: True)
[2018-12-04 11:05:44,703][DEBUG] CMClient: <- Recv'd EMsg: ClientSessionToken (850) (Proto: True)
[2018-12-04 11:05:44,705][DEBUG] CMClient: <- Recv'd EMsg: ClientIsLimitedAccount (5430) (Proto: True)
[2018-12-04 11:05:44,705][DEBUG] CMClient: <- Recv'd EMsg: ClientCMList (783) (Proto: True)
[2018-12-04 11:05:44,717][DEBUG] CMClient: <- Recv'd EMsg: ClientRequestedClientStats (5480) (Proto: True)
[2018-12-04 11:05:44,718][DEBUG] CMClient: <- Recv'd EMsg: ClientServerList (880) (Proto: True)
[2018-12-04 11:05:44,734][DEBUG] CMClient: <- Recv'd EMsg: ClientConcurrentSessionsBase (9600) (Proto: True)
[2018-12-04 11:05:44,734][DEBUG] CMClient: <- Recv'd EMsg: ClientVACBanStatus (782) (Proto: False)
[2018-12-04 11:05:44,736][DEBUG] CMClient: <- Recv'd EMsg: ClientUpdateMachineAuth (5537) (Proto: True)
[2018-12-04 11:05:44,748][DEBUG] CMClient: Sent -> EMsg: ClientAppUsageEvent (Proto: False)
[2018-12-04 11:05:44,752][DEBUG] CMClient: Sent -> EMsg: ClientRichPresenceUpload (Proto: True)
[2018-12-04 11:05:44,758][DEBUG] CMClient: Sent -> EMsg: ClientGamesPlayedWithDataBlob (Proto: True)
[2018-12-04 11:05:44,787][DEBUG] CMClient: Sent -> EMsg: ClientToGC (Proto: True)
[2018-12-04 11:05:44,789][DEBUG] CMClient: Sent -> EMsg: ClientToGC (Proto: True)
[2018-12-04 11:05:44,893][DEBUG] CMClient: <- Recv'd EMsg: Multi (1) (Proto: True)
[2018-12-04 11:05:44,893][DEBUG] CMClient: <- Recv'd EMsg: ClientServersAvailable (5501) (Proto: True)
[2018-12-04 11:05:44,895][DEBUG] CMClient: <- Recv'd EMsg: ClientFriendsGroupsList (5553) (Proto: True)
[2018-12-04 11:05:45,037][DEBUG] CMClient: <- Recv'd EMsg: Multi (1) (Proto: True)
[2018-12-04 11:05:45,037][DEBUG] CMClient: <- Recv'd EMsg: ClientPersonaState (766) (Proto: True)
[2018-12-04 11:05:45,086][DEBUG] CMClient: <- Recv'd EMsg: Multi (1) (Proto: True)
[2018-12-04 11:05:45,086][DEBUG] CMClient: <- Recv'd EMsg: ServiceMethod (146) (Proto: True)
[2018-12-04 11:05:45,594][DEBUG] CMClient: <- Recv'd EMsg: Multi (1) (Proto: True)
[2018-12-04 11:05:45,594][DEBUG] CMClient: <- Recv'd EMsg: ClientServiceCall (831) (Proto: True)
[2018-12-04 11:05:45,670][DEBUG] CMClient: <- Recv'd EMsg: Multi (1) (Proto: True)
[2018-12-04 11:05:45,670][DEBUG] CMClient: <- Recv'd EMsg: ClientNewLoginKey (5463) (Proto: True)
[2018-12-04 11:05:45,672][DEBUG] CMClient: <- Recv'd EMsg: ClientLoggedOff (757) (Proto: True)
[2018-12-04 11:05:45,674][DEBUG] TcpConnection: Socket exception occurred while reading packet: System.IO.IOException: Connection lost while reading packet header. ---> System.IO.EndOfStreamException: Unable to read beyond the end of the stream.
  at System.IO.BinaryReader.FillBuffer (System.Int32 numBytes) [0x0007a] in <3833a6edf2074b959d3dab898627f0ac>:0 
  at System.IO.BinaryReader.ReadUInt32 () [0x00000] in <3833a6edf2074b959d3dab898627f0ac>:0 
  at SteamKit2.TcpConnection.ReadPacket () [0x00004] in <76ca85500f404320adcb89e6491c714b>:0 
   --- End of inner exception stack trace ---
  at SteamKit2.TcpConnection.ReadPacket () [0x0002a] in <76ca85500f404320adcb89e6491c714b>:0 
  at SteamKit2.TcpConnection.NetLoop () [0x0003c] in <76ca85500f404320adcb89e6491c714b>:0 
[2018-12-04 11:05:48,679][DEBUG] ServerList: Next server candidiate: 162.254.197.180:27018 (Tcp)
[2018-12-04 11:05:48,679][DEBUG] TcpConnection: Connecting to 162.254.197.180:27018...
[2018-12-04 11:05:48,749][DEBUG] TcpConnection: Connected to 162.254.197.180:27018
[2018-12-04 11:05:48,809][DEBUG] EnvelopeEncryptedConnection: Got encryption request. Universe: Public Protocol ver: 1
[2018-12-04 11:05:48,878][DEBUG] EnvelopeEncryptedConnection: Encryption result: OK
[2018-12-04 11:05:49,789][DEBUG] CMClient: Sent -> EMsg: ClientToGC (Proto: True)
[2018-12-04 11:05:49,894][DEBUG] CMClient: <- Recv'd EMsg: ClientLoggedOff (757) (Proto: False)
[2018-12-04 11:05:49,905][DEBUG] TcpConnection: Socket exception occurred while reading packet: System.IO.IOException: Connection lost while reading packet header. ---> System.IO.EndOfStreamException: Unable to read beyond the end of the stream.
  at System.IO.BinaryReader.FillBuffer (System.Int32 numBytes) [0x0007a] in <3833a6edf2074b959d3dab898627f0ac>:0 
  at System.IO.BinaryReader.ReadUInt32 () [0x00000] in <3833a6edf2074b959d3dab898627f0ac>:0 
  at SteamKit2.TcpConnection.ReadPacket () [0x00004] in <76ca85500f404320adcb89e6491c714b>:0 
   --- End of inner exception stack trace ---
  at SteamKit2.TcpConnection.ReadPacket () [0x0002a] in <76ca85500f404320adcb89e6491c714b>:0 
  at SteamKit2.TcpConnection.NetLoop () [0x0003c] in <76ca85500f404320adcb89e6491c714b>:0

After that it keeps trying to connect to different servers without much luck.

I'm using Mono 5.16.0.179 in official Docker image. When testing on Windows everything works perfectly fine and unfortunately I didn't yet had chance to test on full Linux.

stanriders commented 5 years ago

Nevermind, exposing 27018 port was enough

shravan2x commented 5 years ago

@yaakov-h I added DebugLog as you had suggested, but I haven't seen the issue since. Thanks for closing - I'll reopen if it happens again.