Bug - Fixed Adventuring at The Shore causes incorrect turn tracking.

Ensiferum

Member
Mafia has been counting the first shore trip in a run as 6 turns lately. It catches up after the 3 extra turns are spent in another zone, but until then the turns a displayed incorrectly.

Not a major problem, but an account of mine had to eat a fortune cookie just after the shore trip yesterday and the result was incorrectly recorder SR counter and missed SR.

Output from the gCLI with the skipped turn numbers visible:
[267] rusty hedge trimmers
Encounter: Lost in the Great Overlook Lodge
Encounter: To Catch a Killer
Encounter: Now It's Dark
You acquire an item: gold wedding ring

[268] The Shore, Inc. Travel Agency
You acquire an item: your father's MacGuffin diary
Your father's diary has been read.
You lose 3 Adventures
You spent 500 Meat
Pulling items from storage...
Requests complete.

[274] The Shore, Inc. Travel Agency
You acquire an item: UV-resistant compass

[274] The Arid, Extra-Dry Desert
Encounter: rock scorpion

[274] The Arid, Extra-Dry Desert
Encounter: rock scorpion

[274] The Arid, Extra-Dry Desert
Encounter: swarm of fire ants

[274] The Arid, Extra-Dry Desert
Encounter: A Sietch in Time

[274] The Arid, Extra-Dry Desert
Encounter: cactuary

[275] The Arid, Extra-Dry Desert
Encounter: giant giant giant centipede

Debug log is a few posts down.
 
Last edited:

lostcalpolydude

Developer
Staff member
That debug log just says that some page didn't have a </head> tag when one was expected, which should be irrelevant.

Does this only happen for the first shore trip of an ascension? Any time I try testing this, everything works properly.
 

Ensiferum

Member
Yeah, the 3 extra turns are only added on the first shore trip in an ascension.

It seems I did upload a wrong debug log, here's the actual one:
 

Attachments

  • DEBUG_20140315.txt
    1,016.2 KB · Views: 212

lostcalpolydude

Developer
Staff member
There's CharPaneRequest.turnsThisRun and KoLCharacter.currentRun, which seem like they should be tracking the same thing. The only time either of them is updated to a value that isn't parsed from charpane/charsheet/api is in ResultProcessor, line 1070. I don't really understand that code well enough to know how it might interact with what happened for you. The choice.php override is something in your setup that I don't have, which may or may not be relevant.
 

Ensiferum

Member
Choice.php is irrelevant since the exact same thing happens in another instance of mafia that doesn't have such override.
 

Darzil

Developer
Given mafia treats it correctly after the first time, and has no code for treating the first time differently from any other time, it COULD be a KoL issue. Am going to try to remember to add some tracking code to my local mafia before I first visit the shore next ascension. Certainly adding this code shows nothing untoward on shore visits post ascension.
 

lostcalpolydude

Developer
Staff member
That adventure has
You lose 3 Adventures.
Every shore trip says that though, and not every shore trip triggers this bug (I reproduced it with my first shore trip of the run today), so it could be the timing of when the charpane is requested versus when the page is parsed. I feel like not parsing that message from that page would be a reasonable fix maybe, but the meat cost is also parsed from there, and I don't know how I would make that change anyway (ResultProcessor is confusing to me).
 

Darzil

Developer
Failed to reproduce it. You could be onto something though, if charpane processed first, and mainpane second, it could have that effect. I'm not sure how likely that is, though.

Charpane Turns: 71 Mafia Turns: 71

[72] The Shore, Inc. Travel Agency
You acquire an item: Shore Inc. Ship Trip Scrip
You lose 3 Adventures
Update turns: 74
You spent 500 Meat
You gain 41 Smarm
Charpane Turns: 74 Mafia Turns: 74
 

Ensiferum

Member
Hrm, is it possible that this bug is somehow triggered by auto-reading the diary? All the miscounts seem to occur when the first shore trip acquires the mcguffin diary - just took an early trip like Darzil and it counted fine.
 

Crowther

Active member
Hrm, is it possible that this bug is somehow triggered by auto-reading the diary? All the miscounts seem to occur when the first shore trip acquires the mcguffin diary - just took an early trip like Darzil and it counted fine.
Or by forged identification documents?
 

devjoe

