Bug - Fixed Mafia doesn't seem to recognise turns if charpane is slow to respond.

D

Darzil

Developer
I've noticed that I play quickly in the relay browser, so that I start a new combat before the character pane has refreshed after the last one, the session log runs the encounters together under the turn number of the first, and Visited Locations treats it all as one visit. I wonder if there something cleverer we can do than just remembering to play slower?

Code: 
[21536] The Outskirts of Cobb's Knob
Encounter: sleeping Knob Goblin Guard
Round 0: Samuel Spade wins initiative!
Round 1: Samuel Spade executes a macro!
Round 1: Samuel Spade casts ENTANGLING NOODLES!
Round 2: sleeping knob goblin guard drops 11 attack power.
Round 2: sleeping knob goblin guard drops 10 defense.
Round 2: Pickpack shakes loose a considerable quantity of spice. You conjure up a canister and collect it.
You acquire an item: spices
Round 2: sleeping knob goblin guard takes 3 damage.
Round 2: Samuel Spade casts CANNELLONI CANNON!
Round 3: sleeping knob goblin guard takes 260 damage.
Round 3: sleeping knob goblin guard drops 13 attack power.
Round 3: sleeping knob goblin guard drops 12 defense.
Round 3: sleeping knob goblin guard takes 5 damage.
Round 3: Samuel Spade wins the fight!
You gain 5 Meat
After Battle: Pickpack whirls around picking up items, like a little couscous tornado.
You acquire an item: viking helmet
You acquire an item: Knob Goblin scimitar
You gain 4 Muscleboundness
You gain 6 Wizardliness
You gain 5 Chutzpah
Encounter: Sub-Assistant Knob Mad Scientist
Round 0: Samuel Spade wins initiative!
Round 1: Samuel Spade executes a macro!
Round 1: Samuel Spade casts ENTANGLING NOODLES!
Round 2: Lil' Beak's bells jingle merrily.
Round 2: sub-assistant knob mad scientist drops 10 attack power.
Round 2: sub-assistant knob mad scientist drops 13 defense.
Round 2: Pickpack shakes loose a considerable quantity of spice. You conjure up a canister and collect it.
You acquire an item: spices
Round 2: sub-assistant knob mad scientist takes 3 damage.
Round 2: Samuel Spade casts CANNELLONI CANNON!
Round 3: sub-assistant knob mad scientist takes 130 damage.
Round 3: sub-assistant knob mad scientist takes 5 damage.
Round 3: Samuel Spade wins the fight!
You gain 6 Meat
After Battle: Pickpack whirls around picking up items, like a little couscous tornado.
You acquire an item: Knob Goblin firecracker
You gain 3 Fortitude
You gain 10 Enchantedness
You gain 3 Cheek
Encounter: Sub-Assistant Knob Mad Scientist
Round 0: Samuel Spade wins initiative!
Round 1: Samuel Spade executes a macro!
Round 1: Samuel Spade casts ENTANGLING NOODLES!
Round 2: sub-assistant knob mad scientist drops 15 attack power.
Round 2: sub-assistant knob mad scientist drops 10 defense.
Round 2: Pickpack shakes loose a considerable quantity of spice. You conjure up a canister and collect it.
You acquire an item: spices
Round 2: sub-assistant knob mad scientist takes 4 damage.
Round 2: Samuel Spade casts CANNELLONI CANNON!
Round 3: sub-assistant knob mad scientist takes 130 damage.
Round 3: sub-assistant knob mad scientist takes 3 damage.
Round 3: Samuel Spade wins the fight!
You gain 5 Meat
After Battle: Pickpack does an impression of a swarm of tiny bees dancing, directing each other to the items they've discovered.
You acquire an item: strongness elixir
You acquire an item: Knob Goblin firecracker
You gain 4 Muscleboundness
You gain 9 Magicalness
You gain 3 Sarcasm
Encounter: Sub-Assistant Knob Mad Scientist
Round 0: Samuel Spade wins initiative!
Round 1: Samuel Spade executes a macro!
Round 1: Samuel Spade casts ENTANGLING NOODLES!
Round 2: Lil' Beak's bells jingle merrily.
Round 2: sub-assistant knob mad scientist drops 10 attack power.
Round 2: sub-assistant knob mad scientist drops 15 defense.
Round 2: Pickpack shakes loose a considerable quantity of spice. You conjure up a canister and collect it.
You acquire an item: spices
Round 2: sub-assistant knob mad scientist takes 6 damage.
Round 2: Samuel Spade casts CANNELLONI CANNON!
Round 3: sub-assistant knob mad scientist takes 130 damage.
Round 3: Lil' Beak's bells jingle merrily.
Round 3: sub-assistant knob mad scientist drops 13 attack power.
Round 3: sub-assistant knob mad scientist drops 14 defense.
Round 3: sub-assistant knob mad scientist takes 3 damage.
Round 3: Samuel Spade wins the fight!
You gain 6 Meat
After Battle: Pickpack demonstrates a dance of celebration from his native land. Translated into couscous, it's basically incomprehensible.
You acquire an item: Knob Goblin firecracker
You gain 3 Strongness
You gain 7 Wizardliness
You gain 5 Smarm
Encounter: Knob Goblin Assistant Chef
Round 0: Samuel Spade wins initiative!
Round 1: Samuel Spade executes a macro!
Round 1: Samuel Spade casts ENTANGLING NOODLES!
Round 2: Pickpack shakes loose a considerable quantity of spice. You conjure up a canister and collect it.
You acquire an item: spices
Round 2: knob goblin assistant chef takes 4 damage.
Round 2: Samuel Spade casts CANNELLONI CANNON!
Round 3: knob goblin assistant chef takes 130 damage.
Round 3: knob goblin assistant chef drops 14 attack power.
Round 3: knob goblin assistant chef drops 12 defense.
Round 3: knob goblin assistant chef takes 3 damage.
Round 3: Samuel Spade wins the fight!
You gain 9 Meat
After Battle: Pickpack performs an interpretive dance on the topic of loot discovery.
You gain 6 Strengthliness
You gain 6 Mysteriousness
You gain 3 Roguishness
Casting Manicotti Meditation 1 times...
You acquire an effect: Pasta Oneness (duration: 5 Adventures)
Manicotti Meditation was successfully cast.

