Bug stash refreshing 1000+ times

AlbinoRhino

AlbinoRhino

Active member
I've been experiencing a strange issue the last couple of days.

This folder:
https://drive.google.com/open?id=1trpckPkg726VcCoGQVd4XNQZTxi0FRYG

contains 2 debug logs which were both produced in this way,

Start Debug Log
Tools > Refresh session
Stop Debug Log

The first log (labeled as 'full' in the file name) is ~45 MB was made with all of the options in Preferences > Extra Debugging enabled.

In an effort to reduce the log file size, I disabled the option "Verbosely log communication between KoLmafia and browser" and ran the test again (labeled, as 'non_verbose' in the file name). This log was ~50 MB. So! :rolleyes:

If there is some way I can make a less lengthy log for you please advise me of the procedure to make it.


In any event, in the first log (full):
The line "Refreshing stash contents..." appears 1061 times according to Notepad++.
The line "Requesting: https://www.kingdomofloathing.com/clan_stash.php" appears 1053 times.

The second log is similar.

I'm not sure what is triggering this behavior but it seems to appear later in a session (perhaps, after switching clans a few times?). However, once it starts I am able to reproduce it with the "Refresh session" link.

Maybe a static variable somewhere getting set false/true and never being set back?

Interestingly, executing the line "ash refresh_stash()" in the cli does NOT trigger this behavior and behaves normally.

Obviously, this can take several minutes to reproduce, but eventually it does resolve itself and mafia's final idea of the stash contents seems accurate.

One other thing I noted was that trying to interrupt this behavior by mashing the ESC key one, or more, times, seems to leave mafia in an unresponsive state. IE, I had to exit and restart. Or, perhaps I was too impatient to wait long enough. I also noted that memory usage (I use the javaw.exe) appeared totally normal while this is going on.
 
After just watching my rollover script run, I have some more observations. I am thinking that multiple clan changes during the execution of a single script may be what is triggering this.

My rollover script hopped to BAFH to collect a buff and that transition happened normally. Then it hopped back to my home clan and the multiple refreshing happened. A bit later in the script it hopped back to BAFH to collect the free MP from the shower and the multiple refreshing happened for what appeared even more times...and then a fourth hop back home and the multiple refreshing happened for what appeared even more times. (ie Each transition seemed to cause a greater number of stash refreshes.) I can't be more specific because I can't scroll back the cli far enough to see all of these transitions again. And the session log didn't capture them at all (it just reflects a normal switching of clans.)

These clan transitions are accomplished via Bale's old clanhop script which is around here somewhere.
 
Last edited:
So, I guess this is something thread related involving types of Java functions that go over my head.

Essentially it appears to create (and register) 1000's of stash requests, and then it submits them to KOL. We don't mark stash as received until the first reply.

Maybe we need to set a refreshingStash flag in when we create a stash refresh request, clear it upon parsing stash, and check for it before running a request ?
 
It seems above my head as well. Another observation, is that changing clans through the browser didn't trigger it. Maybe that doesn't cause a stash request? But "Refresh Session" still will. I dunno? The only thing I can think of that might be submitting a ton of requests is the chat panel? I did recently add that to "open in tabs" in mafia config. I think I closed that tab when I made the debug logs? To reduce noise.

I was actually kind of surprised that, with the preoccupation with conserving server hits, that any duplicate request like that was allowed through so many times in such a short period. Probably things I'm not considering though.

This is a recent development and I have been racking my brain to think if I've changed anything important. We did lose power a couple of times recently...and mafia was open, but idle. Maybe a setting of some kind could have got borked?
 
AlbinoRhino said:
I was actually kind of surprised that, with the preoccupation with conserving server hits, that any duplicate request like that was allowed through so many times in such a short period.
Click to expand...

My recollection is that clan hopping has always been dicey with mafia, in the sense that there was once difficulty in detecting that it was happening and spamming the server with "what is my clan?" requests was never a solution. Consequently I am not surprised that something weird happens with a lot of hopping.

Reveling in ignorance derived from not looking at the code (but I hope to soon) I wonder whether some kind of lazy initialization for the stash would work? Conceptually mafia only needs the contents of the stash for "item" functions so rather than fetch the contents when a clan is entered, the contents are fetched when they are first needed.

I can also imagine some kind of baroque, over-engineered scheme where an on going clan change blocks (or cancels) outstanding stash requests OR an outstanding clan request blocks a clan change.

And there may be something "fundamental" that could/should be revisited to better support clan hopping.
 
