Near-simultaneous trade offers resulted in 2nd offer being auto-accepted when it should not have been

catharsis71 commented 2 months ago

Checklist

[X] I read and understood ASF's Contributing guidelines
[X] I also read Setting-up and FAQ, I don't need help, this is a bug report
[X] This is not a duplicate of an existing issue
[X] I don't own more than 10 accounts in total
[X] I'm not using custom plugins
[X] This is not a question
[X] This is not a technical issue
[x] This is not ASF-ui problem

ASF version

Latest stable release

ASF variant

linux-x64

Bug description

I am using TradingPreferences 3 (AcceptDonations and SteamTradeMatcher) with PublicListing enabled

I had: 1 of card A, 1 of card B, 0 of card C

I received the following two trade offers at approximately the same time:

Trade 1: lose card A, gain card C Trade 2: lose card B, gain card C

in isolation, either of these trades would be considered neutral, however, after trade 1 is executed, trade 2 becomes negative meaning it should not be executed (as I am not using MatchEverything)

however, ASF accepted both trades, leaving me with 0 of card A, 0 of card B, and 2 of card C, which is worse than my initial condition

Log:

2024-09-18 11:17:56|ArchiSteamFarm-648|DEBUG|catharsis|ShouldAcceptTrade() The trade offer 7399595447 is determined to be Accepted due to IsTradeNeutralOrBetter.
2024-09-18 11:17:56|ArchiSteamFarm-648|INFO|catharsis|ParseTrade() Accepting trade: 7399595447
2024-09-18 11:18:01|ArchiSteamFarm-648|DEBUG|catharsis|ShouldAcceptTrade() The trade offer 7399589707 is determined to be Accepted due to IsTradeNeutralOrBetter.
2024-09-18 11:18:01|ArchiSteamFarm-648|INFO|catharsis|ParseTrade() Accepting trade: 7399589707

I don't know if it could be relevant or not but CPU utilization on the server was very high due to another running process at the time this happened.

I have trade screenshots as well as a screenshot of my badge page for the game in question post-trade with the cards in question labeled A, B, and C, however, it's saying this message is too large so I'll try to put the screenshots in a comment

Expected behavior

trade 1 should have been accepted (this happened)

trade 2 should not have been accepted because even though it was neutral at the time it was sent, after the execution of trade 1, trade 2 became a negative trade

Actual behavior

trade 2 was accepted even though, after the acceptance of trade 1, trade 2 became a negative trade rather than neutral

Steps to reproduce

This may be difficult to reproduce at-will due to the timing involved but it seems to be related to two trade offers being received almost simultaneously, the evaluation of whether the 2nd trade offer is good/neutral/negative does not factor in the results of the 1st trade offer

Possible reason/solution

Might or might not be relevant but CPU usage on the server was high at the time of the incident due to another running process, this could have caused lag in ASF or some kind of race condition

Can you help us with this bug report?

Yes, I can code the solution myself and send a pull request

Full log.txt recorded during reproducing the problem

https://gist.github.com/catharsis71/6834e9bfa860847aabf2eec308de3435

Global ASF.json config file

{
  "IPC": false,
  "MaxTradeHoldDuration": 1,
  "SteamOwnerID": *****************,
  "SteamTokenDumperPluginEnabled": true
}

BotName.json config of all affected bot instances

{
  "Enabled": true,
  "FarmingPreferences": 144,
  "SteamLogin": "***************",
  "TradingPreferences": 3,
  "SteamTokenDumperPluginEnabled": true
}

Additional info

taking a closer look at the log, it looks like the trades were actually received a few minutes apart, but the first trade initially got a "TryAgain due to holdDuration" and then accepted a couple minutes later; the reference to holdDuration doesn't make sense to me because there was no hold on the trade. I've actually seen the "TryAgain due to holdDuration" happen with a couple other trades over the past week (before the start of the current log) when there was no hold, seems random, however no harmful behavior was observed as a result of them.

11:15:30 - trade #1 (7399589707) received and "determined to be TryAgain due to holdDuration" 11:17:56 - trade #2 (7399595447) received and accepted 11:18:01 - trade #1 (7399589707) accepted

catharsis71 commented 2 months ago

jackbox trade1 trade2

catharsis71 commented 2 months ago

full log uploaded to https://gist.github.com/catharsis71/6834e9bfa860847aabf2eec308de3435 as it was too large to include in the initial report

JustArchi commented 2 months ago

For record, this is not a bug but intended ASF behaviour. In particular, ASF processes trades in parallel, as soon as it has information about one or more, then it parses them independently - not synchronously, as you expected in your issue.

I'd need to evaluate here whether there are some realistic improvements we can make without changing the trades parsing to synchronous. I do not consider your behaviour as malicious or unwanted, sure, it might in some edge cases produce badge progress degaradation, which is unfortunate, but it's not like the logic is wrong to allow that, it's simply the fact that at the time of accepting the trade both were in fact neutral+. The fact that we accept 2+ at the same split second doesn't change that, rather it causes unwanted side effect due to internal implementation detail of parallel processing.