[21541] The Outskirts of Cobb's Knob
 
lostcalpolydude

lostcalpolydude

Developer
Staff member
Do you think there is any way of knowing whether an encounter took a turn? There are many combats and noncombats that don't take a turn, and occasionally there are encounters that take 2 or 3 turns. I don't think there's any sane way to track that. I suppose it might be possible (but probably not reasonable) to not allow any (non-chat?) requests through until the charpane finishes loading.
 
D

Darzil

Developer
Would be nice to find a way of achieving it, as this also breaks clover protection, counters etc due to Mafia not finding out which turn it is on.
 
Veracity

Veracity

Developer
Staff member
If an automated request asks for charpane.php, we ask for api.php - and we funnel all such requests through a single synchronized instance. The result of that tells us whether KoL has counted a turn.

We don't do that for RelayRequests, since those come from the browser, and if the request asks for charpane.php, the browser will ask for it. When the charpane.php response comes in, we look at various variables in it to decide if it is a fresh new charpane, and if it is, we process it.

Any method of deciding whether a turn was consumed by simply looking at the result of the request itself is a non-starter; there are many ways to use 0, 1, 2, or 3 turns, and we'd have to have them all hardcoded and accurately guess when KoL adds new contents what happened.

An alternative would be to request api.php for RelayRequests that ask for charpane.php - but still let the browser do that, obviously - and depend ONLY on api.php, no longer parsing charpane.php at all. I believe that that is what KoLproxy does.
 
Veracity

Veracity

Developer
Staff member
By the way - I am curious about why you think it is a "Bug" that KoLmafia doesn't parse charpane.php's response before it has arrived.
 
lostcalpolydude

lostcalpolydude

Developer
Staff member
Veracity said:
An alternative would be to request api.php for RelayRequests that ask for charpane.php - but still let the browser do that, obviously - and depend ONLY on api.php, no longer parsing charpane.php at all. I believe that that is what KoLproxy does.
Click to expand...

There tends to be quest information on charpane.php that isn't available from api.php that people want to see. Improved quest tracking by mafia could allow a relay override to reconstruct that information...

