Big issues with trade acceptance

[glen-84]

I have seen 2 issues today, which has meant that we have had to take our bots offline:

1. A trade is accepted and "committed", no OnTradeSuccess, and much later (like 20 mins), there is a trade error. EXAMPLE
2. A trade is accepted and "committed", and much later (like 20 mins), OnTradeSuccess is invoked. EXAMPLE

What is happening!?

Edit: The bots are running on Linux, if that makes any difference.

[scholtzm]

This issue was caused by none other than Steam. It seems to have been fixed by now.

edit. If random stuff like this happens, it's most likely caused by Steam.

[scholtzm]

And it's back. So annoying. The bot can now make only 2 trades an hour at best.

[glen-84]

Annoying is an understatement. :-)

Question:

We currently have our code that saves information about the trade in OnTradeSuccess – does it make sense (and is it safe) to move this code into OnTradeAccept instead?

Something like this:

    public override void OnTradeAccept()
    {
        if (ValidateTrade()) {
            try {
                if (Trade.AcceptTrade()) {
                    // Save information about a successful trade here.
                }
            } catch (Exception e) {
                // Log.
            }
        }
    }

[scholtzm]

Well, the trade may still fail after accepting so I'm not sure this is the best option.

[glen-84]

Okay. How do you deal with this type of thing in your bots?

[scholtzm]

Personally, I haven't changed anything. I actually save information about successful trades too, but I don't mind if it's 20 or 30 minutes later.

[glen-84]

But what about when OnTradeSuccess isn't invoked at all? (see example 1)

[BlueRaja]

In your example 1, the trade failed, so OnTradeSuccess not being called is the correct behavior.

[scholtzm]

@BlueRaja One would think that's the case but the actual items go through and the trade appears in trade history. @glen-84 Happened to me once and I added the record manually. Other than checking trade history, I don't know how one could fix this.

edit. @BlueRaja Just to make it clear, the behaviour is indeed correct, but Steam is just being silly and sends error status (in my case it was status 2).

[glen-84]

It's happened a few times to us.

Which behaviour is correct? Is Steam not sending a response/event that it usually sends?

It's one thing having a delayed OnTradeSuccess, but returning a trade error after a successful trade is really not good. What does Trade status: 2 even mean?

@scholtzm – are your bots working normally again now?

[scholtzm]

SteamBot behaves correctly, however Steam server sends wrong trade status in rare cases. Not much we can do about that other than doing some sort of fail check.

I think status 2 translates to "Session expired" or something similar.

The issue with extremely long trades seems to be gone for me. At least for now ...

[glen-84]

Thanks @scholtzm

[BlueRaja]

Are you certain Steam is sending the wrong status, and we're not just misinterpreting the response? There is no documentation for most of these APIs, others and myself have had to guess at what the responses mean. If some response is a rare occurance, we could have easily missed it.

Are either of you able to capture what the exact response is when this bug occurs? If you can't attach a debugger, you can still view the HTTP calls using Fiddler (or, for Linux/Mac, Charles)

Or, if you don't mind the huge hit to log-file size, you could log every request/response in SteamTrade/SteamWeb.cs::Request()

[scholtzm]

This was the case:

[x 2014-07-27 20:49:07] SUCCESS: Trade Accepted!
[x 2014-07-27 21:26:57] WARN: Trade was closed by other user. Trade status: 2
[x 2014-07-27 21:26:57] WARN: [USERHANDLER] TRADE CLOSED

Trade went through and items were exchanged.

I have no idea how to replicate this behaviour, it happened to me maybe 2 or 3 times in the last 10 months.

[laggingpyro]

I've added the following code in Trade.Poll(), after fetching the trade status and always returns 0, except when the user (me) closes the tarde, it shows 3 (the expected status).

if (status.trade_status != 0) { Console.WriteLine("Trade Status {0}", status.trade_status); }

[laggingpyro]

My bad, I realised that i had an OnTradeClose (); inside my OnTradeAccept(); so the bot accepts and then cancel(?) the trade, but i think steam server acted like "we don't care, both of you accepted"

[glen-84]

Okay, so we updated, and now have:

Linux version 3.2.0-4-amd64 (debian-kernel@lists.debian.org) (gcc version 4.6.3 (Debian 4.6.3-14) ) #1 SMP Debian 3.2.60-1+deb7u3

Mono JIT compiler version 3.6.0 (tarball Thu Aug 14 12:24:28 UTC 2014)

Now for the fun part (all of these trades were COMMITTED):

