SK2 alpha9 regression

[JustArchi]

2017-10-07 05:40:18|ArchiSteamFarm-9864|INFO|nany40|OnDisconnected() Disconnected from Steam!
2017-10-07 05:40:18|ArchiSteamFarm-9864|INFO|nany40|OnDisconnected() Reconnecting...
2017-10-07 05:40:18|ArchiSteamFarm-9864|INFO|nany40|Connect() Connecting...
2017-10-07 05:40:18|ArchiSteamFarm-9864|FATAL|ASF|OnUnhandledException() System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at SteamKit2.Internal.CMClient.Disconnect()
   at SteamKit2.Internal.CMClient.Connect(ServerRecord cmServer)
   at ArchiSteamFarm.Bot.<Connect>d__104.MoveNext() in C:\projects\archisteamfarm\ArchiSteamFarm\Bot.cs:line 1006
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at ArchiSteamFarm.Bot.<OnDisconnected>d__137.MoveNext() in C:\projects\archisteamfarm\ArchiSteamFarm\Bot.cs:line 1623
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()

This looks like SK2 internals. As you can see caused by reconnect attempt in OnDisconnected(). Thanks.

Ref: JustArchiNET/ArchiSteamFarm#665

[yaakov-h]

What OS?

If Windows 7 / Serve 2012, it might be an unintended consequence of #455. If it isn't then I have no idea at all, but either way I don't see how connectionSetupTask can become a cancelled task / throw a TaskCanceledException.

Should be easy enough to fix with the old try/catch/DebugLog treatment.

There were also a few other TaskCanceledExceptions in that ASF log that I don't think can be attributed to SteamKit.

[JustArchi]

Yep, task canceled exceptions that are pointed out by ASF as WARN are fine and caused by Steam not responding, I'm only referring to this specific unhandled exception here, nothing else.

I think I'll start including some bare OS information in my log 😅.

I don't think #461 has anything to do with this, if it was Windows 7 or other system without websockets support then my program would automatically and forcibly disable them from SK2 usage. I'm 99.9% sure it's nothing connected with websockets at all, as I verified with my friend that this piece of logic works properly, at least for Windows 7 SP1. Check yourself.

What is strange is the fact that I reverted to alpha8 as a test and that did fix the issue, this is the whole commit which apart from reverting to previous version only re-included my workaround for the previous persona state issue, but that should have absolutely no connection, OnAccountInfo() is not even executed at any point after disconnect before in fact successful reconnect.

Very strange issue, I'll take a look at SK2 diff.

[JustArchi]

After evaluating the diff only that CMClient.cs change makes any sense, but it still doesn't explain why exactly this exception is unhandled, and why it's being thrown in the first place.

User said that he reproduced it on Windows 10, I'll try to reproduce it myself with debug log enabled and maybe stumble upon some clue.

[yaakov-h]

I already forgot that you silently ignore WebSockets on Win7.

Let me know what you find. Very strange indeed.

[JustArchi]

I managed to reproduce it without bigger problems, it's quite easy to reproduce it actually.

2017-10-07 12:15:55|dotnet-12080|DEBUG|ASF|WriteLine() CMClient | <- Recv'd EMsg: ClientLoggedOff (757) (Proto: True)
2017-10-07 12:15:55|dotnet-12080|INFO|archi|OnLoggedOff() Logged off of Steam: LoggedInElsewhere
2017-10-07 12:15:55|dotnet-12080|DEBUG|ASF|WriteLine() 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()
2017-10-07 12:15:55|dotnet-12080|INFO|archi|OnDisconnected() Disconnected from Steam!
2017-10-07 12:15:55|dotnet-12080|INFO|archi|OnDisconnected() Reconnecting...
2017-10-07 12:15:55|dotnet-12080|INFO|archi|Connect() Connecting...
2017-10-07 12:16:00|dotnet-12080|FATAL|ASF|OnUnhandledException() System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at SteamKit2.Internal.CMClient.Disconnect()
   at SteamKit2.Internal.CMClient.Connect(ServerRecord cmServer)
   at ArchiSteamFarm.Bot.<Connect>d__104.MoveNext() in D:\Wirtualki\shared\git\ArchiSteamFarm\ArchiSteamFarm\Bot.cs:line 1006
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at ArchiSteamFarm.Bot.<OnDisconnected>d__137.MoveNext() in D:\Wirtualki\shared\git\ArchiSteamFarm\ArchiSteamFarm\Bot.cs:line 1623
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.ThreadPoolWorkQueue.Dispatch() 
2017-10-07 12:16:00|dotnet-12080|ERROR|ASF|Exit() Exiting with nonzero error code!
2017-10-07 12:16:00|dotnet-12080|INFO|archi|Stop() Stopping...

I have no clue why it happens, but I can clearly take a look at the code to see what is happening.

The exception seems to be thrown after bot writes "Connecting...". As you can see, in case of this specific message ASF is attempting to reconnect instantly through async call to await Connect() in OnDisconnected() that under the hood is calling typical SteamClient.Connect().

