Bug - Not A Bug Horrible relay failure when launcing teh relay browser for the first time in a sessio

[Winterbay]

As requested here I've now created a debuglog from when I click the relay-button to when the browser has finished loading the page (almost), I closed it down before it was finished unfortunately. Hopefully this won't stop the root cause to be found as the error happens as soon as I click the button.

The session log contains the following around that time:

Horrible relay failure
Horrible relay failure
 > ZLib setting chit.effects.classicons normalized: 'none' => 'none'
 > Checking for updates...
 > Latest version: 0.6.9
 > Checking for updates...
 > Latest version: 0.6.9
 > 1 HP costs 0,587μ. ( 218, / 218 )
 > 1 MP costs 4,082μ. ( 427, / 553 )
 > WHAM: You have no profitable MP restoratives.
 > WHAM: You have no profitable HP restoratives.
 > WHAM: Monster HP is 57.0.
 > WHAM: Running SmartStasis
 > WHAM: SmartStasis complete.
 > WHAM: Starting evaluation and performing of attack
 > Auto-funk: merging 'use 5686' and 'use 2581'.
 > Auto-funk: merging 'use 2581' and 'use 2091'.
 > WHAM: Could not find a way to kill the monster. Trying the best available option since you've set WHAM_AlwaysContinue to true.
 > WHAM: Enqueueing Salsaball (macroid skill 4020).
 > WHAM: We are going to 1-shot with Salsaball.
Round 25: Winterbay executes a macro!
Round 25: Winterbay casts SALSABALL!
Round 26: procrastination giant takes 9 damage.
 > WHAM: Current monster HP is calculated to 48.0
Round 26: Winterbay executes a macro!
Round 27: Winterbay executes a macro!
Round 27: Winterbay casts WAVE OF SAUCE!
Round 28: procrastination giant takes 92 damage.
You gain 17 hit points
You gain 4 Mana Points
You acquire an effect: Burning Soul (duration: 1 Adventure)
Round 28: Winterbay wins the fight!
After Battle: Gronald sits on your fallen opponent's body, blows a smoke ring, and winks at you.
You gain 522 Meat

Both macros generated was generated form the CLI one with "fight!" (which basically calls my CCS) and one with "saucesplash" which attempts a saucesplash.

The CLI-output during the first one contained an error regarding the charpane that isn't vivsible in the session log.

I'm running on Windows XP Professional with Java 1.6.0_33 using Firefox 14.0.1. It should be noted that this error does not occur at work (where I log in via IP and from behind a proxy server) using the same operating system, java version and browser with the same installation (copied back and forth via a USB-stick since dropbox is blocked by the firewall).

 

[roippi]

I can't even copy/paste the malformed response that mafia is getting from your browser, it's so messed up. Only thing that I can think of is a bad override maybe?

 

[Winterbay]

The only one I'm using is CHIT (which admittedly failed to load properly).

 

[Bale]

I'll just say that ChIT never caused that error for me. Like a proud step-parent I feel compelled to defend its virtue.

 

[IronTetsubo]

I can't even copy/paste the malformed response that mafia is getting from your browser, it's so messed up. Only thing that I can think of is a bad override maybe?

Well, I am not a developer (java or otherwise), so take this all with large grains of salt, but in my experience when you're getting garbage responses back like that, you're reading some random section of memory rather than a properly initialized io stream. It looks like the socket is being set (if it was null, it'd be a different exception, and either way that's checked before the readBrowserRequest call), so I could see two options - either one, something external is making garbage calls to localhost:RelayServer.port (pretty unlikely), or that there's some sort of thread-unsafe operation going on? Does that make any sense at all, or am I completely off base?

 

[lostcalpolydude]

I have occasionally seen CHIT give an error message when I first opened the relay browser, and then there was no error message when I reloaded the charpane. I'll have to pay more attention if it happens again (but it hasn't happened in a while). I would expect CHIT to fail because of the error rather than causing it in this case, though that's mostly guessing.

 

[roippi]

So wait there's a few things that I'm not getting. You say that this debug log happens between when you first click the open relay browser button and when the page loads - but your CLI output has something to do with a macrofied fight?

