Feature - Implemented Time-Spinner

Bale

Minion
CheeseCookie is scary. A clannie of mine found snapsot a few days ago. It was a terrifying revelation for her!
 
CheeseCookie is scary. A clannie of mine found snapsot a few days ago. It was a terrifying revelation for her!

I was going to do Source Terminal recipes but work came along. I'm amused that I bring all sorts of fear into the souls of completionists.
 

fronobulax

Developer
Staff member
I was going to do Source Terminal recipes but work came along. I'm amused that I bring all sorts of fear into the souls of completionists.

Yes you do. But that fear is tempered with gratefulness because you took over the script.

But this is the real source of my KoL frustration :)
 

Bale

Minion
You're 25th on that board! SWEET!

I can't imagine how hard it would be to get into the top 10.
 

fronobulax

Developer
Staff member
25, 35 and 47. I am hampered by my refusal to ascend the oldest character :) And note xKiv at 12.

Basically I wrote DCQuest to tell me what I had that was not in the DC and to tell me what items KoL knew about that I did not have. DCBuy - which may not have been released but could be, will buy things that are affordable in the mall and put them in the DC. Then it is just a matter of reviewing the missing items and deciding how, or if, they can be obtained.
 

xKiv

Active member
I have a script that goes through all items that I am missing, and tells me if they are cheap enough to buy (script parameter), if I have some in my inventory, prints missing untradeables separately. I tend to be up to the point where missing things would cost me several million meat each at the minimum, and untradeables keep heaping up.
I *think* I was at #10 at some point, but it didn't last long.
Farming extras of every untradeable outfit (cloathing, std15, hcstd15, std16, hcstd16, ...) is ... sort of timeconsuming.
 

Bale

Minion
That is probably the toughest board in the game, so... wow. I wouldn't every have attempted it.

And holderofsecrets cheats so in my mind you're actually numbers 24 and 11.
 

lostcalpolydude

Developer
Staff member
I wrote up TimeSpinnerCommand, at least for eating food. It makes all the right requests, but at the end gives an error because inv_eat returns a blank page.

Attached what I've written here (also need a line added to KoLmafiaCLI), because it's probably something simple that's missing.
 

Attachments

  • TimeSpinnerCommand.txt
    5.2 KB · Views: 43

Veracity

Developer
Staff member
I wrote up TimeSpinnerCommand, at least for eating food. It makes all the right requests, but at the end gives an error because inv_eat returns a blank page.

Attached what I've written here (also need a line added to KoLmafiaCLI), because it's probably something simple that's missing.
Well, here is what I see in my session log when remembering a delicious meal in the Relay Browser:

Code:
use 1 Time-Spinner
Took choice 1195/2: (secret choice)
choice.php?pwd&whichchoice=1195&option=2
Took choice 1197/1: Spin and Munch!
choice.php?pwd&whichchoice=1197&option=1&foodid=9122

eat 1 Tea, Earl Grey, Hot
You gain 21 Adventures
You gain 1,000 Mojo Points
You gain 1,000 hit points
Here is your sequence of requests:

Code:
			//inv_use.php?whichitem=9104&ajax=1&pwd&_=1475872346193
			RequestThread.postRequest( UseItemRequest.getInstance( ItemPool.TIME_SPINNER ) );

			//choice.php?forceoption=0

			//choice.php?pwd&whichchoice=1195&option=2
			GenericRequest request = new GenericRequest( "choice.php" );
			request.addFormField( "whichchoice", "1195" );
			request.addFormField( "option", "2" );
			request.addFormField( "pwd", GenericRequest.passwordHash );
			RequestThread.postRequest( request );

			//choice.php?pwd&whichchoice=1197&option=1&foodid=2527
			GenericRequest request2 = new GenericRequest( "choice.php" );
			request2.addFormField( "whichchoice", "1197" );
			request2.addFormField( "option", "1" );
			request2.addFormField( "foodid", foodIdString );
			request2.addFormField( "pwd", GenericRequest.passwordHash );
			RequestThread.postRequest( request2 );

			//inv_eat.php?pwd&whichitem=2527&ts=1
			//RequestThread.postRequest( EatItemRequest.getInstance( food ) );
			// this shouldn't be needed, since it appears the redirect from choice.php is being followed
So, a GenericRequest will follow redirects:

Code:
	protected boolean shouldFollowRedirect()
	{
		return this != ChoiceManager.CHOICE_HANDLER && this.getClass() == GenericRequest.class;
	}
So will a UseItemRequest:

Code:
	@Override
	protected boolean shouldFollowRedirect()
	{
		return true;
	}
Therefore, the initial UseItemRequest does inv_use.php which redirects to choice.php&forceoption=0 - which we follow.
You use GenericRequest to select "Travel Back to a delicious Meal" - whichchoice=1195&option=2.
You use GenericRequest to select "Spin and Munch!" - whichchoice=1197&option=1&foodid=9122
That redirects to inv_eat.php?pwd&whichitem=2527&ts=1 - which we follow.

So, yeah, it looks like it submits the right requests. My Relay Browser request sees the inv_eat and passes it to EatItemRequest.registerRequest which logs "eat 1 Tea, Earl Grey, Hot". Presumably, the non-blank response gets passed through EatItemRequest.parseConsumption.

Does your session log using your command show the expected "eat xxx"?

I'll try this tomorrow - first the Relay Browser and then the command - in the debugger and try to see would possibly be different. It sure looks like it should work.
 

lostcalpolydude

Developer
Staff member
Going through the Relay Browser (which works, obviously):

Code:
Requesting: https://www.kingdomofloathing.com/choice.php?pwd&whichchoice=1197&option=1&foodid=2527
3 request properties
Field: Cookie = [charpwd=220; chatpwd=292; PHPSESSID=bsgp2j2al17vn76n03m11t0us7; AWSALB=neaTD67huaBSQUR6e6lBIFCkqMQTJ+NqITk4Z3+jNlEEAkwKifSEXC6UuguwX37tqys//OTyQpueyFz/2iBL0N4dM6X6cz886IQoN8ZVvgTZOBpQErRJguQgZw0P]
Field: User-Agent = [KoLmafia v17.4]
Field: Content-Type = [application/x-www-form-urlencoded]

Retrieving server reply...

Retrieved: https://www.kingdomofloathing.com/choice.php?pwd&whichchoice=1197&option=1&foodid=2527
12 header fields
Field: Transfer-Encoding = [chunked]
Field: null = [HTTP/1.1 302 Moved Temporarily]
Field: Cache-Control = [no-store, no-cache, must-revalidate, post-check=0, pre-check=0]
Field: Server = [nginx/1.8.1]
Field: Connection = [keep-alive]
Field: location = [inv_eat.php?pwd=6dd7086db8e2581c637fe6f2b8736704&whichitem=2527&ts=1]
Field: Set-Cookie = [AWSALB=FVLruN4Ks2ZIiMNAG/oLwx3zbNzZEir/uZaFG3WIQdScF8hLhCD4roNCR4YQI6Fyi9qwXXS5uV6tJknGNxkZpLTiWc9889gysLnp3nNevVnG+s9QS6I8QTsNeHEs; Expires=Fri, 14 Oct 2016 20:32:36 GMT; Path=/]
Field: Pragma = [no-cache]
Field: Expires = [Thu, 19 Nov 1981 08:52:00 GMT]
Field: Date = [Fri, 07 Oct 2016 20:32:36 GMT]
Field: X-Powered-By = [PHP/5.3.29]
Field: Content-Type = [text/html]

class net.sourceforge.kolmafia.request.RelayRequest
Connecting to inv_eat.php...

Requesting: https://www.kingdomofloathing.com/inv_eat.php?pwd&whichitem=2527&ts=1
And other stuff after that which looks just like normal eating.

Using the new command:

Code:
Requesting: https://www.kingdomofloathing.com/choice.php?whichchoice=1197&option=1&foodid=2527&pwd
3 request properties
Field: Cookie = [PHPSESSID=9ankv1tomq1f559i08gdn1hae2; AWSALB=E7GeUIPt5rOsrjjWFnlxGAfo41ZM4SMLKYV7RPaTE5BsuuHYgYGfFs+8wLms1zLBUfbcbxa+qkMP0yBwvnwwfpqzEWvsnuLe60DqffL7pHyXQep3vPDFwtg3meHO]
Field: User-Agent = [KoLmafia v17.4]
Field: Content-Type = [application/x-www-form-urlencoded]

Retrieving server reply...

Retrieved: https://www.kingdomofloathing.com/choice.php?whichchoice=1197&option=1&foodid=2527&pwd
12 header fields
Field: Transfer-Encoding = [chunked]
Field: null = [HTTP/1.1 302 Moved Temporarily]
Field: Cache-Control = [no-store, no-cache, must-revalidate, post-check=0, pre-check=0]
Field: Server = [nginx/1.8.1]
Field: Connection = [keep-alive]
Field: location = [inv_eat.php?pwd=a79ac9a729895154acfdf10a93835aac&whichitem=2527&ts=1]
Field: Set-Cookie = [AWSALB=m+uqgYfRskvqlQUVM2E+GDcd3mYSrZd62bzSDF7KQMgKIEbzI2StzFZqs1Swj8KeLu0CbM3cs4OLc1C1hQz431H1jr2Y1OCMDj4DBjSsMEglzuyGbnhI2Zb1tBdL; Expires=Sat, 15 Oct 2016 00:03:48 GMT; Path=/]
Field: Pragma = [no-cache]
Field: Expires = [Thu, 19 Nov 1981 08:52:00 GMT]
Field: Date = [Sat, 08 Oct 2016 00:03:48 GMT]
Field: X-Powered-By = [PHP/5.3.29]
Field: Content-Type = [text/html]

Server www.kingdomofloathing.com returned a blank page from inv_eat.php. Complain to Jick, not us.

They look the same, other than session-specific stuff. There isn't even anything about requesting inv_eat.php, but clearly the redirect was followed to get a blank page. (On another note, it looks like password hashes should be removed from header info in debug logs? Or maybe it isn't so important with all the other cookie data, or maybe that should be removed as well.)