I did a test and added forced 5 seconds of Task.Delay() before trying to connect again, but this did not help. I can still reproduce it very reliably by just invoking LoggedInElsewhere followed by OnDisconnected().

[JustArchi]

Would you like a repro? I think I could reliably write one if you have no luck reproducing it yourself. Basically everything we want is SK2 attempting to play valid Steam game (CMsgClientGamesPlayed) while somebody else, e.g. your own steam client is already playing it (or anything else). You'll need to use my custom LoginID if you want to have both sessions active on the same machine.

Since we're holding a lock and SK2 only wants to start playing a game without taking over the playing lock, it'll be forcibly disconnected with LoggedInElsewhere. The same thing is happening if SK2 is playing firstly and we'll start playing with our steam client but with taking over the lock.

If you add follow-up logic of SteamClient.Connect() in OnDisconnected() then you should have perfect repro for this.

[JustArchi]

Forget about description above, this is even easier to reproduce. Full case below:

using System;
using System.Threading;
using System.Threading.Tasks;
using SteamKit2;


namespace SK2repro
{
	internal class Program
	{
		private static SteamClient SteamClient1;
		private static CallbackManager Manager1;

		private static SteamUser SteamUser1;

		private static bool TryOnce = true;

		private static void OnUnhandledException(object sender, UnhandledExceptionEventArgs e)
		{
			if (e?.ExceptionObject == null)
			{
				Console.WriteLine(nameof(e) + " || " + nameof(e.ExceptionObject));
				return;
			}

			Console.WriteLine((Exception) e.ExceptionObject);
			Thread.Sleep(10000);
			Environment.Exit(1);
		}

		private static void OnUnobservedTaskException(object sender, UnobservedTaskExceptionEventArgs e)
		{
			if (e?.Exception == null)
			{
				Console.WriteLine(nameof(e) + " || " + nameof(e.Exception));
				return;
			}

			Console.WriteLine(e.Exception);
			Thread.Sleep(10000);
			Environment.Exit(1);
		}

		private static void Main()
		{
			AppDomain.CurrentDomain.UnhandledException += OnUnhandledException;
			TaskScheduler.UnobservedTaskException += OnUnobservedTaskException;

			SteamClient1 = new SteamClient();
			Manager1 = new CallbackManager(SteamClient1);

			SteamUser1 = SteamClient1.GetHandler<SteamUser>();

			Manager1.Subscribe<SteamClient.ConnectedCallback>(OnConnected1);
			Manager1.Subscribe<SteamClient.DisconnectedCallback>(OnDisconnected1);
			Manager1.Subscribe<SteamUser.LoggedOffCallback>(OnLoggedOff1);

			Console.WriteLine("<1> Connecting to Steam...");

			SteamClient1.Connect();

			while (true) Manager1.RunWaitCallbacks(TimeSpan.FromSeconds(1));
		}

		private static void OnConnected1(SteamClient.ConnectedCallback callback)
		{
			Console.WriteLine("<1> Connected to Steam! Logging in using random fake details");

			SteamUser1.LogOn(new SteamUser.LogOnDetails
			{
				Username = "thank_you",
				Password = "netshroud",
				LoginID = 1
			});
		}

		private static void OnDisconnected1(SteamClient.DisconnectedCallback callback)
		{
			if (TryOnce)
			{
				TryOnce = false;
				Console.WriteLine("<1> Disconnected from Steam, reconnecting immediately...");
				SteamClient1.Connect();
			}
			else
			{
				Console.WriteLine("<1> We got second disconnection, bug fixed?");
			}
		}

		private static void OnLoggedOff1(SteamUser.LoggedOffCallback callback)
		{
			Console.WriteLine("<1> Logged off of Steam: {0}", callback.Result);
		}
	}
}

(Forgive me this awful code, I just made it to run into the bug 😀)

Thanks!

[yaakov-h]

Haha, it is related to #455. Looks like a strange consequence of TaskContinuationOptions.OnlyOnFaulted.

Microsoft (R) Visual C# Interactive Compiler version 2.3.2.62116
Copyright (C) Microsoft Corporation. All rights reserved.

Type "#help" for more information.
> using System.Threading.Tasks;
> Task.FromResult(true)
(1,1): warning CS4014: Because this call is not awaited, execution of the current method continues before the call is completed. Consider applying the 'await' operator to the result of the call.
Task<bool>(Id = 35, Status = RanToCompletion, Method = "{null}", Result = "True") { AsyncState=null, CancellationPending=false, CreationOptions=None, Exception=null, Id=35, Result=true, Status=RanToCompletion }
> Task.FromResult(true).ContinueWith(t => { }, TaskContinuationOptions.OnlyOnFaulted)
(1,1): warning CS4014: Because this call is not awaited, execution of the current method continues before the call is completed. Consider applying the 'await' operator to the result of the call.
ContinuationTaskFromResultTask<bool>(Id = 54, Status = Canceled, Method = "{null}") { AsyncState=null, CancellationPending=false, CreationOptions=None, Exception=null, Id=54, Status=Canceled }