Bug Mafia seems to spend meat but not buy an item

dapanda

dapanda

Member
Posted on the ASSdiscord as a question but recommended to make a bug report to check it. I posted a snippet on discord because I wanted to see if it was a coding issue or a mafia issue and it was suggested I submit a bug

Mafia Version: 28334

Here is a snippet of the code I run to buy the drinks (ASSdiscord had a modified code because I hit the character limit for what I was typing):

Code: 
if(get_property("_roboDrinks") == ""){
cli_execute("buy 1 drive-by shooting");
cli_execute("buy 1 Newark");
cli_execute("robo Newark");
cli_execute("robo drive-by shooting");
}

kolmafia then did this:

Code: 
Searching for "drive-by shooting"...
Search complete.
Purchasing drive-by shooting (1 @ 23,100) from #1937905...
Preference _concoctionDatabaseRefreshes changed from 2515 to 2516
Purchasing drive-by shooting (1 @ 44,444) from #3138482...
Preference _concoctionDatabaseRefreshes changed from 2516 to 2517
Purchasing drive-by shooting (1 @ 60,000) from #1158200...
Preference _concoctionDatabaseRefreshes changed from 2517 to 2518
Purchasing drive-by shooting (1 @ 65,000) from #32207...
Preference _concoctionDatabaseRefreshes changed from 2518 to 2519
Purchasing drive-by shooting (1 @ 99,900) from #2792867...
Preference _concoctionDatabaseRefreshes changed from 2519 to 2520
Purchasing drive-by shooting (1 @ 500,000) from #1681024...
Preference _concoctionDatabaseRefreshes changed from 2520 to 2521
Desired purchase quantity not reached (wanted 1, got 0)

What is weird is that it spent all my meat and I can't find 6 drive-by shootings. I know it consumed the meat because my day normally starts with about 900k+ and now my total amount is at 6k. (script failed because it couldn't purchase anything else).

What makes it doubly weird is that someone has a stock of over 300 drive-by shootings in the mall at 23,050 in a store that I have access too (just tested it) and I didn't purchase from there. Kol Store: mallstore.php?whichstore=1937905
This is actually the 2nd day this happened, the first day I didn't catch it in time and just happened to really be paying attention today while everything was running. My autobuypricelimit is also at 20,000.

Here is the log file that was from today: https://github.com/dapanda1/logfiles/blob/main/dapanda_20250211.txt

Here is the log when it happened the first time: https://github.com/dapanda1/logfiles/blob/main/dapanda_20250209.txt
This may have been mafia version 28331.

My script runs every day and those are the only 2 days I have noticed this issue. It only happened after the loopsmol script completed, it didn't happen on the pre-ascension part of the script. The code attached runs on both legs though.
 

Attachments

More context: The owner of the first mallstore confirmed that 1 drive-by-shooting was indeed purchased from them, but at the price of 23,050 (they had recently adjusted prices).

This pattern of mallbuying up through all stores, regardless of autoBuyPriceLimit was seen a few years ago, when purchasing tradeable free-pull items.
 
KoLmafia doesn’t automatically do a mall search before making a purchase. It does timestamp each mall search and if the latest search is more than 30? seconds ago (no computer, so can’t check right now), I think it will refresh.

It attempts buy at that price, and there is old old code to defend against a store that raised the price on you after search before purchase.

In this case, the shop lowered the price on you.

Perhaps that confused KoLmafia.

Unless KoL itself has a bug, it is impossible to make a mall purchase, have the Meat removed, and NOT get the item. Perhaps you needed to refresh inventory - or log in again - but I guarantee that only one of “I lost the Meat” and “I didn’t get the items” is true.

It would be a KoLmafia bug to not notice the received item - which make it conclude the store didn’t yield, and it should go to the next.

Note that a “buy” command is not “automation”, so “autoBuyPriceLimit” is irrelevant. You can “acquire” if you want that to kick in.

There is a form of “buy” which lets you specify max price.

I suggest that investigation focus on why KoLmafia thought it did not succeed in buying an item even though it succeeded.

(And no, conjectures on discord that shop.php changes might be related are wrong; those are NPC stores, not player mall stores.)
 
I've been looking at this.

I tried it three ways:

In the Relay Browser:

I entered the mall and searched for "drive-by-shooting"
I entered the store
I made the purchase.

In the DEBUG log:

Code: 
mallstore.php?pwd&whichstore=1937905&buying=Yep.&whichitem=9396.24200&quantity=1
... response...
Processing result: drive-by shooting
Processing result:  Meat Gained: -24,200

In the session log:
Code: 
mallsearch "drive-by shooting"
mallsearch shop #1937905
mallsearch shop #1937905

I have no idea why it didn't register the mall purchase.

Ha ha ha. Actually, now I do. If you buy from within the shop, it is "buying=Yep." and from the search results (or KoLmafia), it is "buying=1".
We need to recognize either, and logging will be better.

I ran the HTML through MallPurchaseRequest.parseResponse and it registered acquisition of the drink and spending of the Meat.

I tried again using the Mall Search frame.

gCLI:

Code: 
Searching for "drive-by shooting"...
Search complete.
Purchasing drive-by shooting (1 @ 29,000) from #1937905...
Purchases complete.

Session log:

Code: 
mallsearch "drive-by shooting"
buy 1 drive-by shooting for 29000 each from shop #1937905 on 20250218

I tried again using the "buy" command:

gCLI:

Code: 
> buy 1 drive-by shooting @ 29000

Searching for "drive-by shooting"...
Search complete.
Purchasing drive-by shooting (1 @ 29,000) from #1937905...
Purchases complete.

Session log:

