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

Already on GitHub? Sign in to your account

Trade fails to load until the bot is restarted #404

Closed
catalyst518 opened this Issue Jul 29, 2013 · 28 comments

Comments

Projects
None yet

The bot will be operating normally and performing trades successfully for a while. At some point, the bot will fail to load trades successfully. The trade window will open and the place where the bot's items go will remain at "Waiting for [Bot Name]" until it times out and the trade window then goes to "Sorry, some kind of error has occurred. The trading session has expired." All future trades will encounter the same problem. Restarting the bot always fixes the problem temporarily until it eventually bugs out again at a random time later. I have also noticed this issue when using other bots besides my own.

Here's what the log looks like when the trades are not loading properly:

[2013-07-23 06:12:54] DEBUG: SteamKit2.SteamFriends+PersonaStateCallback
[2013-07-23 06:13:33] DEBUG: SteamKit2.SteamTrading+TradeProposedCallback
[2013-07-23 06:13:35] SUCCESS: [User] has requested to trade with me!
[2013-07-23 06:13:36] DEBUG: SteamKit2.SteamTrading+SessionStartCallback
[2013-07-23 06:13:36] DEBUG: SteamTrading.SessionStartCallback handled successfully. Trade Opened.
[2013-07-23 06:13:37] WARN: Opened trade with user.
[2013-07-23 06:13:37] DEBUG: SteamKit2.SteamFriends+PersonaStateCallback
[2013-07-23 06:14:07] WARN: [USERHANDLER] TRADE CLOSED
[2013-07-23 06:14:08] DEBUG: SteamKit2.SteamFriends+PersonaStateCallback

After enabling the TradeManager.cs debugging by adding #define DEBUG_TRADE_MANAGER to the top of TradeManager.cs, this is the error that is output to the console when the trades are not loading:

[TRADEMANAGER] general error caught: SteamTrade.Exceptions.TradeException: The w
eb command to send the trade message failed.
   at SteamTrade.Trade.SendMessage(String msg)
   at SteamBot.MyUserHandler.OnTradeInit()
   at SteamTrade.Trade.Poll()
   at SteamTrade.TradeManager.<StartTradeThread>b__1()
Trade thread shutting down.

Note: The above description was previously posted in the now closed issue #398

Owner

Jessecar96 commented Jul 29, 2013

I'll confirm this as a bug. I feel we should not be throwing an exception when a web request fails (which happens often). Just write a warning to the log instead. This is what I did with The ScrapTF bots to make them more stable.

Contributor

cwhelchel commented Jul 29, 2013

@jessecar96 This will be easier once the Log class is refactored into a new project.

Yes this does seem to happen occasionally, I think there should be a way to restart bot from the userhandler.

Contributor

SephirothSG commented Sep 11, 2013

There is though.

if (message == "self.restart")
            {
                if (IsAdmin)
                {
                    // Starts a new instance of the program itself
                    var filename = System.Reflection.Assembly.GetExecutingAssembly().Location;
                    System.Diagnostics.Process.Start(filename);

                    // Closes the current process
                    Environment.Exit(0);
                }
            }
Contributor

waylaidwanderer commented Sep 11, 2013

A rather clunky solution if you're running multiple bots and only one is having this problem.

SephirothSG notifications@github.com wrote:

There is though.

if (message == "self.restart")
            {
                if (IsAdmin)
                {
                    // Starts a new instance of the program itself
                    var filename = System.Reflection.Assembly.GetExecutingAssembly().Location;
                    System.Diagnostics.Process.Start(filename);

                    // Closes the current process
                    Environment.Exit(0);
                }
            }

Reply to this email directly or view it on GitHub:
#404 (comment)

Contributor

SephirothSG commented Sep 11, 2013

True but judging from the OP's issue description he seems to only be running one bot.

Collaborator

BlueRaja commented Dec 9, 2013

I'll confirm this as a bug. I feel we should not be throwing an exception when a web request fails (which happens often). Just write a warning to the log instead. This is what I did with The ScrapTF bots to make them more stable.

Any chance you could push that change to the public repo?

[Edit] Nevermind, I fixed it myself. I'll send a pull-request later.

qtong commented Dec 13, 2013

Could you share info how did you actualy fix the issue ?

Contributor

FrozenHaxor commented Dec 13, 2013

@qtong Use try catch...

Collaborator

BlueRaja commented Dec 13, 2013

https://github.com/BlueRaja/SteamBot/commit/a9b8c9b3b2ef9ee58a5c347ecd373168bd96c4a1

I'm still making various fixes, I'll send one big pull request in a few days.

qtong commented Dec 13, 2013

@FrozenHaxor whats your problem ?

Contributor

FrozenHaxor commented Dec 13, 2013