I'll give this a thought over few next days and decide upon something. One option that comes to my mind right now is synchronizing trades that are touching the same sets. The problem with this approach however is that we can't be 100% sure whether the trade we accept goes through until we get confirmation from Steam API itself, which is not going to happen until next trades parsing. We could therefore, at least in theory, actively put another trade on hold until next parsing session if ASF detects conflict over same set in more than one trade.

the reference to holdDuration doesn't make sense to me because there was no hold on the trade

ASF is telling you that it can't process the trade due to failure in resolving trade hold duration. You specified it yourself:

"MaxTradeHoldDuration": 1

catharsis71 commented 2 months ago

trade hold duration was 0 on all the trades in question

JustArchi commented 2 months ago

How does that change the fact that ASF had to resolve trade hold duration for the trade in order to realize it was 0, which failed?

catharsis71 commented 2 months ago

the tradehold thing is tangential to the main issue

The trades that happened today appear to be an unlucky coincidence rather than a deliberate attack, but I'm concerned that (to use an extreme example) if I have 9 cards out a 10-card set, a malicious attacker with multiple accounts could issue 8 simultaneous trade requests from 8 accounts and I'd end up with 9 copies of the same card (and none of any of the others)

if it intended that hackers with multiple accounts should be allowed to exploit the system in this way?

I probably should have opened this as a security vulnerability instead of a normal issue, I apologize for not doing so but it didn't initially occur to me how ripe this is for malicious exploit, if you'd like me to re-file it as a security vulnerability I can do that, but some people have probably already seen it

as a stopgap measure I've disabled SteamTradeMatcher on my system as that seems to be the least disruptive way of mitigating the vulnerability, I'd like to turn it back on eventually, but only if/when it's safe to do so

JustArchi commented 2 months ago

It's not a security issue, you're not losing anything but badge progress, no data is lost neither digital property, and it's intended ASF functionality and implementation detail how it works right now.

Any "exploit" of this implementation detail is moot as sooner or later the bots with STM matching go back to the original state, and you can't make artbirary trades pass this way, only those that are determined as neutral+ at the time of accepting, so it's very limited abuse of intended ASF functionality, nothing critical.

JustArchi commented 2 months ago

As presented in the issue, we might end up in situation when parallel-processing and accepting two neutral+ trade offers will result in unwanted inventory state, because while they're both neutral+ and therefore OK to accept standalone, the combination of them both causes active badge progress degradation.

Considering the requirements we have, e.g. still processing trades in parallel, being performant, low on resources and with limited Steam servers overhead, the solution that I came up with in regards to this issue is quite simple:

After we determine the trade to be neutral+, but before we tell the parse trade routine to accept it, we check if shared with other parallel processes set of handled sets contains any sets that we're currently processing.
If no, we update that set to include everything we're dealing with, and tell the caller to accept this trade.
If yes, we tell the caller to retry this trade after (other) accepted trades are confirmed and handled as usual.

This solves some issues and creates some optimistic assumptions:

First of all, it solves the original issue, since if trade A and B both touch set S, then only one of them will be accepted. It's not deterministic which one (the one that gets to the check first), and not important anyway.
We do not "lock" the sets before we determine that trade is neutral+, because otherwise unrelated users could spam us with non-neutral+ trades in order to lock the bot in infinite retry. This way they can't, as if the trade is determined to not be neutral+ then it never checks for concurrent processing.
We are optimistic about resources usage. This routine could be made much more complicated to be more synchronous in order to avoid unnecessary calls to inventory and matching, however, that'd slow down the whole process only because the next call MAYBE will be determined as unneeded. Due to that, ASF is optimistic that trades will (usually) be unrelated, and can be processed in parallel, and if the conflict happens then simply we end up in a situation where we did some extra work for no reason, which is better than waiting with the work till all previous trades are processed.
As soon as the conditions are met, the conflicting trades are retried to check if the conditions allow to accept them. If yes, they'll be accepted almost immediately after previous ones, if not, they'll be rejected as non-neutral+ anymore.

This way the additional code does not hurt the performance, parallel processing or anything else in usually expected optimistic scenarios, while adding some additional overhead in pessimistic ones, which is justified considering we don't want to degrade the badge progress.

Rudokhvist commented 2 months ago

First of all, it solves the original issue, since if trade A and B both touch set S, then only one of them will be accepted. It's not deterministic which one (the one that gets to the check first), and not important anyway.

Won't it be a race-condition prone?

JustArchi commented 2 months ago

No. lock exists for a reason.

obraz

JustArchi commented 2 months ago

V6.0.7.3 is now available for testing which should solve this issue.

Thanks for report @catharsis71 :+1:

JustArchiNET / ArchiSteamFarm