The gCLI output from that command is:
Using 1 Time-Spinner...
Manual control requested for choice #1195
choice 1: (secret choice)
choice 2: (secret choice)
choice 3: (secret choice)
choice 4: (secret choice)
choice 5: (secret choice)
Click here to continue in the relay browser.

Server www.kingdomofloathing.com returned a blank page from inv_eat.php. Complain to Jick, not us.
 

Darzil

Developer
The only difference I see is in cookies : charpwd=220; chatpwd=292;

Not sure why that'd make a difference though.
 

Veracity

Developer
Staff member
Going through the Relay Browser (which works, obviously):

Code:
Requesting: https://www.kingdomofloathing.com/choice.php?pwd&whichchoice=1197&option=1&foodid=2527
Retrieved: https://www.kingdomofloathing.com/choice.php?pwd&whichchoice=1197&option=1&foodid=2527
Field: location = [inv_eat.php?pwd=6dd7086db8e2581c637fe6f2b8736704&whichitem=2527&ts=1]

class net.sourceforge.kolmafia.request.RelayRequest
Connecting to inv_eat.php...

Requesting: https://www.kingdomofloathing.com/inv_eat.php?pwd&whichitem=2527&ts=1
Browser sends request for choice.php
KoL responds with redirect to inv_eat
Browser sends request for inv_eat.

Code:
Requesting: https://www.kingdomofloathing.com/choice.php?whichchoice=1197&option=1&foodid=2527&pwd
Retrieved: https://www.kingdomofloathing.com/choice.php?whichchoice=1197&option=1&foodid=2527&pwd
Field: location = [inv_eat.php?pwd=a79ac9a729895154acfdf10a93835aac&whichitem=2527&ts=1]

Server www.kingdomofloathing.com returned a blank page from inv_eat.php. Complain to Jick, not us.
I see no evidence that we actually followed the redirect. We would have seen "Requesting: inv_eat..."

There isn't even anything about requesting inv_eat.php, but clearly the redirect was followed to get a blank page.
I don't think that is so "clear". :)