It also leads to people playing the first 2 days of AoSP without knowing about pete's motorcycle, or about love/hate (from what I saw in /clan). I suppose ChIT resulted in the same thing for some people (I was away from KoL for the first 3 days of the path, so lots of stuff was fixed by the time I made it back), but it isn't built in to mafia.

At most, I feel that it could be an option, defaulting to off, to always use api.php.
 
D

Darzil

Developer
Veracity said:
By the way - I am curious about why you think it is a "Bug" that KoLmafia doesn't parse charpane.php's response before it has arrived.
Click to expand...

It also appears that it doesn't parse it after it arrives, if it's started another fight ? In the example above KoLmafia in the logs at least did not notice the turns passing until it had done 5 turns and then cast a spell (which would have triggered api.php). The character panes were updating during the following fight. I don't recall this happening before the last few months, but it could just be that efficiency improvements have allowed relay browser play to be sufficiently faster for it to happen.
 
D

Darzil

Developer
lostcalpolydude said:
There tends to be quest information on charpane.php that isn't available from api.php that people want to see. Improved quest tracking by mafia could allow a relay override to reconstruct that information...

It also leads to people playing the first 2 days of AoSP without knowing about pete's motorcycle, or about love/hate (from what I saw in /clan). I suppose ChIT resulted in the same thing for some people (I was away from KoL for the first 3 days of the path, so lots of stuff was fixed by the time I made it back), but it isn't built in to mafia.
Click to expand...

I played the first day of AoSP without noticing the motorcycle, as I was using CHIT, but Love/Hate worked fine. By day two CHIT worked fine with the Motorcycle. But yes, the pitfall of relying on api.php is that it takes time for api and mafia to get updated.
 
Veracity

Veracity

Developer
Staff member
Darzil said:
It also appears that it doesn't parse it after it arrives, if it's started another fight ?
Click to expand...
When the charpane.php response comes in, we look at various variables in it to decide if it is a fresh new charpane, and if it is, we process it.
Click to expand...
charpanes often arrive out of order; we (as a proxy for the browser) can forward multiple requests to charpane.php on different request threads, KoL will respond to each of them, and when the responses come in (in whatever order the Network decides to deliver them), they are matched to the appropriate requests and the threads to handle the responses are scheduled (in whatever order your Operating System chooses). There is nothing whatsoever that we can do to change the behavior of the Network or the Operating System to prevent charpane responses from arriving out of order. We just have to do our best to make sure that we don't process a charpane that is earlier than one we have already processed. Otherwise, we will roll back turns, add back HP and MP that were previously spent, and so on.

I suggest you look at CharPaneRequest.php.processResults. There is code there to look the "timestamp" and the "turnsthisrun" variable that is inside the charpane. We use those things to determine if we've already processed a charpane which is "newer" than the one which has just arrived. If you think there is a bug there, I suggest you instrument that code. Perhaps log timestamps and turnsthisrun and log whether a charpane is processed or is dropped for being stale, as a result of those checks.
 
Veracity

Veracity

Developer
Staff member
lostcalpolydude said:
There tends to be quest information on charpane.php that isn't available from api.php that people want to see.
Click to expand...
We obviously could continue to parse the charpane - including our current checks to make sure we don't process "stale" responses - but ONLY extract information from it that is not in api.php. That will also make it crystal clear, when we add code there, what is missing from api.
 
roippi

roippi

Developer
Veracity said:
An alternative would be to request api.php for RelayRequests that ask for charpane.php - but still let the browser do that, obviously - and depend ONLY on api.php, no longer parsing charpane.php at all. I believe that that is what KoLproxy does.
Click to expand...

I know that that makes things nice and tidy from the client side, but I truly do dislike all those extra server hits for what is essentially 99%+ redundant data.

I understand that every server hit is not equal, and certainly API hits are lighter-weight than full charpane requests, but still. I like that we go the extra mile to be server friendly. My two cents.
 
Veracity

Veracity

Developer
Staff member
Yup. I'm still waiting to see any other solution that will address Darzil's complaints, though.
 
D

Darzil

Developer
We may not have exactly the issue I thought we had.

I added two lines into CharPane Request, one for outputting the response times (before the check), one for outputting the current Mafia KoLCharacter.getCurrentRun() and Charpane TurnsThisRun value (before they are compared).