New member
I've been experiencing this bug too. I had some semis tracked incorrectly because I got into a habit of, in AoSP runs, taking my first semi in the hidden temple, letting my second fall wherever, and attempting to track my third to grab an inhaler from the castle top (which I start too late to ensure the second semi can fall there, and I'm not looking for any other semis so I just wait until that semi-rare counter times out or the castle top is open before eating another fortune cookie). It happens that I'm often starting level 11 when I think to do this, but I've learned to make sure Mafia is showing the same Ronin counter as KoL before eating that cookie. [It is NOT for me right now.]

FYI, this is still happening in build 13946. Unfortunately, I already read the diary, so I can't say if it is getting out of sync when taking the first vacation (possibly only if using the link mafia provides when acquiring the forged identification documents) or if it happens when reading the diary (again possibly from the [read] link when acquiring the diary).
 

Terion

Member
Unfortunately, I already read the diary, so I can't say if it is getting out of sync when taking the first vacation (possibly only if using the link mafia provides when acquiring the forged identification documents) or if it happens when reading the diary (again possibly from the [read] link when acquiring the diary).

As far as I'm aware, mafia automatically reads the diary when you obtain it. The times I've thought to look after taking that "vacation", it's been in the text of the gCLI.
 

ereinion

Member
Doing a shore vacation seems to throw off the adventure counter

Not really sure what happened here, after taking a shore vacation, mafia seemed to think it was turn 616 instead of turn 614. The only reason I noticed was that I had a fortune cookie coming up, so I wondered why its counter had disappeared. I'm in a HC AoSP run, if that has any bearing on the issue.

Code:
[611]      The Shore, Inc. Travel Agency
You acquire an item: your father's      MacGuffin diary
Your father's diary has been read.
You lose 3      Adventures
You spent 500 Meat

[COLOR=olive]> counters[/COLOR]

Last      semirare found 184 turns ago (on turn 432) in The Haunted Pantry

Unexpired      counters:
Spookyraven Lights Out (3)

[COLOR=olive]>      refresh all[/COLOR]

Refreshing session data...
Synchronizing moon      data...
Loading character status...
Retrieving character data...
Updating      inventory...
Examining Meat in closet...
Updating closet...
Retrieving      quest data...
Retrieving familiar data...

[COLOR=olive]> [B]CURRENT[/B]:      refresh all[/COLOR]
[COLOR=olive]> [B]QUEUED 1[/B]: counters[/COLOR]

Retrieving      campground data...
Examining Meat and pulls in storage...
Updating      storage...
Visiting Hot Dog Stand in clan VIP lounge
Session data      refreshed.

[COLOR=olive]> counters[/COLOR]

Last      semirare found 181 turns ago (on turn 432) in The Haunted Pantry

Unexpired      counters:
Fortune Cookie (1)
Spookyraven Lights Out (6)
 

Veracity

Developer
Staff member
I just did a shore trip through the relay browser with debug logging on. Here's some info I extracted from the log:

Code:
GET /adventure.php?snarfblat=355 HTTP/1.1
Requesting: http://www.kingdomofloathing.com/adventure.php?snarfblat=355
Retrieved: http://www.kingdomofloathing.com/adventure.php?snarfblat=355
HTTP/1.1 302 Found
Location: choice.php?forceoption=0
GET /choice.php?forceoption=0 HTTP/1.1
Requesting: http://www.kingdomofloathing.com/choice.php?forceoption=0
Retrieved: http://www.kingdomofloathing.com/choice.php?forceoption=0
HTTP/1.1 200 OK
POST /choice.php HTTP/1.1
Requesting: http://www.kingdomofloathing.com/choice.php?pwd&whichchoice=793&option=2
Retrieved: http://www.kingdomofloathing.com/choice.php?pwd&whichchoice=793&option=2
You lose 3 Adventures
Processing result:  Advs Used: -3
HTTP/1.1 200 OK
GET /charpane.php HTTP/1.1
Requesting: http://www.kingdomofloathing.com/charpane.php
GET /charpane.php HTTP/1.1
Requesting: http://www.kingdomofloathing.com/charpane.php
Retrieved: http://www.kingdomofloathing.com/charpane.php
Field: Date = [Mon, 30 Jun 2014 19:25:02 GMT]
var turnsthisrun = 458136
HTTP/1.1 200 OK
Retrieved: http://www.kingdomofloathing.com/charpane.php
Field: Date = [Mon, 30 Jun 2014 19:25:02 GMT]
var turnsthisrun = 458136
HTTP/1.1 200 OK
The timestamps and "turnsthisrun" are used by CharPaneRequest to decide if this charpane is out of order.

For some reason, the browser is asking for the charpane twice. KoLmafia dutifully passes on those requests and processes both responses.

