Bug - Fixed Mafia automatically using custom combat macro

fredg1

Member
--Fighting using the Relay browser

--Combat Action bar enabled (may not be relevant)


When chaining multiple fights, if some of them (not even all of them!) were done using a Custom Combat Script (from the "Script" button, at the left of the Combat Action Bar, the shiny watch that turns to "again" once the fight is over), mafia will sometimes, at the start of a fight, just KNOW that you DEFINITELY will use the CCS again this fight and decides to BENEVOLENTLY do it for you, before you lift a finger.

It is easy to know when this occurs as you then get the "Not in a Fight" message... As well as noticing you are now beaten up, in most cases.

When the custom combat script is summoned normally:
Code:
[34091] Dreadsylvanian Woods
Preference lastEncounter changed from Boilfur, Biter of Sloths to Voice of The Icy Vacuum Of Space
Encounter: Voice of The Icy Vacuum Of Space
Preference _lastCombatStarted changed from 20190909013731 to 20190909014303
Round 0: fredg1 wins initiative!
You acquire an effect: Chilled to the Bone (1)
Preference chilledToTheBone changed from 0 to 3
Round 1: Tollace is looking a little thin.
Round 1: fredg1 executes a macro!
Round 1: fredg1 attacks!
Round 2: cold bugbear takes 412 damage.
Round 2: You lose 24 hit points
Round 2: cold bugbear takes 14 damage.
Round 2: You lose 11 hit points
Round 2: fredg1 attacks!
Round 3: cold bugbear takes 399 damage.
Round 3: You lose 15 hit points
Round 3: fredg1 attacks!
Round 4: cold bugbear takes 408 damage.
Round 4: An old Dreadsylvanian grandma gives you 2 kisses on the cheek.
Round 4: fredg1 wins the fight!
After Battle: Tollace hops around, dancing a jig accompanied by wet squelching noises.
After Battle: An old Dreadsylvanian grandma gives you 2 kisses on the cheek.
After Battle: You gain 33 Strengthliness
After Battle: You gain 44 Mysteriousness
After Battle: You gain 108 Cheek
You acquire an item: stick of firewood
Preference _boomBoxFights changed from 6 to 7
Preference chilledToTheBone changed from 3 to 0

When it acts on its own:
Code:
[34090] Dreadsylvanian Woods
Preference lastEncounter changed from Blood of Flamethrowers to Boilfur, Biter of Sloths
Encounter: Boilfur, Biter of Sloths
Preference _lastCombatStarted changed from 20190909013720 to 20190909013728
Strategy: C:\Users\(expunged)\Kolmafia\ccs\default.ccs [default]
Round 0: fredg1 wins initiative!
Round 1: Tollace is just skin and bones. Well, slime and slime, technically, but still -- you should feed him!
Round 1: fredg1 executes a macro!
Round 1: fredg1 casts WEAPON OF THE PASTALORD!
Cannot find monster.
Preference _lastCombatStarted changed from 20190909013728 to 20190909013731
Strategy: C:\Users\(expunged)\Kolmafia\ccs\default.ccs [default]
Round 0: fredg1 loses initiative!
Round 0: fredg1 attacks!
KoLmafia thinks it is round 1 but KoL thinks it is round 2
Round 2: takes 13 damage.
Round 2: fredg1 attacks!
Round 3: takes 155 damage.
Round 3: You lose 25 hit points
Round 3: takes 5 damage.
Round 3: You lose 290 hit points
[...]
Round 14: fredg1 attacks!
Round 15: takes 149 damage.
Round 15: You lose 11 hit points
Round 15: takes 3 damage.
Round 15: You lose 290 hit points
(dead)

The fact those examples come from dreadsylvania is completely irrelevant; it happened in other locations.
 
Last edited:

Veracity

Developer
Staff member
What do you mean by “chaining multiple fights”?
I could not understand what happened in the second fight.
 

fredg1