Well....if I am the only one experiencing it, then it makes me think there is something local that has gotten borked. But, if Refresh Session will trigger it, then I guess my ASH scripts aren't involved. If there is some setting involved, then I'm unaware of it. Just weird.
 
I don't have much useful to add, since I just returned from vacation, but Easyfax is having trouble and it does multiple clan hops in a single script. My trouble is that the fax machine sometimes isn't seen.
 
I did a quick look. Everything dealing with clans goes through ClanManager. That is an abstract class and everything of significance is static. This means you can only deal with one clan at a time and anything that is pending and not aborted or not explicitly cleared when clans are changed has the potential to bleed over.

Looking at the code, the lounge, rumpus and hot dog data is not reset when changing clans. That was done in 2017 by lost with a comment about not rechecking when you return to a clan.

With the exception of the above, everything else is cleared. The bleed potential exists because there are several requests that are issued on behalf of the current clan but they are never cancelled or waited on. Thus a long running request from one clan could update ClanManager after it had been reset for another.

One solution would be to have ClanManager track pending requests and not reset itself (clear data) until the requests are finished. Some kind of synchronizing/blocking might have a similar effect. A kludge might be to insert a delay before actually clearing the cache. Users could be advised to manage how fast they change clans. I can see the latter two causing angst for faxbots.

Just musing. If this is the first time this has occurred, I'm not sure there is much benefit in addressing it.
 
Thanks for looking into this. I've had the same trouble multiple times (2-3) recently. I've also had some messages about server side lag, so it is possible that's why it suddenly started. I just added a small delay into my code which might help.
 
The not clearing some data is because it is stored for all clans you have been in, not just current clan. Confused me for a while too.

I think this might be an issue in ClanStashRequest, which is what managed to queue up 1000 stash requests! (Probably via the RefreshConcoctions code in Clan Manager)
 
I added 'waitq(5)' directly after the visit_url() to the apply link. It doesn't appear to have affected anything. The stash requests are apparently all submitted before the waitq is reached. I can still change clans normally via clicking links in the browser though. However, visiting those same links with visit_url() makes it pound the stash page. Maybe I need to restart mafia after adding the delay? I left this instance open today in case any testing was needed.
 
Since you mentioned concoctions, it occurred to me that my code sets autoSatisfyWithStash to false whenever it leaves my home clan and back to true when it returns. I assume concoctions are affected by that setting. Could that be triggering this somehow? It looks like it changes the prop directly after switching clans. Maybe it should do it before switching? I will make that change for tomorrow as well.
 
Yeah...none of that fixed it.

Refresh stash @ login = fine.

Login script goes to BAFH to run breakfast = fine.

Login script returns to home clan = a bazillion stash requests.
 
Some more information:

As I said previously, I am able to switch clans from the clan recruiter page in the browser without triggering this behavior.

I added a bit of code to the beginning of my main play script to detect if my clan had changed and to set autoSatisfyWithStash true or false depending. I changed clans in the browser...all was fine. I ran the script, it indicated to me that it changed the prop appropriately and I also got the message that the script had completed running. And then mafia initiated a long stream of:

...
Refreshing stash contents...
Refreshing stash contents...
Refreshing stash contents...
Refreshing stash contents...
Refreshing stash contents...
Stash list retrieved.
Stash list retrieved.
Stash list retrieved.
Stash list retrieved.
Stash list retrieved.
...
Click to expand...

which is what I see when this happens.
 
I commented out any changes to autoSatisfy and then ran my clan switching function. Mafia refreshed the stash repeatedly.

I'm not clear what is going on. I was able to trigger it (above) by simply changing the autoSatisfy after changing clans (in the browser).

But then another (scripted) change in clan without altering the setting, still resulted in the repeated requests.
 
I went through my main script (currently 1.7 MB, and 67,051 lines) and commented out every single change to the autoSatisfyWithStash property and that seems to have resolved it.

Still not sure of the cause, or how that could affect something like "Refresh Session"...??
 
I wrote a small script that only changes clans back and forth.

Starting with autoSatisfyWithStash = false, I ran the script many times without incident.

I then typed 'set autoSatisfyWithStash = true' in the cli and this triggered a long series of stash refreshes.

Mafia didn't respond to ESC key, the "Stop Everything" menu item, or the "Exit KoLmafia" menu item (had to kill the task).
 
After a clean restart, I just repeated those results. I set the prop false (since it was left true from the previous instance).

I changed clans twice without incident. I typed the line 'set autoSatisfyWithStash = true' and triggered it.
 
You must log in or register to reply here.
Back
Top