Code: 
mallsearch "drive-by shooting"
buy 1 drive-by shooting for 29000 each from shop #1937905 on 20250218

OK, all of the above are verifying how things are supposed to work, and what we can expect to see in the session log.
Part 2 of investigation coming up...
 
This a working example from your log:

Code: 
mallsearch "drive-by shooting"

buy 1 drive-by shooting for 22870 each from shop #1937905 on 20250209
Preference _concoctionDatabaseRefreshes changed from 62 to 63
mallsearch "Newark"

buy 1 Newark for 27986 each from shop #2417576 on 20250209
Preference _concoctionDatabaseRefreshes changed from 63 to 64

These are failures:

Code: 
mallsearch "drive-by shooting"

buy 1 drive-by shooting for 22870 each from shop #683944 on 20250209
Preference _concoctionDatabaseRefreshes changed from 2478 to 2479

buy 1 drive-by shooting for 22998 each from shop #2359293 on 20250209
Preference _concoctionDatabaseRefreshes changed from 2479 to 2480

buy 1 drive-by shooting for 22998 each from shop #1357078 on 20250209
Preference _concoctionDatabaseRefreshes changed from 2480 to 2481

etc.

It logged the purchases - and fired a concoction refresh, which should only happen when it succeeds at a purchase.
And yet, it didn't think it had actually acquired the item, and moved on to the next purchase request.

Something I noticed in part one of this investigation is that the "buy" command makes purchases with ajax=1 - i.e., it does not show you the mall store's inventory. I don't see why that should matter, but, your purchase response should have looked something like this.

mallstore.php?whichstore=1937905&buying=1&ajax=1&whichitem=9396.29000&quantity=1

HTML: 
<script type="text/javascript">top.charpane.location.href="charpane.php";</script><script type="text/javascript">if (window.updateInv) updateInv({"9396":1})</script><script type="text/javascript">if (!window.updateInv && parent.mainpane.updateInv) parent.mainpane.updateInv({"9396":1})</script><center><table  width=95%  cellspacing=0 cellpadding=0><tr><td style="background-color: blue" align=center ><b style="color: white">Results:</b></td></tr><tr><td style="padding: 5px; border: 1px solid blue;"><center><table><tr><td><center><table class="item" style="float: none" rel="id=9396&s=15&q=0&d=1&g=0&t=1&n=1&m=0&p=0&u=b"><tr><td><img src="https://d2uyhvukfffg5a.cloudfront.net/itemimages/chamflute.gif" alt="drive-by shooting" title="drive-by shooting" class=hand onClick='descitem(401865184)' ></td><td valign=center class=effect>You acquire an item: <b>drive-by shooting</b></td></tr></table></center><center><table><tr><td><img src="https://d2uyhvukfffg5a.cloudfront.net/itemimages/meat.gif" height=30 width=30 alt="Meat"></td><td valign=center>You spent 29,000 Meat.</td></tr></table></center><script type="text/javascript">if (window.update_stock) update_stock(1937905, 9396, 1);</script></td></tr></table></center></td></tr><tr><td height=4></td></tr></table></center>

and in DEBUG log:

Code: 
Processing result: drive-by shooting
Processing result:  Meat Gained: -29,000

When processing the responseText, it looks for a table:

Code: 
private static final Pattern TABLE_PATTERN = Pattern.compile("<table>.*?</table>", Pattern.DOTALL);

If it doesn't find it, it returns silently.

I see a table in that result.

HTML: 
<table><tr><td><center><table class="item" style="float: none" rel="id=9396&s=15&q=0&d=1&g=0&t=1&n=1&m=0&p=0&u=b"><tr><td><img src="https://d2uyhvukfffg5a.cloudfront.net/itemimages/chamflute.gif" alt="drive-by shooting" title="drive-by shooting" class=hand onClick='descitem(401865184)' ></td><td valign=center class=effect>You acquire an item: <b>drive-by shooting</b></td></tr></table>

MallPurchaseRequest.processItemFromMall() looks for an "item":

Code: 
  public static final Pattern ITEM_PATTERN =
      Pattern.compile(
          "<table class=\"item\".*?rel=\".*?\".*?( \\(stored in Hagnk's Ancestral Mini-Storage\\))?</td></tr></table>",
          Pattern.DOTALL);

Again, if it doesn't find it, it returns silently.

It passes the entire string to ResultProcessor:

Code: 
    ArrayList<AdventureResult> results = new ArrayList<>();
    ResultProcessor.processResults(false, result, results);

    if (results.isEmpty()) {
      // Shouldn't happen
      return null;
    }

Adding the results to inventory - and deducting Meat - happens only after this.

I conjecture that ResultProcessor is failing - rarely - and the "shouldn't happen" is, in fact, happening.
I notice that the caller does not check for a null being given to it.

I think it should check and abort.

Or perhaps processItemFromMall should force the unparseable responseText into the DEBUG log (so we can learn from it) and then abort (so we don't look for another shop to sell us what we successfully purchased.)

Or perhaps the MallPurchaseRequest should detect this failure and abort, since we don't necessarily want to enter an ABORT state if a purchase fails like this in the Relay Browser.

Or something.
 
r28371 made us abort on purchasing if we didn't obtain the item for the price we expected.
I make it write to the DEBUG log so we could understand what happened.
Yesterday, I caught such a failure.

HTML: 
<table><tr><td>This store doesn't have that item at that price.  Perhaps someone beat you to it, or the shop owner changed the price of the item while you were browsing.</td></tr></table>

Except, this is not the situation the OP ran into, since that resulted in a successful purchase.

We have code, up the call stack, which handles the situation I caught - and logged and aborted on - and moves to the next store.
Perhaps we should not abort on this case...
 
You must log in or register to reply here.
Back
Top