As you can see, we actually get the pages back in good time, I could not play fast enough to get them out of sync, at least according to the log. However, all did not line up correctly. You can see in the following log that turn and location is not printed before the encounter, and in other logs though Mafia knows correctly which monsters I fought and how many adventures it took, it is out on how many times I visited a location. Am going to keep delving.

Code: 
[23937] The Outskirts of Cobb's Knob
Encounter: Knob Goblin Assistant Chef
Round 0: Samuel Spade wins initiative!
Last Response: 1394019961000, Response: 1394019962000
Current turns: 23936, Charpane: 23936
Round 1: Samuel Spade executes a macro!
Last Response: 1394019962000, Response: 1394019963000
Current turns: 23936, Charpane: 23936
Round 1: Samuel Spade attacks!
Round 2: knob goblin assistant chef takes 919 damage.
Round 2: knob goblin assistant chef drops 13 attack power.
Round 2: knob goblin assistant chef drops 15 defense.
Round 2: Pickpack shakes loose a considerable quantity of spice. You conjure up a canister and collect it.
You acquire an item: spices
Round 2: Samuel Spade wins the fight!
You gain 7 Meat
After Battle: Pickpack performs an interpretive dance on the topic of loot discovery.
You acquire an item: Knob Goblin pants
You gain 1 Strengthliness
You gain 2 Enchantedness
You gain 1 Cheek
Last Response: 1394019963000, Response: 1394019963000
Current turns: 23937, Charpane: 23937
Last Response: 1394019963000, Response: 1394019964000
Current turns: 23937, Charpane: 23937
Encounter: Knob Goblin Barbecue Team
Round 0: Samuel Spade wins initiative!
Last Response: 1394019964000, Response: 1394019965000
Current turns: 23937, Charpane: 23937
Round 1: Samuel Spade executes a macro!
Round 1: Samuel Spade attacks!
Round 2: knob goblin barbecue team takes 894 damage.
Round 2: Pickpack shakes loose a considerable quantity of spice. You conjure up a canister and collect it.
You acquire an item: spices
Round 2: Samuel Spade wins the fight!
You gain 11 Meat
After Battle: Pickpack performs an interpretive dance on the topic of loot discovery.
You acquire an item: bowl of cottage cheese
You acquire an item: Knob Goblin tongs
You gain 2 Strengthliness
You gain 2 Enchantedness
You acquire a bounty item: bloodstained briquette
Last Response: 1394019965000, Response: 1394019966000
Current turns: 23938, Charpane: 23938
Last Response: 1394019966000, Response: 1394019967000
Current turns: 23938, Charpane: 23938
Encounter: Sub-Assistant Knob Mad Scientist
Round 0: Samuel Spade wins initiative!
Last Response: 1394019967000, Response: 1394019968000
Current turns: 23938, Charpane: 23938
Round 1: Samuel Spade executes a macro!
Round 1: Samuel Spade attacks!
Round 2: sub-assistant knob mad scientist takes 893 damage.
Round 2: Pickpack shakes loose a considerable quantity of spice. You conjure up a canister and collect it.
You acquire an item: spices
Round 2: Samuel Spade wins the fight!
You gain 6 Meat
After Battle: Pickpack demonstrates a dance of celebration from his native land. Translated into couscous, it's basically incomprehensible.
You acquire an item: strongness elixir
You acquire an item: Knob Goblin firecracker
You gain 2 Wizardliness
You gain 2 Roguishness
Last Response: 1394019968000, Response: 1394019969000
Current turns: 23939, Charpane: 23939
Last Response: 1394019969000, Response: 1394019969000
Current turns: 23939, Charpane: 23939
 
D

Darzil

Developer
Still not there with the cause, but am finding interesting stuff.

After every relay browser fight we request and parse api.php, this always seems to result in "Processing result: Advs used: -1" in debug log. We then request and parse charpane,php as requested by the browser. Maybe we are adding more turns than we should elsewhere, and manually having to fix?

For some reason, KoLAdventure.locationLogged isn't getting set back to false if you play too quickly, so nothing relating to location logging happens, which is why you don't see [xxxxx] Location in the GCLI.

It appears that the issue occurs when you call adventure.php prior to receiving the charpane.ash response, though it could actually be prior to processing it all, as it's easier to generate this problem with a large charpane.ash file, like CHIT, though at my distance from the server I can generate it without.
 