[...]
[x 2014-08-20 13:31:12] INFO: GG: [123][1408534207126] User added item (defindex: 10406, steam original id: 3556144175)
[x 2014-08-20 13:31:18] INFO: GG: [123][1408534207126] Trade ready.
[x 2014-08-20 13:31:56] INFO: GG: [123][1408534207126] Trade accepted.
[x 2014-08-20 13:31:56] INFO: GG: [123][1408534207126] Trade ready.
[x 2014-08-20 13:32:57] INFO: GG: [123][1408534207126] Trade error (Trade was closed by other user. Trade status: 2).

[...]
[x 2014-08-20 15:51:42] INFO: GG: [123][1408542687413] Offering bot item (defindex: 6025).
[x 2014-08-20 15:52:05] INFO: GG: [123][1408542687413] Trade ready.
[x 2014-08-20 15:52:35] INFO: GG: [123][1408542687413] Trade accepted.
[x 2014-08-20 15:52:40] INFO: GG: [123][1408542687413] Trade error (Trade was closed by other user. Trade status: 2).

[...]
[x 2014-08-20 17:05:21] INFO: GG: [123][1408547018553] Offering bot item (defindex: 5157).
[x 2014-08-20 17:06:48] INFO: GG: [123][1408547018553] Trade ready.
[x 2014-08-20 17:07:14] INFO: GG: [123][1408547018553] Trade ready.
[x 2014-08-20 17:08:03] INFO: GG: [123][1408547018553] Trade accepted.
[x 2014-08-20 17:08:19] INFO: GG: [123][1408547018553] Trade error (Trade was closed by other user. Trade status: 2).

[...]
[x 2014-08-20 17:44:41] INFO: GG: [123][1408549451026] User added item (defindex: 5852, steam original id: 4401777618)
[x 2014-08-20 17:44:42] INFO: GG: [123][1408549451026] Trade ready.
[x 2014-08-20 17:45:01] INFO: GG: [123][1408549451026] Trade accepted.
[x 2014-08-20 17:45:18] DEBUG: SteamKit2.SteamUser+SessionTokenCallback
[x 2014-08-20 17:45:23] INFO: GG: [123][1408549451026] Trade error (Trade was closed by other user. Trade status: 2).

That's 4 times today that OnTradeSuccess was not called. :-(

What is the best way to debug this? It's driving me crazy.

[Soni96pl]

The possible solution might be checking bot's inventory if the trade fails. That's what I do with my bots, they do not base on SteamBot though.

2014-08-20 21:38 GMT+02:00 glen-84 notifications@github.com:

Okay, so we updated, and now have:

Linux version 3.2.0-4-amd64 (debian-kernel@lists.debian.org) (gcc version 4.6.3 (Debian 4.6.3-14) ) #1 SMP Debian 3.2.60-1+deb7u3

Mono JIT compiler version 3.6.0 (tarball Thu Aug 14 12:24:28 UTC 2014)

Now for the fun part (all of these trades were COMMITTED):

[...] [x 2014-08-20 13:31:12] INFO: GG: [123][1408534207126] User added item (defindex: 10406, steam original id: 3556144175) [x 2014-08-20 13:31:18] INFO: GG: [123][1408534207126] Trade ready. [x 2014-08-20 13:31:56] INFO: GG: [123][1408534207126] Trade accepted. [x 2014-08-20 13:31:56] INFO: GG: [123][1408534207126] Trade ready. [x 2014-08-20 13:32:57] INFO: GG: [123][1408534207126] Trade error (Trade was closed by other user. Trade status: 2).

[...] [x 2014-08-20 15:51:42] INFO: GG: [123][1408542687413] Offering bot item (defindex: 6025). [x 2014-08-20 15:52:05] INFO: GG: [123][1408542687413] Trade ready. [x 2014-08-20 15:52:35] INFO: GG: [123][1408542687413] Trade accepted. [x 2014-08-20 15:52:40] INFO: GG: [123][1408542687413] Trade error (Trade was closed by other user. Trade status: 2).

[...] [x 2014-08-20 17:05:21] INFO: GG: [123][1408547018553] Offering bot item (defindex: 5157). [x 2014-08-20 17:06:48] INFO: GG: [123][1408547018553] Trade ready. [x 2014-08-20 17:07:14] INFO: GG: [123][1408547018553] Trade ready. [x 2014-08-20 17:08:03] INFO: GG: [123][1408547018553] Trade accepted. [x 2014-08-20 17:08:19] INFO: GG: [123][1408547018553] Trade error (Trade was closed by other user. Trade status: 2).