@qtong What? I just told you how to solve the problem with crashing. Use try catch. A cheap fix but SteamBot doesn't offer much more about handling Web exceptions...

qtong commented Dec 13, 2013

@FrozenHaxor Dont know why but not understanding what you said I automaticly assumed your trying to insult me in some kind of strange way. So yeah, whats try catching. Sorry for sounding rude btw,

EDIT: OK, Just found out what it actualy means, my knowlegde of programming comes down to intuitive code manipulating so I guess I wont fix it so easily. :)

Collaborator

BlueRaja commented Jan 3, 2014

This should happen less often with the latest version. I believe #494 will actually fix it.

Collaborator

BlueRaja commented Jan 21, 2014

Confirmed that this has not been fixed. I have no idea what's causing it :\

Contributor

FrozenHaxor commented Jan 21, 2014

I second what @BlueRaja said. This is happening too often to be left unattended.

Contributor

cwhelchel commented Jan 21, 2014

Some other exception causing this? Perhaps not a web command exception.

Also @BlueRaja doesn't T result = webEvent(); need to be in a try...catch?

Collaborator

BlueRaja commented Jan 21, 2014

@cwhelchel Good point, sometimes those web commands throw an exception rather than simply returning an error. Would you like to submit a pull request?

Contributor

cwhelchel commented Jan 21, 2014

Can't right now. At work.

cwhelchel added a commit to cwhelchel/SteamBot that referenced this issue Jan 22, 2014

Bug-fix patch for #404
Surround web call with a try...catch. The exception is silently ignored but needs to be logged.

ref #394

Jessecar96 added a commit that referenced this issue Jan 22, 2014

Contributor

scholtzm commented Sep 11, 2014

I'm not sure my issue is the same, but it goes like this:

[x 2014-09-09 10:34:32] INFO: Chat Message from y: !trade
[x 2014-09-09 10:34:34] INFO: Trade Accepted!
[x 2014-09-09 10:34:34] INFO: Trade init started.
[x 2014-09-09 10:34:43] INFO: Trade init complete.
[x 2014-09-09 10:35:34] WARN: User was kicked because he was AFK or the trade timed out.
[x 2014-09-09 10:35:37] WARN: [USERHANDLER] TRADE CLOSED
[x 2014-09-09 10:36:00] INFO: Chat Message from y: !trade
[x 2014-09-09 10:36:02] INFO: Trade Accepted!
[x 2014-09-09 10:36:02] INFO: Trade init started.
[x 2014-09-09 10:36:11] INFO: Trade init complete.
[x 2014-09-09 10:37:03] WARN: User was kicked because he was AFK or the trade timed out.
[x 2014-09-09 10:37:06] WARN: [USERHANDLER] TRADE CLOSED

No exceptions. Nothing extra in the console. User on the other side only sees the spinning wheel. The bot never contacts the server and the session times out. Bot doesn't know this and 1 minute later, AFK watcher kicks in (thank god, it would go on forever otherwise).

I have started logging all session calls (in SteamWeb.Fetch) to see exactly what the responses are. I'll be waiting for the issue to occur again.

glen-84 commented Sep 11, 2014

I've seen this as well. When it happened, I asked the user to restart the Steam client, and I think that fixed the issue ... not sure if he did that before or after I restarted the bots though.

Contributor

scholtzm commented Sep 13, 2014

Finally captured the Steam response when this happens:

1.1 200 OK
Server: Apache
X-Frame-Options: DENY
Expires: Mon, 26 Jul 1997 05:00:00 GMT
Cache-Control: no-cache
Content-Type: application/json; charset=utf-8
X-Varnish: 1835233527
Date: Sat, 13 Sep 2014 09:04:10 GMT
Content-Length: 17
Connection: keep-alive
Set-Cookie: steamLogin=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; path=/,steamLoginSecure=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; path=/,steamRememberLogin=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; path=/,webTradeEligibility=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; path=/

{"success":false}

Notice the cookies. Why?!

edit. It really says "deleted". I didn't change that.
edit2. steamLogin is the Bot.token variable. Do we need to refresh it somehow after a while?
edit3. Found another example:

------------------------------------------------------------
6 hours of this ...
------------------------------------------------------------
1.1 200 OK
Server: Apache
X-Frame-Options: DENY
Expires: Mon, 26 Jul 1997 05:00:00 GMT
Cache-Control: no-cache
Content-Type: application/json; charset=utf-8
X-Varnish: 1069987890
Date: Sat, 13 Sep 2014 00:42:15 GMT
Content-Length: 17
Connection: keep-alive
Set-Cookie: steamLogin=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; path=/,steamLoginSecure=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; path=/,steamRememberLogin=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; path=/,webTradeEligibility=deleted; expires=Thu, 01-Jan-1970 00:00:01 GMT; path=/