Member
Actually, it instead seems like "it" always has a chance to occur the fight right after you used a custom combat macro (maybe it's tied to entering another fight too quickly?).

As for what happened:

[34090] Dreadsylvanian Woods
Encounter: Boilfur, Biter of Sloths
Preference _lastCombatStarted changed from 20190909013720 to 20190909013728 <--- Combat initiated
Strategy: C:\Users\(expunged)\Kolmafia\ccs\default.ccs [default] <--- "The glitch"


Round 0: fredg1 wins initiative! <--- Me selecting "weapon of the pastalord" on the combat action bar, followed by mafia processing it...
Round 1: Tollace is just skin and bones. Well, slime and slime, technically, but still -- you should feed him!
Round 1: fredg1 executes a macro!
Round 1: fredg1 casts WEAPON OF THE PASTALORD!
Cannot find monster. <--- ... but the monster was already dealt with? What??



Preference _lastCombatStarted changed from 20190909013728 to 20190909013731 <--- from here on, it's mafia telling what happened during the fight as a result of the (unwanted) macro; "the glitch"
Strategy: C:\Users\(expunged)\Kolmafia\ccs\default.ccs [default]
Round 0: fredg1 loses initiative!
Round 0: fredg1 attacks!
KoLmafia thinks it is round 1 but KoL thinks it is round 2
Round 2: takes 13 damage.
Round 2: fredg1 attacks!
Round 3: takes 155 damage.
Round 3: You lose 25 hit points
Round 3: takes 5 damage.
Round 3: You lose 290 hit points
[...]
Round 14: fredg1 attacks!
Round 15: takes 149 damage.
Round 15: You lose 11 hit points
Round 15: takes 3 damage.
Round 15: You lose 290 hit points
(dead)



What is in dark red is from my attempt at progressing the fight, the rest was mafia acting on is own (and apparently against part of itself)
 

Veracity

Developer
Staff member
The "Cannot find monster." message is printed when we are top-level processing a fight response for the first time and cannot find either a "monpic" or "monname" node.
Post a DEBUG log showing the previous fight and the "glitch" fight.

What prints this?

Preference _lastCombatStarted changed from 20190909013720 to 20190909013728
 

fredg1

Member
What prints this?

Preference _lastCombatStarted changed from 20190909013720 to 20190909013728

Not sure of what you want to know, but will try to tell what I think may be it...


General => - Session Logs => Log preference changes

This is a preference indicating the last time a fight started, which means the last fight started at 2019/09/09 01:37:28 (doesn't seem to match my PC's clock, must be universal)

I checked and during the last fight, i saw the line "Preference _lastCombatStarted changed from 20190909013713 to 20190909013720", so it should mean that this glitch isn't about the fight "dragging on" onto the next one (thought that maybe using a script, then quickly starting another fight made it so the script was used in the 2nd fight because it "was still the script from the previous fight")


The fact the preference changed twice basically means that mafia processed what it thought was two different fights, here.

Post a DEBUG log showing the previous fight and the "glitch" fight.

Since this glitch isn't extremely consistent, the debug log may contain a handful of fights, but will try my best (I think it's based on quickly starting a new fight, so i won't really have the time to "check if the glitch happened"; the result may be a bit... lengthy, will try to trim).
 

fredg1

Member
Ok, so while I didn't get the same thing as before, I did get something interesting (for now).
First, let me say, making the debug log go from 6566KB to 641KB took FOREVER ;-; (contains 2 fights + some leeway both ways since i don't really know up to where it's important)

Something that I thought of was that, somehow, the "glitch" (Auto-macro/Cannot find the monster/you-are-not-in-a-fight) only occurred when I DIDN'T want to use a custom combat macro. It can't just be a coincidence, right?
Interestingly enough, after trying to get the glitch to come out for a while (19 fights), I went through the GCLI, and wouldn't you know it:

Code:
[34699] Dreadsylvanian Castle <--  6th fight, things go normally on this one (including it since the DEBUG log will also contain it)
Preference lastEncounter changed from Prisoner #205173: "Gropin' Humerus" McDonald to Baron Dorian Lickmaw
Encounter: Baron Dorian Lickmaw
Preference _lastCombatStarted changed from 20190910063729 to 20190910063736
Round 0: fredg1 wins initiative!
Round 1: You lose 1 hit point
Round 1: Tollace is just skin and bones. Well, slime and slime, technically, but still -- you should feed him!
Round 1: fredg1 executes a macro!
Round 1: fredg1 attacks!
Round 2: sleaze vampire takes 6435 damage.
Round 2: A Dreadsylvanian grandpa gives you a kiss on the cheek. Must be one of those foreign things.
Round 2: fredg1 wins the fight!
After Battle: Tollace hops around, dancing a jig accompanied by wet squelching noises.
After Battle: A Dreadsylvanian grandpa gives you a kiss on the cheek. Must be one of those foreign things.
After Battle: You gain 30 Beefiness
After Battle: You gain 65 Enchantedness
After Battle: You gain 81 Sarcasm
Preference _boomBoxFights changed from 4 to 5

[34700] Dreadsylvanian Castle
Preference lastEncounter changed from Baron Dorian Lickmaw to Prisoner #232169: "Ashy Backbone" Stewart
Encounter: Prisoner #232169: "Ashy Backbone" Stewart
Preference _lastCombatStarted changed from 20190910063736 to 20190910063743
Strategy: C:\Users\Sophie\Desktop\Kolmafia\ccs\default.ccs [default]    <--- THERE we go!!
Round 0: fredg1 wins initiative!
Round 1: You lose 5 hit points
Round 1: Tollace is looking a little thin.
Round 1: fredg1 executes a macro!
Round 1: fredg1 attacks!
Round 2: hot skeleton takes 6428 damage.
Round 2: A grateful Dreadsylvanian baby gives you a kiss on the cheek, which is adorable.
Round 2: fredg1 wins the fight!
After Battle: Tollace hops around, dancing a jig accompanied by wet squelching noises.
After Battle: A grateful Dreadsylvanian baby gives you a kiss on the cheek, which is adorable.
After Battle: You gain 43 Muscleboundness
After Battle: You gain 42 Magicalness
After Battle: You gain 94 Roguishness
Preference _boomBoxFights changed from 5 to 6

I don't know if that's a line that comes up when adventuring automatically, but that "strategy: ---" line NEVER comes up when adventuring manually: this IS the glitch.

The reason it didn't trigger that "double fight" thing seems to be because during the fight where the glitch occurred, I chose to use a CCS anyway, so I guess there was no conflict and things went on normally.
That's it--a CONFLICT. What happened previously (the dual fight/cannot find monster/you are not in a fight) must be because mafia is basically trying to use two actions at the same time against the same monster; it is simply a result of "the glitch", not the glitch itself; the glitch is mafia preemptively thinking it knows what you want to do, shown by "Strategy: [path]".


Overall, this means that if I'd want to go further and replicate exactly what first happened, I'd need to constantly alternate between CCS, action, CCS, action, CCS, action, CCS, action...
 

Attachments

  • DEBUG_20190910(trimmed).txt
    640.6 KB · Views: 17
Last edited:

Veracity

Developer
Staff member
I've been busy working on my support for choice adventures with extra parameters.
Is that a problem? :)
 