[...] [x 2014-08-20 17:44:41] INFO: GG: [123][1408549451026] User added item (defindex: 5852, steam original id: 4401777618) [x 2014-08-20 17:44:42] INFO: GG: [123][1408549451026] Trade ready. [x 2014-08-20 17:45:01] INFO: GG: [123][1408549451026] Trade accepted. [x 2014-08-20 17:45:18] DEBUG: SteamKit2.SteamUser+SessionTokenCallback [x 2014-08-20 17:45:23] INFO: GG: [123][1408549451026] Trade error (Trade was closed by other user. Trade status: 2).

That's 4 times today that OnTradeSuccess was not called. :-(

What is the best way to debug this? It's driving me crazy.

— Reply to this email directly or view it on GitHub https://github.com/Jessecar96/SteamBot/issues/598#issuecomment-52832329.

[scholtzm]

@glen-84 I log every trade and this simply does not happen on my end.

OnTradeSuccess did not fire because of all those statuses. Afaik, trade status 2 is "Session not found."

Have you tried logging every web request as suggested by @BlueRaja ?

[BlueRaja]

The official Steam web client simply retries the request on trade_status == 2, up to three times (search for OnTradeStatusUpdate, which calls OnTradeStatusFailure).

We should probably be doing the same thing.

[glen-84]

@scholtzm – not yet, because we do a lot of trades so it would take up a lot of space, but I was thinking of just logging the response when the trade status is = 2.

@BlueRaja – ahhh, I think this might be the solution. Can this be added?

[glen-84]

@BlueRaja

This bug is causing us major hassles. Are you able to help with a fix?

My knowledge of the code is limited, but it maybe something like this?

    switch (status.trade_status)
    {
        // Nothing happened. i.e. trade hasn't closed yet.
        case 0:
            break;

        // Successful trade.
        case 1:
            HasTradeCompletedOk = true;
            return false;

        // Cancelled.
        case 3:
            FireOnErrorEvent("Trade cancelled. Trade status: " + status.trade_status);
            OtherUserCancelled = true;
            return false;

        // Timeout.
        // *** DOUBLE CHECK THAT 4 IS A TIMEOUT ***
        case 4:
            FireOnErrorEvent("Trade timed out. Trade status: " + status.trade_status);
            OtherUserCancelled = true; // ?
            return false;

        // Failed.
        case 5:
            FireOnErrorEvent("Trade failed. Trade status: " + status.trade_status);
            OtherUserCancelled = true; // ?
            return false;

        // Missing expected data - treat this as a failure.
        // *** I DON'T KNOW WHAT rgNewTradeStatus.me AND rgNewTradeStatus.them ARE IN THE STEAM CODE ***
        default:
            if (TradePollFailures++ > 3)
            {
                FireOnErrorEvent("Trade failed. Trade status: " + status.trade_status);
                OtherUserCancelled = true; // ?
                return false;
            }
    }

    TradePollFailures = 0;

You could leave the error messages the same to avoid BC breaks.

[BlueRaja]

That will most likely not work. There's a good chance @scholtzm is correct, and this is occurring due to an expired session.

The official Steam code just refreshes the page when it encounters that return code, which updates the session cookie in the process. We're not a webpage, so we don't have that liberty. I've never looked at the session code, so I'm not sure how we'd do something similar.

Also, the fact that no one else has complained about this makes me believe it might be caused by something done in your UserHandler.

[glen-84]

The official Steam code refreshes the page on an error. This will update the session cookie. We're not a webpage, so we don't have that liberty.

Where? To me it looks like it only refreshes the page after 3 or 4 failures.

Also, the fact that no one else has complained about this makes me believe it might be caused by something done in your UserHandler.

@scholtzm himself has had this issue. It's possible that we notice the issue more because we have more bots running than he does (I'm not sure how many he's running?).

[scholtzm]

@glen-84 Have you tried isolating the problem? Try running your bots from different machine for the next 24/48 hours and see what happens. Also logging the SteamWeb.Fetch might be useful.

I'm running just 1 bot right now but @FrozenHaxor is running like 10 bots and he would certainly post here if he encountered this issue.

[FrozenHaxor]

@scholtzm Certainly. This appears to be a local networking issue to me. Or an extremely badly designed UserHandler.

[glen-84]

We are running 150 bots (3 x 50) using Supervisor.

Keep in mind that this might happen 2-4 times a day (or sometimes not at all) while another ~2000 or more trades are successful.

Steam must handle trade status 2 like this for a reason, right?

[scholtzm]

150

Woah. That might actually cause some unexpected issues.