Note that we get the result of the shore trip and process the "You lose 3 adventures" from it - which updates KoLmafia's idea of turns spent this run - and then we process two charpanes, neither of which is rejected. What do we do with the adventures we parse from the charpane?

Code:
		ResultProcessor.processAdventuresUsed( turnsThisRun - mafiaTurnsThisRun );
Since turnsThisRun == mafiaTurnsThisRun, this will do nothing.

Similarly, if you automate, when the response to the vacation comes back, we call api.php and do this:

Code:
		int turnsThisRun = JSON.getInt( "turnsthisrun" );
...
			int mafiaTurnsThisRun = KoLCharacter.getCurrentRun();
			ResultProcessor.processAdventuresUsed( turnsThisRun - mafiaTurnsThisRun );

Now, if we received a charpane response after we submitted the choice to take the vacation but before we got the response which happened to already have the updated turn counter in it, we would deduct 3 adventures when we process the charpane and then deduct 3 more when we process the response to the vacation, which would be consistent with this report. But, why would we have an asynchronous request to fetch the charpane?

If we assume that the user didn't bang on the "refresh" button on the GUI (which submits an api.php request), the only thing I can guess is something coming from chat. So, lets's see if I can force something like that:

Code:
GET /newchatmessages.php?lasttime=0000000102&afk=0 HTTP/1.1
Requesting: http://www.kingdomofloathing.com/newchatmessages.php?lasttime=1380310296&pwd
Retrieved: http://www.kingdomofloathing.com/newchatmessages.php?lasttime=1380310296&pwd
<font color=green><a class=nounder target=mainpane href=showplayer.php?who=121572><b>Veracity</b></a> has fortified you with the Empathy of the Newt. (15 Adventures)</font><br><!--lastseen:1380310304-->
Requesting: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
Retrieved: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
HTTP/1.1 200 OK
Yes, indeed. My multi was logged into KoLmafia with debug logging. I logged directly in to a browser and buffed her. We got the chat message and requested api.php. That happens in ChatManager.processEvent. It will do that any time it gets what it thinks is an "event" (something it will display in green) which has the word " has " in it.

We have had similar issues with parsing Meat, I think, if we deduct Meat from a response and also from the charpane.

I'll have to think about this.
 

Veracity

Developer
Staff member
And after all that analysis, just looking at the DEBUG log from higher in this thread that had the shore trip that netted the diary showed me this:

Code:
Requesting: http://www.kingdomofloathing.com/choice.php?pwd&whichchoice=793&option=1
Retrieved: http://www.kingdomofloathing.com/choice.php?pwd&whichchoice=793&option=1
You acquire an item: your father's MacGuffin diary
Processing result: your father's MacGuffin diary
Processing result: forged identification documents (-1)
Requesting: http://www.kingdomofloathing.com/diary.php?textversion=1
(contains Javascript to refresh the charpane)
Requesting: http://www.kingdomofloathing.com/api.php?what=status&for=KoLmafia
Processing result:  Advs Used: -3
Your father's diary has been read.
Parsing result: You lose 3 Adventures
You lose 3 Adventures
Processing result:  Advs Used: -3
Parsing result: You spent 500 Meat
You spent 500 Meat
Processing result:  Meat Gained: -500
When we gain the diary, the response text has "You gain an item" BEFORE "You lose 3 Adventures".
We read the diary and the response to that asks for a charpane refresh - which we do via api.php.
That adjusts your turn counter by 3.
And then "You lose 3 adventures" does it by 3 again.

So, yeah - asynchronous charpane stuff is still a possibility, but, sure enough, it's the diary adventure that screws things up every time.

I have several weeks more of aftercore activities before I ascend again, so I won't be able to test a fix for quite a while. But I'll see what I can come up with. This bug report has been open for months, anyway. :-/
 

Veracity

Developer
Staff member
I forgot to deal with this when I got the diary this run - and I noticed that I missed the following semirare. Not good.

The problem is that when we read the diary, KoL asks for a charpane update, which we satisfy with a call to api.php, in the middle of result processing and before we handle the "You lose 3 Adventures" line.

Revision 14288 auto-reads the diary using a RelayRequest rather than a GenericRequest. RelayRequest is what we use for requests from the browser and for ASH visit_url calls. Even if the result comes back indicating that KoL thinks we should refresh the charpane, we do not do so, since the browser or the ASH script will do that if it wants. In this case, we don't want. ;)

Untested. I'll be back in about 5 days, probably.
 
Top