If this is reproducible, does it always happen when opening the relay browser?

Does this happen if you don't use CHIT?

 

[Catch-22]

Well, you're definitely not streaming bytes from random memory locations.

One possibility is that you've got some TCP connections being reset prematurely. Are you running any personal firewalls at home?

Can you also name all the relay overrides you're using?

 

[Winterbay]

1) It happens every first time in a session I load the relay browser. If I close that specific tab and open up a new relay browser there is no problem.

2) It is reproducible. The attached debuglog is from just after I logged in when I had done nothing else but create a double-ice cap after running login scritps and breakfast. This time I waited for the entire page to load before stopping.

3) The CLI-output from earlier was just to put things in context and to mention that I didn't actually use the broswer window I had opened up but rather finished the fight that was going on from the CLI.

4) I've had memory problems on this computer before (wonderful random RAM errors) and it has been doing fun things like getting BSODs on startup every now and again (to the point where the computer refuses to start without having 8 or 9 BSODs). This is fixable by doing a "chkdsk" on the drive with the help of the Windows installation disk for a few months). The computer is old and probably falling apart, could be a possible reason?

5) The relay overrides in use are version 0.6.8 of CHIT and a version of pyramid.ash and that's it.

6) I have no extra firewall at home (well, I do have one via the security program I use, but I've never had any trouble with that before)

7) Trying without CHIT appears to give no Horrible relay failure, but I'll have to double-check that tomorrow to make sure that it's not just a once-a-day error... (I did exit and restart Mafia so it should be a new session but you never know)

 

[Catch-22]

Well, I created this patch which will print a stack trace when a relay HTTP request is malformed. It won't really help determine why the request is malformed in this case, but it's at least more helpful than a generic "horrible relay failure" due to a catch all exception later down the track.

I think there's some confusion floating around this thread. The problem is not with the HTTP response, it's with the HTTP request (generated by KoLmafia). KoLmafia expects the first line of the HTTP request to look similar to this:

GET game.php HTTP/1.1

In Winterbay's case, the first 2 lines appear to be garbled.

 

[Veracity]

I think there's some confusion floating around this thread.

Indeed.

The problem is not with the HTTP response, it's with the HTTP request (generated by KoLmafia).

In particular, with this statement.

The Relay Browser acts as an HTTP proxy. It operates like this:

1) Browser -> KoLmafia: request
2) KoLmafia -> KoL: request
3) KoL -> KoLmafia: response
4) KoLmafia -> Browser: response

Normal DEBUG logs show you 2 and 3. If you have checked "Verbosely log communication between KoLmafia and browser" (logBrowserInteractions). you will also get 1 and 4.

The posted log has this:

-----From Browser-----
GET /game.php HTTP/1.1
...
Requesting: http://www.kingdomofloathing.com/game.php
...
Retrieved: http://www.kingdomofloathing.com/game.php
...
-----To Browser-----
HTTP/1.1 200 OK
...

That is a perfectly normal request/request/response/response sequence.

It also shows us this:

-----From Browser-----
...garbage characters...
Horrible relay failure

In other words, at step 1, the text that the Browser sent to KoLmafia was garbled.

Contrary to the statement I quoted, this was not "generated by KoLmafia". This was generated by the browser and read by KoLmafia.

This is the code that reads the request from the browser and prints it:

		this.reader = new BufferedReader( new InputStreamReader( this.socket.getInputStream() ) );

		String requestLine = this.reader.readLine();

		if ( debugging )
		{
			RequestLogger.updateDebugLog( "-----From Browser-----" );
			RequestLogger.updateDebugLog( requestLine );
		}

That's it. If KoLmafia got that garbled line from the browser, I see two possibilities:

1) The browser really sent those garbled characters
2) The Java socket is broken, somehow.

In either case, it's something that happens to Winterbay and only to Winterbay and only some of the time.

Sucks to be him.

 

[Winterbay]

Yeah, well. It doesn't give me any problem, apart from making the first load of the relay browser of the day take longer. I just thought I'd post it in case there was something that could be done about it

 

