Feature - Implemented Migration from HTTP/1.1 to HTTP/2.0

[Irrat]

KOL supports HTTP 2.0 and prefers to use that, while HTTP 1.1 is outdated and a legacy of the past.
It's also slower.

Unfortunately, this does create a small problem as HttpURLConnection, which is used internally, does not support HTTP 2.0
Instead HttpClient seems to the recommended library for usage, included since Java 9.

Mafia's internals looks to be using the HttpURLConnection as request builder, built request, and response. Which is separated into three different objects when using HttpClient.

 

[Ryo_Sangnoir]

Browsers also only support HTTP2 over TLS (as I understand it), which means the proxying has to deal with certificates, as the relay browser would need to be https://127.0.0.1 (instead of http://127.0.0.1) to work.

 

[heeheehee]

Strictly speaking, you could use H1 for Mafia's relay server while using H2 to talk to upstream. That may be the simplest option for backwards compatibility.

If we were to start serving https on localhost, I think users would be unhappy with the browser nags induced by self-signed certs.

 

[heeheehee]

Upon slightly further inspection: there does not seem to be an analogous HttpServer built into Java's standard library that handles HTTP 2. So unless we were to pull in a dependency on something like Netty, we wouldn't migrate the relay server.

That said, the performance benefits of H2 disappear when you're talking about serving files locally, where the OS is basically just copying bytes between in-memory buffers and doesn't have meaningful latency / loss compared to the broader network.

 

[Ryo_Sangnoir]

I've been looking into this at https://github.com/midgleyc/kolmafia/commits/http-client. It's non-trivial. It doesn't work at the moment, though I did manage to migrate the wiki call and can confirm that single requests work (wiki doesn't use HTTP/2, though, so that wasn't particularly necessary).

I think the issue is likely that HttpUrlConnection makes a request if you ask for a response code, while HttpClient requires you to formally make requests, and I'm probably not doing that in some place.

GenericRequest has some documentation quirks, and some methods return the opposite of what they say they return.

 

[Ryo_Sangnoir]

Implemented in r26293.

 

[Irrat]

Implemented in r26293.

Oh wow, the performance increase is insane. I was getting up to 900ms in response times, and it's gone down to 250ms.

I live in New Zealand, so this is about the best ping I can get. Mafia now feels like it's running suspiciously fast..

Awesome work! I had fully expected this project to be tackled over the course of a year, not inside a month!

 

[esko]

Question regarding this feature; it sounds like the relay server won't be migrated over, is that correct? I have a somewhat unique use-case that's affected by this change that I'm trying to figure out how to address.

Some urls such as charpane.php will load correctly while /game.php will not.

```> user-agent: curl/7.68.0
> accept: */*
>
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* old SSL session ID is stale, removing
* Connection state changed (MAX_CONCURRENT_STREAMS == 128)!
* http2 error: Invalid HTTP header field was received: frame type: 1, stream: 1, name: [:status], value: [200]
* HTTP/2 stream 0 was not closed cleanly: PROTOCOL_ERROR (err 1)```

The tl;dr Kolmafia runs in a container with the relay server exposed and served via nginx. This is primarily to allow me to play and use Kolmafia on other devices such as an iPad and up until this PR it worked great, though now I run into invalid http headers.

 

[Ryo_Sangnoir]

You make HTTP/1.1 requests to the relay server; KoLMafia makes HTTP/2 requests to KoL and returns the result.

If you can run `debug on` in the CLI, make some requests, and post here the invalid HTTP headers you get I can try to debug what needs to happen.

To remove one potential point of failure: what happens if you expose the relay server directly, without nginx getting involved?

One difference now is that some HTTP headers are lowercase. HTTP headers are case insensitive by spec, but if whatever you've got in there doesn't correctly handle that, it might be that?

 

[esko]

Sure thing.

Here's an example request to /game.php:

% curl --http2 -v -I 'https://kolmafia.internaldomain.org/game.php'
...
CApath: /etc/ssl/certs
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.3 (IN), TLS handshake, Encrypted Extensions (8):
* TLSv1.3 (IN), TLS handshake, Certificate (11):
* TLSv1.3 (IN), TLS handshake, CERT verify (15):
* TLSv1.3 (IN), TLS handshake, Finished (20):
* TLSv1.3 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.3 (OUT), TLS handshake, Finished (20):
* SSL connection using TLSv1.3 / TLS_AES_256_GCM_SHA384
* ALPN, server accepted to use h2
* Server certificate:
* subject: CN=*.internaldomain.org
* start date: Feb 7 00:58:48 2022 GMT
* expire date: May 8 00:58:47 2022 GMT
* subjectAltName: host "kolmafia.internaldomain.org" matched cert's "*.internaldomain.org"
* issuer: C=US; O=Let's Encrypt; CN=R3
* SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x55a08c36fe30)
> HEAD /game.php HTTP/2
> Host: kolmafia.internaldomain.org
> user-agent: curl/7.68.0
> accept: */*
>
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* TLSv1.3 (IN), TLS handshake, Newsession Ticket (4):
* old SSL session ID is stale, removing
* Connection state changed (MAX_CONCURRENT_STREAMS == 128)!
* http2 error: Invalid HTTP header field was received: frame type: 1, stream: 1, name: [:status], value: [200]
* HTTP/2 stream 0 was not closed cleanly: PROTOCOL_ERROR (err 1)
* stopped the pause stream!
* Connection #0 to host kolmafia.internaldomain.org left intact
curl: (92) HTTP/2 stream 0 was not closed cleanly: PROTOCOL_ERROR (err 1)

And corresponding kolmafia debug output:

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

Requesting: https://www.kingdomofloathing.com/game.php
4 request properties
Field: Accept-Encoding = [gzip]
Field: Cookie = [PHPSESSID=SESSIDHERE; AWSALB=blahblah; AWSALBCORS=blahblah]
Field: Referer = [https://www.kingdomofloathing.com/game.php]
Field: User-Agent = [Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.110 Safari/537.36]

Retrieving server reply...

Retrieved: https://www.kingdomofloathing.com/game.php
11 header fields
Field: :status = [200]
Field: cache-control = [no-store, no-cache, must-revalidate, post-check=0, pre-check=0]
Field: content-encoding = [gzip]
Field: content-type = [text/html; charset=UTF-8]
Field: date = [Tue, 15 Mar 2022 23:52:20 GMT]
Field: expires = [Thu, 19 Nov 1981 08:52:00 GMT]
Field: pragma = [no-cache]
Field: server = [nginx/1.8.1]
Field: set-cookie = [AWSALB=blahblah; Expires=Tue, 22 Mar 2022 23:52:20 GMT; Path=/, AWSALBCORS=blahblah; Expires=Tue, 22 Mar 2022 23:52:20 GMT; Path=/; SameSite=None; Secure]
Field: vary = [Accept-Encoding]
Field: x-powered-by = [PHP/5.3.29]

Retrieving server reply
ResponseText has 798 characters.
<html><head><title>The Kingd....

Removing nginx and exposing the relay server on 60080 to my LAN seems to work ok. As an additional test, I also removed the "force SSL" option in nginx proxy manager to force plaintext and can access the relay server that way. Confirmed 8cc7eb9266ee9f431cdabc0481ed6be8b7ca4ecc seemed to have introduced the oddity here, though I wouldn't go so far as to blame it

To add to the mystery, it seems as though both curl and chrome will return an error here, though oddly enough the “links” cli browser will work just fine. I’m assuming perhaps links isn’t as strict as curl/chrome is for checking http headers, which makes me even wonder if nginx is to even be blamed here.

Kind regards for taking a quick look at this, much appreciated.

 

[Ryo_Sangnoir]

Okay, I think I see what's going on here.

The relay server explicitly serves HTTP/1.1, and proxies the input stream and all headers it receives. Under HTTPClient using HTTP/2, it looks like the headers include ":status", which is a header from the header frame. Under HTTP/1.1, this is no problem.

You're, by the looks of it, having nginx re-proxy the relay server output under HTTP/2, which then complains that ":status" isn't a valid header.

I think you should either:

• use HTTP/1.1 to access the relay server, or
• make nginx drop any header starting with ":" before it serves the page

We could drop the ":status" field from the headers we re-serve, but the relay server is explicitly HTTP/1.1 in places (can't remember, perhaps image caching?), so accessing it over HTTP/2 isn't officially supported.

 

[the dictator]

I've been getting IO warnings while just idling my mafia, and I suspect it's related to this, so I'm putting it here:

IOException retrieving server reply (newchatmessages.php?j=1&lasttime=1517040211).

Seems to show up very rarely, but only since yesterday.

 

[esko]

Good call out. Stripping out :status in the nginx responses solved my issue. Thanks again for your help with this.

 

[Magus_Prime]

I suspect that this is related to the HTTP changes. With r26301 the relay browser loaded properly but, post-combat, the character pane did not refresh and the GCLI had the following:

[289] The Dark Neck of the Woods
Encounter: Hellion
Round 0: Arbos wins initiative!
Round 1: You gaze in the mini crystal ball that Nanite Configuration 4821549 is holding and see that if you stay here, your next fight will be against a W imp.
Round 1: You lose 1 hit point
Round 1: Arbos casts NANTLERS!
Round 2: Hellion takes 338 damage.
Round 2: Arbos wins the fight!
After Battle: Peeking into Nanite Configuration 4821549's mini crystal ball, you see yourself. It's hard to make out the details, but it seems like you're doing a good job at... whatever you're doing in there. (+5 Stats)
After Battle: Nanite Configuration 4821549 does the nanobot. Which is a dance like the robot, but smaller and harder to see.
You acquire an item: hellion cube
You acquire an item: white pixel
You acquire an item: stick of firewood
You can now equip a Gaia beads (and possibly other things).
Unexpected error, debug log printed.
Unexpected error, debug log printed.
Unexpected error, debug log printed.
Unexpected error, debug log printed.

After the debug log was generated the character pane did populate but it took, approximately, ten seconds.

 

[Ryo_Sangnoir]

Interesting things from this log:

The error is not from the newly changed GenericRequest, but from FileUtilities, which was changed about two weeks ago. That indicates to me this is a rare occurrence.

The exception is a java.nio.channels.ClosedChannelException, four times (!?). One possibility (that I've filed a PR for) is that the pseudo-response for a cached image includes "Connection: close", and maybe that makes the client close a connection when it doesn't need to?

 

[Irrat]

I've been getting IO warnings while just idling my mafia, and I suspect it's related to this, so I'm putting it here:

Seems to show up very rarely, but only since yesterday.

Was thinking of making a bug report for this, but I'm not sure if it can be linked to this https://bugs.openjdk.java.net/browse/JDK-8198947

The error itself is

IOException: GOAWAY received

I'm using Java 11, are you on 11 too? Could be the case this would be fixed if java is updated.

Another possible reason I found was in stackoverflow. Link to stackoverflow

 

[fronobulax]

Maybe this is of interest here?

IOException retrieving server reply (http://dcdb.coldfront.net/collectio...st_query_type=player&last_query_value=2115655) -- HTTP/1.1 header parser received no bytes.

The script that generates it asks Coldfront for a collection ranking page and, when successful, scrapes it. Over the years there would be errors so the script now stops trying after the second error. I'm getting this pretty consistently lately.

 

[Ryo_Sangnoir]

I suspect that this is related to the HTTP changes. With r26301 the relay browser loaded properly but, post-combat, the character pane did not refresh and the GCLI had the following:

After the debug log was generated the character pane did populate but it took, approximately, ten seconds.

Question here: are you using a proxy? This is what happens if the proxy goes down briefly.

 

[Magus_Prime]

I'm not using a proxy. I play daily, the the current release at the time of playing, and this is the first, and so far only, time I've seen the behavior described.

 

[Magus_Prime]

Something similar happened again today. This time it was as I finished running turns for today. There was no disruption of play or the relay browser. Debug log attached.