[glen-84]

4 times again yesterday in 2,050 trades.

Do you think it's worth moving all bots to a single process (possibly outside of Supervisor), or is this unlikely to make any difference?

As far as I'm concerned, looking at the Steam code, this is a bug in SteamBot as it incorrectly handles trade status 2. Can someone please acknowledge this?

Also, please let me know if you have any intention of fixing it. If not, I'll have to write experimental code which I'd like to avoid if possible.

Thanks.

[waylaidwanderer]

SteamBot is open-source. If we fix it, it's because someone wrote "experimental code" which solved the issue, and that someone then made a pull request which then got merged into the main repo.

You can be that someone, you know. SteamBot isn't maintained by one person.

On Aug 27, 2014 1:38 AM, glen-84 notifications@github.com wrote: 4 times again yesterday in 2,050 trades.

Do you think it's worth moving all bots to a single process (possibly outside of Supervisor), or is this unlikely to make any difference?

As far as I'm concerned, looking at the Steam code, this is a bug in SteamBot as it incorrectly handles trade status 2. Can someone please acknowledge this?

Also, please let me know if you have any intention of fixing it. If not, I'll have to write experimental code which I'd like to avoid if possible.

Thanks.

---

Reply to this email directly or view it on GitHub: https://github.com/Jessecar96/SteamBot/issues/598#issuecomment-53541305

[glen-84]

@waylaidwanderer

I understand that, however I don't have in-depth knowledge of the SteamBot code (or even C# in some ways). Also, this is not an easily-reproducible issue: It happened to @scholtzm about 3 times in 10 months, and for us it's something like 1 in every 500 trades.

To add to that, I did propose a fix above, but I wanted feedback from those of you who know the code inside & out. I'd like to avoid testing something like this in production until I know that it has a reasonable chance of success (and a very small chance of making things even worse).

If no one is able to help/comment within the next day or two, then we will most-likely have to proceed with a very experimental fix and hope for the best.

I don't know certain things, as commented in my code above:

1. Is status 4 a time-out? (I think so)
2. Should I change the error messages for each type of error?
3. Should OtherUserCancelled be set to true when it's a time-out or failure?
4. What is rgNewTradeStatus.me and rgNewTradeStatus.them in the Steam code (the JS)?
5. How the TradePollFailures variable should be defined, where to reset it, etc.

[BlueRaja]

I ported over the changes from my repo to Trade.Poll(). They include better error messages, and an enum for trade_status. I also implemented the fix for retrying when trade_status == 2 (though I don't believe that's will actually work)

See https://github.com/Jessecar96/SteamBot/pull/615

[glen-84]

Thanks @BlueRaja

We have to give this a try now.

Question: Is a new Trade object created for each trade session, i.e. is there no need to reset the numUnknownStatusUpdates counter?

[BlueRaja]

Yeah, you can see that pretty quickly by doing a 'Find Usages' in Visual Studio on the Trade constructor.

[glen-84]

@BlueRaja, you were right, it hasn't fixed the problem. :-(

I even increased the number of re-tries to 5. I also moved all bots to a single process outside of Supervisor (run via screen).

Here is a more crazy example:

[...]
[x 2014-08-31 10:23:54] INFO: GG: [123][1409473376934] Offering bot item (defindex: 6030).
[x 2014-08-31 10:24:56] DEBUG: SteamKit2.SteamFriends+ClanStateCallback
[x 2014-08-31 10:24:58] DEBUG: SteamKit2.SteamUser+SessionTokenCallback
[x 2014-08-31 10:25:09] INFO: GG: [123][1409473376934] Trade ready.
[x 2014-08-31 10:25:34] INFO: GG: [123][1409473376934] Trade ready.
[x 2014-08-31 10:27:42] INFO: GG: [123][1409473376934] Trade accepted.
[x 2014-08-31 10:27:54] INFO: GG: [123][1409473376934] Trade accepted.
[x 2014-08-31 10:27:54] INFO: GG: [123][1409473376934] Trade ready.
[x 2014-08-31 10:28:39] DEBUG: SteamKit2.SteamFriends+FriendMsgCallback
[x 2014-08-31 10:28:39] DEBUG: SteamKit2.SteamFriends+FriendMsgCallback
[x 2014-08-31 10:29:58] DEBUG: SteamKit2.SteamUser+SessionTokenCallback
[x 2014-08-31 10:30:13] DEBUG: SteamKit2.SteamFriends+ClanStateCallback
[x 2014-08-31 10:30:39] INFO: GG: [123][1409473376934] Trade error (Trade with x (123) CLOSED FOR UNKNOWN REASONS - WHAT CAUSES THIS STATUS!?).

It doesn't always repeat the trade events like that though.

When Steam is very busy, have you guys noticed it taking up to 10-20 seconds to add a single item?

I've also noticed this quite a few times:

[x 2014-08-31 20:06:38] INFO: GG: [123][1409508213423] Trade error (Trade with x (123) expired because bot timed out).

... and I'm wondering if Steam could be doing some kind of rate limiting based on our IP address?

Do you know anyone who is running a large number of bots?

I can only think of 2 more variables:

1. Linux vs Windows (would they run any better on Windows? -- doesn't seem likely)
2. Some kind of network-related issue / throttling.

[scholtzm]

10-20 seconds to add a single item

Sometimes it's slow but never THIS slow for me.

By the way, regular Steam trading does not use API key so if they are throttling you, it's IP based. But it still doesn't make sense to send dummy trade statuses to throttle someone.

[glen-84]

Maybe trade status 2 means "too many requests from this IP address, try again later" or something?

[waylaidwanderer]

When using trade offers, trade status 2 corresponds to large trades. It will show an error 2 when you accept the trade, but if you check your inventory and your partner's, the items gradually go through. I'd imagine error 2 still means the same thing in normal trades.

[glen-84]

I've seen this affecting trades of all sizes, so I don't think that it's related to the size of the trade.

I also noticed this happening the other day while there wasn't a huge amount of activity, which goes against my rate-limiting theory.

[VaporFan]

Could you try to test the connection speed between two points ?

---

Regards, Hoang Nguyen

On Mon, Sep 8, 2014 at 3:57 PM, glen-84 notifications@github.com wrote:

I've seen this affecting trades of all sizes, so I don't think that it's related to the size of the trade.

I also noticed this happening the other day while there wasn't a huge amount of activity, which goes against my rate-limiting theory.

— Reply to this email directly or view it on GitHub https://github.com/Jessecar96/SteamBot/issues/598#issuecomment-54791914.

[glen-84]

@hnkent, between which two points, and using which tool?

BTW, this (trade status 2) happened again yesterday, about 5 times.

It was taking 15 seconds or more to add a single item to the trade, and when we updated the bot to make use of one of 13 random IPs, it didn't seem to help much at all. :-(

[scholtzm]

taking 15 seconds

That's incredibly slow. Network bottleneck maybe?

Do you know if the other person also sees this error when they trade with your bots?

[glen-84]

I'm not really sure how I would test for a network bottleneck. I've asked our host if he knows of anything that might be restricting the bandwidth.

Do you know if the other person also sees this error when they trade with your bots?

I'm not sure what they see, but they usually end up trading again (when it's a withdrawal) which means that they get double the items.

[glen-84]

and when we updated the bot to make use of one of 13 random IPs, it didn't seem to help much at all. :-(

[facepalm] I uploaded SteamBot.exe instead of SteamTrade.dll [/facepalm]

Anyway, I'm monitoring now and I see a lot of "Item not found in inventory" errors, which means that Trade.AddItemByDefindex() is failing for some reason. Any idea why this happens? I'm 99.99% sure that the item exists in the bot's inventory when this happens.

Edit: Oh, and it's often followed by: Trade error (Trade with x (123) expired because bot timed out).

[scholtzm]

It might be the issue I described in #404. It affects all trade session calls including "additem" commands. [TradeSession.cs#L133]

[glen-84]

This is just happening constantly now. Almost every trade ends with a timeout or Trade.AddItemByDefindex failure.

I'm really sick of this all. :-(

[scholtzm]

This just happened:

[x 2014-09-23 16:48:33] SUCCESS: Trade Accepted!
[x 2014-09-23 16:49:04] WARN: error: Trade was closed by other user. Trade status: 2
[x 2014-09-23 16:49:04] WARN: [USERHANDLER] TRADE CLOSED

The trade was not committed this time and the items stayed in the backpack. Seems like a Steam issue?

Some extra details:

• the cookies were OK
• next trade worked flawlessly
• I did not have to restart
• I have logged the HTTP calls - there is nothing extra
• the message in the trade window was "Trade session not found." (I asked the guy)

[glen-84]

It's happened numerous times today, and yesterday, and the day before ...

How can the trade session not be found!? :confused:

[scholtzm]

Have you considered parsing the inventory history page if the trade ends with status 2?

[glen-84]

Do you mean using the GetPlayerItems API?

This only results in a failed transaction a few times here and there, so I didn't really want to spend a lot of time on it.