[Catch-22]

Thanks for clearing things up V. I probably should've said "generated by a socket that KoLmafia uses"

On my machine, using packet capture software, you can see what happens:

Firefox generates this request.
GET http://127.0.0.1:60080/game.php HTTP/1.1
Host: 127.0.0.1:60080
User-Agent: Mozilla/5.0 (Windows NT 6.0; WOW64; rv:14.0) Gecko/20100101 Firefox/14.0.1
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip, deflate
Connection: keep-alive

The connection stays open, while KoLmafia gets the real page.

GET http://www.kingdomofloathing.com/game.php HTTP/1.1
Cookie: appserver=www10; PHPSESSID=bkgq1itrv1l1vi83j5titgspb2
User-Agent: KoLmafia v15.3
Connection: close
Cache-Control: no-cache
Pragma: no-cache
Host: www.kingdomofloathing.com
Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2

KoLmafia gets the response, remixes it a little, and returns that response to the first request made by the browser and the connection is closed.

Your game.php request seems to go through fine, the first request after that (assuming you have javascript enabled), is basic.js (served by KoLmafia). The curious thing is, your basic.js comes through fine as well, but it's only after those two mysterious garbled lines are read out of the socket. In a hex editor they look like kinda like TCP packet segments or something. My guess is that something is interfering with the connection. Are you running a proxy at home?

I think the issue is going to be hard to get to the bottom of because nobody else can reproduce it. If you're familiar with Wireshark, perhaps using that will be able to provide you with some more clues.

 

[xKiv]

Thanks for clearing things up V. I probably should've said "generated by a socket that KoLmafia uses"

I would say "coming out of a socket that KoLmafia uses" is ... less misinterpretable.

 

[Winterbay]

I did once have Wireshark installed, but I never managed to figure out what to do with it so probably not

 

[Catch-22]

Eh, well this isn't really a bug. I honestly think you have something funky in your setup. Try turning off the firewall, or switch your default browser (temporarily?). Perhaps reinstall the browser or disable some addons?

The only weird behavior I could find in my testing was that if you're connecting via proxy, KoLmafia sets the "Proxy-connection" header to "keep-alive", which overrides the hard set "Connection: close" header. I don't think that would be causing problems like this though, especially if you're not even using a proxy.

KoLmafia could easily be patched to skip over any bung lines that get read out of the socket, but I don't think KoLmafia is where the problem lies.

 

[Veracity]

KoLmafia could easily be patched to skip over any bung lines that get read out of the socket, but I don't think KoLmafia is where the problem lies.

It already does. It attempts to extract things from the line, takes an Exception, which it traps, and prints "Horrible Relay Failure".

Your patch, or something like it, would make people less likely to post bug reports like this one when their own setup is, somehow, screwed up.

I think I'll do that. In the mean time, this is Not A Bug.

 

[Catch-22]

Your patch, or something like it, would make people less likely to post bug reports like this one when their own setup is, somehow, screwed up.

First patch I posted used the "!contains HTTP/1.1" but I changed it to simply reuse the index variable. I'm guessing you saw my old patch

Good to see a patch come out of this, even though it's not a bug in KoLmafia.

 

[Veracity]

Your first patch was clearly never tested. Likely never compiled, considering that an extra semicolon in it turned the bulk of the function into unreachable code (with associated compile warning), which would have rendered the entire Relay Browser inoperative.

I think the check for HTTP version number is better than relaying on the index of a space character, since random garbage could well contain a space, but is exceedingly unlikely to contain the version string.

 

[Catch-22]

Your first patch was clearly never tested. Likely never compiled, considering that an extra semicolon in it turned the bulk of the function into unreachable code (with associated compile warning), which would have rendered the entire Relay Browser inoperative.

I think the check for HTTP version number is better than relaying on the index of a space character, since random garbage could well contain a space, but is exceedingly unlikely to contain the version string.

Nah I tested it, after I uploaded it, that's when I realized that I added a semi-colon to the end of an if statement. I uploaded it again and switched to using the index variable, but I was in two minds about it. I think what you patched in is perfect If my patch actually worked I would've just left it there.