(On another note, it looks like password hashes should be removed from header info in debug logs? Or maybe it isn't so important with all the other cookie data, or maybe that should be removed as well.)
Cookie data is interesting in that we get to see that we are doing the right thing changing cookies when KoL sends us a new cookie. Removing the password hash when logging the location header seems reasonable.

I'm going to see if I can figure out why we'd say "Server returned a blank page" without having actually logged a request being sent. Something about choice.php redirecting to inv_eat.php - which is something new - from a GenericRequest?
 

Veracity

Developer
Staff member
lost, can we see the Relay Browser case with "show browser interactions" on? I want to see GET vs. POST.
 

lostcalpolydude

Developer
Staff member
Here it is (with bulky responses removed). Looks like POST to choice.php and GET to inv_eat.php.
 

Attachments

  • DEBUG_20161013a.txt
    9.5 KB · Views: 30

ckb

Minion
Staff member
I have no idea what most any of this stuff is on this page you are talking about, but I do know that you Mafia devs are the best.
 

Veracity

Developer
Staff member
Here it is (with bulky responses removed). Looks like POST to choice.php and GET to inv_eat.php.
That's as it should be; you do a GET on redirects. So do we. Look at this loop:

Code:
	public void externalExecute()
	{
		do
		{
			if ( !this.prepareConnection() )
			{
				break;
			}
		}
		while ( !this.postClientData() && !this.retrieveServerReply() && this.timeoutCount < GenericRequest.TIMEOUT_LIMIT && this.redirectCount < GenericRequest.REDIRECT_LIMIT );
	}
this.retrieveServerReply() returns false if we follow a redirect:

Code:
		if ( this.shouldFollowRedirect() )
		{
			// Re-setup this request to follow the redirect
			// desired and rerun the request.

			this.constructURLString( this.redirectLocation, this.redirectMethod.equals( "POST" ) );
			// this.hasResult = !this.isExternalRequest && ResponseTextParser.hasResult( this.redirectLocation );
			if ( this.redirectLocation.startsWith( "choice.php" ) )
			{
				ChoiceManager.preChoice( this );
			}
			return false;
		}
If we follow the redirect and go to the top of the loop, the first thing we call is this.prepareConnection().

Code:
	private boolean prepareConnection()
	{
		if ( this.shouldUpdateDebugLog() )
		{
			RequestLogger.updateDebugLog( "Connecting to " + this.baseURLString + "..." );
		}
Literally the first thing we do is say "Connecting to...". We don't see that, so it broke out of the loop. The caller is run():

Code:
		{
			this.execute();
		}

		// Response is ok or redirect
		if ( this.responseCode != 200 && this.responseCode != 302 )
		{
			return;
		}

		if ( this.responseText == null )
		{
			KoLmafia.updateDisplay(
				MafiaState.ABORT,
				"Server " + GenericRequest.KOL_HOST + " returned a blank page from " + this.getBasePath() + ". Complain to Jick, not us." );
			return;
		}
Your message was "Server www.kingdomofloathing.com returned a blank page from inv_eat.php. Complain to Jick, not us." - so the path in the request was inv_eat.php - but the responseText was null - because we did

Code:
			this.constructURLString( this.redirectLocation, this.redirectMethod.equals( "POST" ) );
and the very first thing that does is this:

Code:
		this.responseText = null;
Conclusion:

1) we did follow the redirect and change the url in the request to go to inv_eat.php and clear the responseText
2) we never submitted the URL, since prepare_connection did not log "Connecting to".
3) Therefore, one of the subsequent tests must have finished the loop:

Code:
		while ( !this.postClientData() && !this.retrieveServerReply() && this.timeoutCount < GenericRequest.TIMEOUT_LIMIT && this.redirectCount < GenericRequest.REDIRECT_LIMIT );
Well, if we get redirected too many times, we bail without submitting it.

Hard to see why we'd get too many redirects, since this is the first one in this request.

Notice that the "blank page, complain to Jick" is printed even if the response code is 302 - i.e., a redirect - which legitimately doesn't have a response.

I think we should have a check there for "too many redirects" and a different message. But, still - I will use a debugger tomorrow and see if I can figure out more.
 

Veracity

Developer
Staff member
Revision 17280 should be more informative about unhandled redirects. I doubt it will solve this issue, but perhaps we will see some different messages.
 

Veracity

Developer
Staff member
This is the issue.

Code:
Using 1 Time-Spinner...
[color=red]Manual control requested for choice #1195[/color]
choice 1: (secret choice)
choice 2: (secret choice)
choice 3: (secret choice)
choice 4: (secret choice)
choice 5: (secret choice)
[color=red]Click here to continue in the relay browser[/color]
It decides that it is "automating" the initial choice.php?forceoption=0 and enters an abort state, which makes future redirects not actually follow the redirect.

Pondering the best way to deal with this.
 
Top