Veracity

Developer
Staff member
I downloaded your log.

Please keep in mind that my looking at your log will happen when I choose to use my precious free unpaid time to do so.

I'll look at at it, by and by, but it will fit into my own schedule, rather than yours.
 

heeheehee

Developer
Staff member
That strategy line _is_ supposed to be printed if Mafia handles your combat for you, so I'm not sure that debug log is meaningful.

(To limit its impact if the bug still exists, you may consider setting your CCS to "abort" or something like that; that way, if you catch it in action, you won't die or anything.)

Have you seen this particular issue in the past few days? What day was the session log excerpt in the OP from?
 

fredg1

Member
I was just worried that the inactivity could have been due to something else than schedules, didn't want to be rude :(
Better ask and end up being wrong than being right and never knowing; that's anxiety for you...


That strategy line _is_ supposed to be printed if Mafia handles your combat for you.
But this is using the relay browser, in which I've never been able to get this line (without it meaning this glitch occured). Just take the log from my previous post as proof/support of my point: both fights were done the same way: entering it using the Adventure Again link, then using a CCS by clicking the custom button (drawn out with Preferences => Look & Feel => Relay Browser => Add custom buttons to the top of fight pages (or does it not matter and that button is always there when using the Combat Action Bar?))
Not copying all of this; just use the blue arrow on the right to see the post >>
It's possible to see the absence of this line during the 1st fight, but it IS there during the 2nd one, before the initiative was even checked!


Have you seen this particular issue in the past few days? What day was the session log excerpt in the OP from?
I remember seeing this issue... half a year? a year ago? I immediately understood it was linked with using the CCS from the relay browser, so it made me not use it for the longest time, which was the only reason I didn't see it until then, when I tried using CCSs again.

I submitted this bug report containing this session log the same day as it occured.
 

heeheehee

Developer
Staff member
But this is using the relay browser, in which I've never been able to get this line (without it meaning this glitch occured). Just take the log from my previous post as proof/support of my point: both fights were done the same way: entering it using the Adventure Again link, then using a CCS by clicking the custom button (drawn out with Preferences => Look & Feel => Relay Browser => Add custom buttons to the top of fight pages (or does it not matter and that button is always there when using the Combat Action Bar?))
Ah, my bad. I struggled to parse the line "I went through the GCLI". I suppose if you actually do want to try using the CCS, then my workaround isn't relevant for your situation.

It's possible to see the absence of this line during the 1st fight, but it IS there during the 2nd one, before the initiative was even checked!
Yeah. The "Strategy: " line indicates that Mafia saw Round 0 and FightRequest.isAutomatingFight is true. Maybe we're somehow not clearing the state between these invocations? FightRequest doesn't seem to do any synchronization, so if this is called from two threads at the same time, the code could get into an unintended state.

I remember seeing this issue... half a year? a year ago? I immediately understood it was linked with using the CCS from the relay browser, so it made me not use it for the longest time, which was the only reason I didn't see it until then, when I tried using CCSs again.

I submitted this bug report containing this session log the same day as it occured.

By "this particular issue", I should have clarified I was referring to the "Cannot find monster" line, which had been reported as fixed elsewhere in the bug.

The debug log containing a bunch of formatted HTML inline is admittedly weird.
Code:
[34699] Dreadsylvanian Castle
Preference lastEncounter changed from Prisoner #205173: "Gropin' Humerus" McDonald to Baron Dorian Lickmaw
Encounter: Baron Dorian Lickmaw
Preference _lastCombatStarted changed from 20190910063729 to 20190910063736
Round 0: fredg1 wins initiative!
<td>
  <center>
    <table>
      <tbody>
        <tr>
          <td>
            <div id="monsterpic" style="position: relative;">
              <img id="monpic" src="https://s3.amazonaws.com/images.kingdomofloathing.com/adventureimages/dvsleazevamp2.gif" width="100" height="100">
          <td valign="center">
            You're fighting
            <span id="monname">
              Baron Dorian Lickmaw
...

(I don't have time to look deeply into this myself, just sharing my observations in case another dev finds them helpful)
 

fredg1

Member
Yeah. The "Strategy: " line indicates that Mafia saw Round 0 and FightRequest.isAutomatingFight is true. Maybe we're somehow not clearing the state between these invocations? FightRequest doesn't seem to do any synchronization, so if this is called from two threads at the same time, the code could get into an unintended state.

This may actually be it.

Reproducing this glitch definitely requires/involves quickly starting a new fight as fast as possible, so maybe the fight is started before mafia has a chance to clear the state of isAutomatingFight?
 

Veracity

Developer
Staff member
Here's how the Relay Browser works:

You click something in your browser
The browser submits a request to KoLmafia
(There can be multiple pending requests. Each runs in its own thread.)
KoLmafia forwards the request to KoL
(The thread blocks waiting for KoL's response)
KoLmafia processes the response, updates internal game state, decorates the response, etc.
The decorated response is send down to the browser
(The thread dies.)

There are a few cases where KoLmafia will do multiple request/response to KoL before responding the the browser. Automating choice adventures, for example: the "auto" button will follow a chain of choices, responding with the configures decisions for each, or the "Go To Goal" button. That is not the case for Fights: the "script" button looks up your CCS and generates a macro for it, which is the single request it sends to KoL. The exception is probably CCS calling consult scripts: it will generate a macro of actions up to the consult script, will then call the ASH script, which will make requests/response, and when the consult script ends, if the fight is still going on, it will make a macro for the rest of the CCS section. Only after all of that will it respond to the browser.

I have not yet looked at your log. I have to go paint my porch. I'll look at the log this evening. But from what you descibe, I'll bet you anything that the "glitch" was a result of you clicking twice on the "script" button. The browser accepts both clicks and generates a "fight.php?action=script" request to KoLmafia. KoLmafia accepts each request in a separate thread, generates a macro, and submits to KoL. KoL responds with one - we start processing - KoL responds to the other - and we start processing while the first is munging the fight data. As heeheehee said, we do not synchonize on that data.

We could, but I want to understand what, exactly, KoL responded with. I'll bet the second response is a "You don't seem to be in a fight. Perhaps you killed that monster? If so, congratulations".

I need to look at the log and understand when and how the "start new fight" - i.e., the adventure.php request which redirects to fight.php - came in and why that did not seem to log correctly as a new encounter. I'll look at the log and figure this out. But I am quite sure you had an extra click on "script", rather than having your click on "again", somehow, automatically choosing to automate. You don't even SEE the "again" button until KoLmafia has responded to the browser with the response to the (finished) fight. At that time, the fight data has been cleared out and initialized, since the fight is over.

Later.
 

Veracity

Developer
Staff member
And I see no evidence of a double click. Sorry.

Code:
GET /adventure.php?snarfblat=340 HTTP/1.1
class net.sourceforge.kolmafia.request.RelayRequest
Requesting: https://www.kingdomofloathing.com/adventure.php?snarfblat=340
...
Retrieved: https://www.kingdomofloathing.com/adventure.php?snarfblat=340
Field: Location = [fight.php?ireallymeanit=1568097457]
...
HTTP/1.1 302 Found
Date: Tue Sep 10 02:37:36 EDT 2019
Server: KoLmafia v19.7
Location: fight.php?ireallymeanit=1568097457
...
GET /fight.php?ireallymeanit=1568097457 HTTP/1.1
class net.sourceforge.kolmafia.request.RelayRequest
Requesting: https://www.kingdomofloathing.com/fight.php?ireallymeanit=1568097457
...
Retrieved: https://www.kingdomofloathing.com/fight.php?ireallymeanit=1568097457

[34699] Dreadsylvanian Castle
Preference lastEncounter changed from Prisoner #205173: "Gropin' Humerus" McDonald to Baron Dorian Lickmaw
Encounter: Baron Dorian Lickmaw
Preference _lastCombatStarted changed from 20190910063729 to 20190910063736
Round 0: fredg1 wins initiative!
Parsing result: You lose 1 hit point
Round 1: You lose 1 hit point
Processing result:  HP: -1
Round 1: Tollace is just skin and bones. Well, slime and slime, technically, but still -- you should feed him!
...
HTTP/1.1 200 OK
Content-Length: 30763
...
GET /fight.php?action=custom HTTP/1.1
class net.sourceforge.kolmafia.request.FightRequest
HTTP/1.1 302 Found
Location: /fight.php?action=script

Round 1: fredg1 executes a macro!
Requesting: https://www.kingdomofloathing.com/fight.php?action=macro&macrotext=%0A%0A%0Amark+mafiafinal%0Aattack%0Agoto+mafiafinal
...
GET /fight.php?action=script HTTP/1.1
...
Retrieved: https://www.kingdomofloathing.com/fight.php?action=macro&macrotext=%0A%0A%0Amark+mafiafinal%0Aattack%0Agoto+mafiafinal

Round 1: fredg1 attacks!
Round 2: sleaze vampire takes 6435 damage.
Round 2: A Dreadsylvanian grandpa gives you a kiss on the cheek. Must be one of those foreign things.
Round 2: fredg1 wins the fight!
After Battle: Tollace hops around, dancing a jig accompanied by wet squelching noises.
After Battle: A Dreadsylvanian grandpa gives you a kiss on the cheek. Must be one of those foreign things.
Parsing result: You gain 30 Beefiness
After Battle: You gain 30 Beefiness
Processing result:  Substats: 30 / 0 / 0
Parsing result: You gain 65 Enchantedness
After Battle: You gain 65 Enchantedness
Processing result:  Substats: 0 / 65 / 0
Parsing result: You gain 81 Sarcasm
After Battle: You gain 81 Sarcasm
Processing result:  Substats: 0 / 0 / 81
Preference testudinalTeachings changed from 171:0|267:4|168:5|18:2|59:4|69:4|102:3|271:1|272:1|172:4|112:3|262:4|116:1|104:4|198:4|89:0|261:2|109:0|-1:4|268:2|173:1|274:3|114:1 to 171:0|267:4|168:5|18:2|59:4|69:4|102:3|271:1|272:1|172:4|112:4|262:4|116:1|104:4|198:4|89:0|261:2|109:0|-1:4|268:2|173:1|274:3|114:1
Preference _boomBoxFights changed from 4 to 5
...
class net.sourceforge.kolmafia.request.ApiRequest
Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
Processing result:  Advs Used: -1
...
HTTP/1.1 200 OK
...
GET /adventure.php?snarfblat=340 HTTP/1.1
class net.sourceforge.kolmafia.request.RelayRequest
Requesting: https://www.kingdomofloathing.com/adventure.php?snarfblat=340
Retrieved: https://www.kingdomofloathing.com/adventure.php?snarfblat=340
Field: Location = [fight.php?ireallymeanit=1568097463]
...
HTTP/1.1 302 Found
Location: fight.php?ireallymeanit=1568097463
...
GET /fight.php?ireallymeanit=1568097463 HTTP/1.1
class net.sourceforge.kolmafia.request.RelayRequest
Requesting: https://www.kingdomofloathing.com/fight.php?ireallymeanit=1568097463
Retrieved: https://www.kingdomofloathing.com/fight.php?ireallymeanit=1568097463
ResponseText has 31403 characters.

[34700] Dreadsylvanian Castle
Preference lastEncounter changed from Baron Dorian Lickmaw to Prisoner #232169: "Ashy Backbone" Stewart
Encounter: Prisoner #232169: "Ashy Backbone" Stewart
Preference _lastCombatStarted changed from 20190910063736 to 20190910063743
Strategy: C:\Users\Sophie\Desktop\Kolmafia\ccs\default.ccs [default]
Round 0: fredg1 wins initiative!
Parsing result: You lose 5 hit points
Round 1: You lose 5 hit points
Processing result:  HP: -5
Round 1: Tollace is looking a little thin.
...
HTTP/1.1 200 OK
Content-Length: 30457
...
class net.sourceforge.kolmafia.request.FightRequest
Round 1: fredg1 executes a macro!
Requesting: https://www.kingdomofloathing.com/fight.php?action=macro&macrotext=%0A%0A%0Amark+mafiafinal%0Aattack%0Agoto+mafiafinal
Retrieved: https://www.kingdomofloathing.com/fight.php?action=macro&macrotext=%0A%0A%0Amark+mafiafinal%0Aattack%0Agoto+mafiafinal
Round 1: fredg1 attacks!
Round 2: hot skeleton takes 6428 damage.
Round 2: A grateful Dreadsylvanian baby gives you a kiss on the cheek, which is adorable.
Round 2: fredg1 wins the fight!
...
class net.sourceforge.kolmafia.request.ApiRequest
Requesting: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
Retrieved: https://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
Processing result:  Advs Used: -1
...
GET /fight.php?action=custom HTTP/1.1
HTTP/1.1 302 Found
Location: /fight.php?action=script
...
GET /fight.php?action=script HTTP/1.1
HTTP/1.1 200 OK
The browser did, in fact, request fight.php?ireallymeantit to initiate the fight and KoLmafia did, in fact automate the fight with no additional request from the browser. And THEN you clicked on the "script" button, but the fight was already finished and we responded with nothing.

I'll look at the code in GenericRequest/FightRequest, by and by.
 

fredg1

Member
But I am quite sure you had an extra click on "script", rather than having your click on "again", somehow, automatically choosing to automate. You don't even SEE the "again" button until KoLmafia has responded to the browser with the response to the (finished) fight.

There's just one problem with this: I am not initiating new fights using the "again" button, I use the "Adventure Again (<zone name>)" link at the bottom of the fight page, which actually mean that I DO see KoLmafia's response to the browser with the response to the (finished) fight.

A double input of "script" could explain the glitch, yes, but I don't actually see HOW it would've happen.

(edit: wouldn't you know it, you were faster than me)
 
Last edited:
Top