{"success":false}
------------------------------------------------------------
Then this happens ...
------------------------------------------------------------
[x 2014-09-13 02:59:48] WARN: Logged Off: ServiceUnavailable
[x 2014-09-13 02:59:48] WARN: Disconnected from Steam Network!
[x 2014-09-13 02:59:50] SUCCESS: User Authenticated!
[x 2014-09-13 02:59:50] SUCCESS: Steam Bot Logged In Completely!
------------------------------------------------------------
And it works again ...
------------------------------------------------------------
1.1 200 OK
Server: Apache
X-Frame-Options: DENY
Expires: Mon, 26 Jul 1997 05:00:00 GMT
Cache-Control: no-cache
Content-Type: application/json; charset=utf-8
X-Varnish: 1308503207
Date: Sat, 13 Sep 2014 01:26:16 GMT
Content-Length: 373
Connection: keep-alive

{"trade_status":0,"success":true,"version":1,"newversion":false,"me":{"ready":0,"confirmed":0,"sec_since_touch":0},"them":{"ready":0,"confirmed":0,"sec_since_touch":0,"connection_pending":true},"events":[{"steamid":"<STEAMID64>","action":"7","timestamp":1410571575,"appid":0,"text":"<MESSAGE>"}]}

edit4. Restart does not always seem to help:

[<BOT> 2014-09-13 11:08:31] INFO: Connecting...
[<BOT> 2014-09-13 11:08:31] SUCCESS: Done Loading Bot!
[<BOT> 2014-09-13 11:08:48] SUCCESS: User Authenticated!
[<BOT> 2014-09-13 11:08:48] INFO: Downloading Schema...
[<BOT> 2014-09-13 11:08:52] SUCCESS: Schema Downloaded!
[<BOT> 2014-09-13 11:08:52] SUCCESS: Steam Bot Logged In Completely!
[<BOT> 2014-09-13 11:19:26] SUCCESS: <NAME> (<STEAMID32>) has requested to trade with me!
[<BOT> 2014-09-13 11:19:27] INFO: Trade init started.
[<BOT> 2014-09-13 11:19:41] INFO: Trade init complete.
[<BOT> 2014-09-13 11:20:27] WARN: User was kicked because he was AFK or the trade timed out.
[<BOT> 2014-09-13 11:20:30] WARN: [USERHANDLER] TRADE CLOSED

edit5. Other interesting info:
sessionid can be set to anything and it will work just fine (POST param must match the cookie).
@BlueRaja says that changing the steamLogin to garbage reproduces this issue.

Collaborator

BlueRaja commented Sep 13, 2014

Set a breakpoint on the line that sets the steamLogin cookie, change it to something else. That reproduces this issue.

I can add code that detects when that happens in SteamWeb.Fetch(), but unfortunately I don't know what to do after that. Calling Authenticate() again causes an HTTP/401 UNAUTHORIZED response (presumably because MyLoginKey needs to be refreshed too. No clue how to force that), and calling SteamClient.Connect() to force a disconnect/reconnect causes an exception within SteamKit(!?!)

@cwhelchel you wrote this code, and @Lagg I know you looked into the Steam authorization API before. Do either of you know how to get an updated value for the steamLogin cookie?

@scholtzm and I discussed using the doLogin() method that steamcommunity.com uses, but that could require entering a CAPTCHA value, which would not be good if the issue occurs when no one's around...

Contributor

scholtzm commented Sep 13, 2014

So, after some testing we have concluded that steamLogin (or token) does not change / refresh after this event. That means simple restart / reconnect / relogin won't do a thing here because it does not seem to be related at all.

This also proves my edit4 and disproves edit3 theory from my previous post.

Contributor

scholtzm commented Sep 17, 2014

The issue has not happened once in the last 4 days running on my W7 machine. I'm switching back to unix and see how that goes. @lub4oo has also started logging his HTTP sessions.

Collaborator

BlueRaja commented Sep 17, 2014

If the issue occurs on Linux but not Windows, the issue is most likely due to Mono vs. .Net, rather than Linux vs. Windows

Mono runs under Windows. Try running/logging your bot with that instead.

Contributor

scholtzm commented Sep 22, 2014

Another progress report: no issues after running for 4 days straight on my linux machine. The bug seems to be extremely random.

Edit.

Fix proposed in #627.

scholtzm added a commit to scholtzm/SteamBot that referenced this issue Sep 22, 2014

BlueRaja added a commit that referenced this issue Sep 28, 2014

Merge pull request #627 from scholtzm/404fix
Fix for issue #404 + added support for steamLoginSecure
Collaborator

BlueRaja commented Sep 28, 2014

Closing due to #617, please let us know if you see the bug again.

@BlueRaja BlueRaja closed this Sep 28, 2014

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment