Jessecar96 / SteamBot

Automated bot software for interacting with Steam Trade
http://scrap.tf
MIT License
1.34k stars 910 forks source link

OnTradeInit invoked after OnTradeRequestReply (accepted=false) – is this the correct behaviour? #599

Closed glen-84 closed 9 years ago

glen-84 commented 10 years ago

I asked about this on Reddit, but no one could help.

Is OnTradeInit supposed to run regardless of whether or not the trade has been accepted?

If it is, I'm not sure if moving our code to OnTradeRequestReply would be a good idea, because it seems like this method can be invoked more than once. Have a look at an example from last night. TradeResultCallback is executed twice in the same second, with a different result.

Maybe we should just set a flag in OnTradeRequestReply if the trade is not accepted, and then exit early from OnTradeInit if the flag is true.

scholtzm commented 10 years ago

Is this happening to you just randomly? I can't replicate the behaviour. Bot always reacts accordingly.

And to answer the 1st question, no it should not.

glen-84 commented 10 years ago

Yes, it seems to be random, a few times a day at the most.

scholtzm commented 10 years ago

Sometimes when both users send trade request at the same time from regular Steam client, the session starts but no one sees the actual trade window and both sides have to wait for timeout. Could this be the case?

glen-84 commented 10 years ago

The most common case is "TargetAlreadyTrading", for example:

[x 2014-07-26 08:13:27] INFO: x: [123] *** FRIEND: 100, REL. Friend ***
[x 2014-07-26 08:13:27] INFO: x: [123] *** FRIEND: 123, REL. PendingInvitee ***
[x 2014-07-26 08:13:27] INFO: x: [123] Accepting friend request.
[x 2014-07-26 08:13:27] DEBUG: SteamKit2.SteamFriends+PersonaStateCallback
[x 2014-07-26 08:13:27] DEBUG: SteamKit2.SteamFriends+PersonaStateCallback
[x 2014-07-26 08:13:27] DEBUG: SteamKit2.SteamFriends+FriendAddedCallback
[x 2014-07-26 08:13:27] DEBUG: SteamKit2.SteamFriends+FriendsListCallback
[x 2014-07-26 08:13:27] DEBUG: SteamKit2.SteamFriends+PersonaStateCallback
[x 2014-07-26 08:13:35] DEBUG: SteamKit2.SteamTrading+SessionStartCallback
[x 2014-07-26 08:13:35] DEBUG: SteamTrading.SessionStartCallback handled successfully. Trade Opened.
[x 2014-07-26 08:13:35] DEBUG: SteamKit2.SteamTrading+TradeResultCallback
[x 2014-07-26 08:13:35] WARN: Trade failed: TargetAlreadyTrading
[x 2014-07-26 08:13:35] INFO: x: [123] Trade request not accepted (response: TargetAlreadyTrading).
[x 2014-07-26 08:13:35] INFO: x: [123] Connecting to database.
[x 2014-07-26 08:13:35] INFO: x: [123] Connected to database.
[x 2014-07-26 08:13:35] INFO: x: [123] Loading bot & user.
[x 2014-07-26 08:13:35] INFO: x: [123] Setting x bot status to busy.
[x 2014-07-26 08:13:36] DEBUG: SteamKit2.SteamFriends+FriendsListCallback
[x 2014-07-26 08:13:36] INFO: x: [123] Removing friend.
[x 2014-07-26 08:13:36] DEBUG: SteamKit2.SteamFriends+PersonaStateCallback
[x 2014-07-26 08:13:36] DEBUG: SteamKit2.SteamTrading+TradeResultCallback
[x 2014-07-26 08:13:36] WARN: Trade failed: Cancel
[x 2014-07-26 08:13:36] INFO: x: [123] Trade request not accepted (response: Cancel).
[x 2014-07-26 08:13:40] DEBUG: SteamKit2.SteamUser+SessionTokenCallback
[x 2014-07-26 08:13:58] DEBUG: SteamKit2.SteamFriends+FriendMsgCallback
[x 2014-07-26 08:13:58] DEBUG: SteamKit2.SteamTrading+TradeResultCallback
[x 2014-07-26 08:13:58] WARN: Trade failed: Cancel
[x 2014-07-26 08:13:58] INFO: x: [123] Trade request not accepted (response: Cancel).

Where 123 is the Steam ID of the user (the bot had another friend [100], but I don't think that it is interfering). Where it says "Connecting to database", that is in OnTradeInit, but the trade has already failed at this point.

Note also how there are three (!) TradeResultCallbacks.

glen-84 commented 10 years ago

Something is seriously wrong. Have a look at this example (and similar things are happening a few times a day). I added extra logging.

[123] = The user's Steam ID. [1406832797480], [1406832817433], [1406832833083] = Separate instances of the user handler. tradeNotAccepted = A flag I set in OnTradeRequestReply when accepted=false

Note:

  1. OnTradeInit is definitely invoked before OnTradeRequestReply (it's the same handler instance).
  2. NUL bytes (one in this case) in the log file and a missing LF.
  3. A new handler (1406832817433) for the same user in the same second (2014-07-31 20:53:37).
  4. The new handler accepts the friend request after OnTradeRequestReply.
  5. Another OnTradeRequestReply (cancel) and then ANOTHER OnTradeRequestReply (accepted!).
  6. MORE TradeResultCallbacks in yet another handler instance (1406832833083).

What on earth is going on?

I have the latest SteamBot code (the only change is replacing the AppId with 570).

We run the bots on Linux:

Linux version 2.6.32-5-amd64 (Debian 2.6.32-46) (dannf@debian.org) (gcc version 4.3.5 (Debian 4.3.5-4) ) #1 SMP Sun Sep 23 10:07:46 UTC 2012

With mono:

Mono JIT compiler version 3.4.1 (master/fdae265 Wed Mar 19 10:07:04 CET 2014)

I compile SteamBot on Windows 7 with Visual Studio Express 2013.

We run 3 SteamBot processes with multiple bots each using Supervisor.

Any ideas?

scholtzm commented 10 years ago

It's not clear from the log, who sends the trade request. I'm assuming it's the bot.

  1. OnTradeInit fires first because:

    [x 2014-07-31 20:53:36] DEBUG: SteamKit2.SteamTrading+SessionStartCallback [x 2014-07-31 20:53:36] DEBUG: SteamKit2.SteamTrading+TradeResultCallback

    The order of the callbacks is all wrong.

  2. No idea.
  3. Weird.
  4. Why is the same user accepted over and over again?
  5. That's not the issue. These are firing according to:

    SteamKit2.SteamTrading+TradeResultCallback

  6. All of these are coming from the Steam servers.

The log actually makes sense. All the methods are firing as they should. But your bot is intercepting SteamKit callbacks in an unusual order.

I'm unable to replicate any of the stuff you described. Are you sure the 3 separate processes aren't "fighting" each other?

glen-84 commented 10 years ago

It's not clear from the log, who sends the trade request. I'm assuming it's the bot. The bot does, before returning from OnFriendAdd.

  1. Yep.
  2. Could be something to do with concurrent file access?
  3. Indeed.
  4. I don't know, maybe because the user is removed when there's an error or he/she cancels the trade, and then they add the bot again.
  5. I know, but there seem to be too many TradeResultCallbacks.
  6. Sure, I just don't know why.

I'm unable to replicate any of the stuff you described. Are you sure the 3 separate processes aren't "fighting" each other?

I'm not sure of anything :D ... shouldn't it be possible to run multiple processes side-by-side, assuming that they each have a different set of bots?

What is your setup like?

Linux seems to be very outdated, so I'll try to get that updated FWIW.

scholtzm commented 10 years ago

The bot does, before returning from OnFriendAdd.

This might be an issue. If you are sending the trade request in OnFriendAdd, that means you are sending it before you even become "friends". Use timer or something to fix this.

Could be something to do with concurrent file access?

Yep, something like that could corrupt the file.

I'm also running on Linux (mono), but only a single process as a screen session.

The most important for you right now is to find out the reason of so many "dummy" (maybe?) callbacks. Debug those and see what info they can provide you with.

scholtzm commented 10 years ago

I have noticed that this event may indeed happen. One of the ways to cause this seems to be sending trade request exactly when someone else sends you a trade request. This happens in regular Steam client as well.

Obilux commented 10 years ago

hi How to check pending trade requests? i can check accept or decline.

scholtzm commented 10 years ago

It's pending once you send it. There is no other way to check afaik.