Bug - Waiting for Info Guild unlocked-ness detection occasionally fails on login

[zarqon]

As discussed in the CanAdv thread, certain players including Theraze, Darzil, and myself have characters for which mafia doesn't correctly detect that the guild is unlocked.

Some things people have noted:

• It doesn't seem to always happen.
• These characters are usually aftercore farmer types. For my character, it's a level 46 PM who has only ascended 5 times and who has just been running a clan bot script since his last ascension about three years ago (he's our Impersonal Trainer).
• After logging in, the lastGuildStoreOpen property, which mafia uses to track the guild unlock, contains "0". Not the default value of "-1" and not the correct value of "5" (or whatever run the last actual unlock happened).
• Running the CLI "guild" command causes mafia to correctly detect the guild's unlocked-ness, and the lastGuildStoreOpen property then correctly contains "5" (or whatever), until the next time the problem occurs on login.

I've been able to confirm a few more things since I have a character for which this is currently happening:

• The problem has been occurring for me only on the first login of each day. After fixing the issue by calling "guild", successive logins retain the correct setting for lastGuildStoreOpen.
• In my case, I also get a debug log on problematic logins, which contains a confusing (to me anyway) null pointer error when accessing topmenu.php. After truncating it to contain only mafia's login actions (and not the login script stuff) it was less than 700K, so I attached it below.

Hopefully the debug log sheds some light on this issue. If there's anything else you'd like me to try, please let me know.

 

[roippi]

The biggest issue I see, and one that is probably related to why that NPE happened, is further up in the log:

class net.sourceforge.kolmafia.request.GuildRequest
Connecting to guild.php...

Requesting: http://www.kingdomofloathing.com/guild.php
2 request properties

Field: Cookie = [appserver=www9; PHPSESSID=rhe6ru7n88l85bjcj71r0kcmb0]
Field: User-Agent = [KoLmafia v16.0]

Retrieving server reply...
class net.sourceforge.kolmafia.request.GuildRequest
Connecting to guild.php...

Requesting: http://www.kingdomofloathing.com/guild.php
2 request properties

Field: Cookie = [appserver=www9; PHPSESSID=rhe6ru7n88l85bjcj71r0kcmb0]
Field: User-Agent = [KoLmafia v16.0]

We are firing off two simultaneous guild requests. I believe one is built in to standard login logic, and one is being generated from the daily deeds panel - specifically the Stills deed, which has

		@Override
		public void update()
		{
			boolean unlocked = KoLCharacter.getGuildStoreOpen();

Since the login-related GuildRequest hasn't finished yet, the state of the guild store is not known, so getGuildStoreOpen fires off its own request to find out. The two threads interfere, and blammo.

I'm out of state/traveling a bunch right now so I don't know when I'll be able to look at fixing this.

 

[lostcalpolydude]

The GuildRequest apparently leads to charpane parsing, which leads to recalculateAdjustments() being called before statDay is set. That's the cause of the NPE, and a workaround that probably wouldn't have any negative effect is having statDay default to "None" instead of null;

However, lastGuildStoreRequest is getting set to 0 because GuildRequest happens (and sets it) before either CharSheetRequest or ApiRequest get a chance to update KoLCharacter.ascensions. This seems to be a timing issue, probably dependent on one's internet connection.

I don't know why there are two requests for guild.php, but Daily Deeds is the only thing that should be creating a GuildRequest when logging in. Perhaps something could be added to delay DailyDeedsPanel's constructor from calling populate()? Perhaps a check for !KoLmafia.isRefreshing() could be used for that, I don't really know how to approach that though.

 

[roippi]

I don't know why there are two requests for guild.php, but Daily Deeds is the only thing that should be creating a GuildRequest when logging in.

I'm not sure where the other guildrequest is coming from then, maybe there's a hint in the debug log somewhere.

Perhaps something could be added to delay DailyDeedsPanel's constructor from calling populate()? Perhaps a check for !KoLmafia.isRefreshing() could be used for that, I don't really know how to approach that though.

There is already code that is supposed to do that. See the reflection performed by

RequestThread.executeMethodAfterInitialization( this, "populate" );

I suspect that the listener attached to dailyDeedsOptions may fire at some point during login, causing a premature populate(). I'd have to add some debug logging to look at it.

 

[zarqon]

It's not a purely random problem, i.e. internet connection, because I run five characters daily, three of which are clan bots, and this problem only happens with this specific character, pretty consistently on the first login of the day.

Further, sometimes -- and only for this character -- the main mafia interface never appears on login, though the javaw.exe process remains in Task Manager. I've taken to opening up the CLI and logging in using the login command. I don't know how to get a debug log of that though.

I'd be happy to make another debug log using a version of mafia which logs a bunch of extra stuff, if that might help.

 

[Veracity]

Bump to look at this, since Donovin's "refresh going into HCZ" was a result of repeatedly submitting requests to guild.php while refreshing.

Near as I can tell, the only place in KoLmafia which wants to go look at the guild is the "stills" Daily Deed - and I don't see why that would get fired before you finish logging in.

There have been a couple of changes since this bug report was submitted:

- We get api.php at startup, not charpane.php
- I changed the "stills" Daily deed to only look to look at the guild if you are a Moxie class and know Superhuman Cocktailcrafting, rather than checking the guild FIRST.

Since you are class "none", essentially, until we learn your class from api.php, that should shut down the requests to guild.php.

Therefore, I suspect that this issue has been fixed. I'd like zarqon to confirm it, please. (Is he still here? I sent him a forum PM three weeks ago which he has not responded to.)

And I want to understand the repeated guild requests better, so I will continue to investigate how and when that Daily Deed gets fired during - not after - login.

 

[Fluxxdog]

Zarqon also hasn't logged in for a couple weeks. (Last KoL login date Nov. 22) He could be burnt out or on vacation. Just hope he's OK.