D

Darzil

Developer
It appears that CharpaneRequest (both api and charpane bits) fires off a version of setLastAdventure that marks KoLAdventure.locationLogged as true. I'm not sure it should. I think this means it can consider the new location as logged to CLI etc if you start an adventure before parsing the post fight api and charpanes, so not log it.

Edit - of course, that just explains the logging portion of it, so isn't the whole story.
 
Last edited:
D

Darzil

Developer
Darzil said:
After every relay browser fight we request and parse api.php, this always seems to result in "Processing result: Advs used: -1" in debug log. We then request and parse charpane,php as requested by the browser. Maybe we are adding more turns than we should elsewhere, and manually having to fix?
Click to expand...

Nope, this isn't an issue at all, I was just reading it wrongly. What this is actually saying is that we have used one adventure. It is actually Adventures: -1, I think.
 
D

Darzil

Developer
Darzil said:
It appears that CharpaneRequest (both api and charpane bits) fires off a version of setLastAdventure that marks KoLAdventure.locationLogged as true. I'm not sure it should. I think this means it can consider the new location as logged to CLI etc if you start an adventure before parsing the post fight api and charpanes, so not log it.

Edit - of course, that just explains the logging portion of it, so isn't the whole story.
Click to expand...

Marking KoLAdventure.locationLogged as true was added in r13137 for the patch "Fernswarthy's Basement is an abnormal adventure zone".

If I remove it from KoLAdventure.setLastLocation() the logging issues are fixed, but I'm a little reluctant to do so while I don't know why it was added. I guess there is some other issue it fixes?
 
Veracity

Veracity

Developer
Staff member
Darzil said:
Marking KoLAdventure.locationLogged as true was added in r13137 for the patch "Fernswarthy's Basement is an abnormal adventure zone".

If I remove it from KoLAdventure.setLastLocation() the logging issues are fixed, but I'm a little reluctant to do so while I don't know why it was added. I guess there is some other issue it fixes?
Click to expand...
Well, Fernswarthy's Basement IS an abnormal adventure zone.

- You visit it and it shows you what awaits you on the current floor.
- You can leave and buff up, change outfit, what have you (or do it via the GUI, or via KoLmafia's Basement Helper) and click on the link to actually attempt the level.

I don't recall exactly, but I think it logged something like this:

[xxx] Fernswarthy's Basement (Level 53)
... details about the current test, given current buffs and equipment
... optional logging for changing the above

[xxx] Fernswarthy's Basement (level 53)
... details about the current test, given current buffs and equipment
Encounter: ... the actual test

If I recall, I wanted only the latter to show; it was not necessary to log simply visiting the basement and looking at the test.

I, too, have been seeing logging screwups. For example:

[872] The Palindome
Encounter: Racecar Bob
Round 0: Veracity wins initiative!
Round 1: Veracity attacks!
Round 2: racecar bob takes 131 damage.
Round 2: Veracity attacks!
Round 3: racecar bob takes 131 damage.
Round 3: Veracity wins the fight!
You gain 144 Meat
You acquire an item: enormous belt buckle
You acquire an item: stunt nuts
You acquire an item: ketchup hound
You gain 24 Meat.
You gain 13 Strengthliness
You gain 13 Enchantedness
You gain 27 Smarm
Encounter: Flock of Stab-bats
Round 0: Veracity wins initiative!
Round 1: Veracity attacks!
Round 2: flock of stab-bats takes 144 damage.
Round 2: Veracity attacks!
Round 3: flock of stab-bats takes 122 damage.
Round 3: Veracity wins the fight!
You gain 164 Meat
You acquire an item: batblade
You acquire an item: batgut
You gain 20 Meat.
You gain 11 Strengthliness
You gain 15 Enchantedness
You gain 30 Cheek
Click to expand...
If you want to fix the logging issues as you suggest, I encourage you to do so. I'll take a look at Fernswarthy's Basement again, once I hit aftercore again, and will see if I can come up with a better way to make it log the way I want it to log.
 
D

Darzil

Developer
I will do so. The issue appears to be that location logging is suppressed as well as last adventure being updated whenever the character pane or api status is updated, rather than just when in the basement. This doesn't really matter unless the next adventure has started, in which case it's processing is affected.
 
You must log in or register to reply here.
Top