new-req over HTTP/2 causes "Error 400 - urn:acme:error:malformed"

[jeffallen]

I was trying to use lego to register. I was using Go from tip, and I got:

./lego -m "test10@nella.org" -s "https://acme-staging.api.letsencrypt.org/directory" -d nella.org -d blog.nella.org run
2015/12/15 20:14:01 No key found for account test10@nella.org. Generating a 2048 bit key.
2015/12/15 20:14:01 Saved key to /Users/jra/src/github.com/xenolf/lego/.lego/accounts/acme-staging.api.letsencrypt.org/test10@nella.org/keys/test10@nella.org.key
2015/12/15 20:14:02 [INFO] acme: Registering account for test10@nella.org
2015/12/15 20:14:02 Could not complete registration
acme: Error 400 - urn:acme:error:malformed - Unable to read/verify body :: Parse error reading JWS

After a lot of bisecting, I found that what's changed in Go tip to cause this is the introduction of HTTP/2 by default. When I turn off Go's HTTP/2 client support, it works:

GODEBUG=h2client=0 ./lego -m "test11@nella.org" -s "https://acme-staging.api.letsencrypt.org/directory" -d nella.org -d blog.nella.org run
2015/12/15 20:37:41 No key found for account test11@nella.org. Generating a 2048 bit key.
2015/12/15 20:37:41 Saved key to /Users/jra/src/github.com/xenolf/lego/.lego/accounts/acme-staging.api.letsencrypt.org/test11@nella.org/keys/test11@nella.org.key
2015/12/15 20:37:43 [INFO] acme: Registering account for test11@nella.org
2015/12/15 20:37:44 !!!! HEADS UP !!!!
2015/12/15 20:37:44
Your account credentials have been saved in your Let's Encrypt
configuration directory at "/Users/jra/src/github.com/xenolf/lego/.lego/accounts/acme-staging.api.letsencrypt.org/test11@nella.org".
You should make a secure backup of this folder now. This
configuration directory will also contain certificates and
private keys obtained from Let's Encrypt so making regular
backups of this folder is ideal.
2015/12/15 20:37:44 Please review the TOS at https://letsencrypt.org/documents/LE-SA-v1.0.1-July-27-2015.pdf
2015/12/15 20:37:44 Do you accept the TOS? Y/n

Note the addition of the GODEBUG environment variable.

What is your HTTP/2 implementation? Can we get some extra debugging near urn:acme:error:malformed to find out what bytes are making there?

(This happens on the live servers too, not only staging.)

[jsha]

In prod and staging we are fronted by Akamai, so any HTTP/2 interaction is through them. We should do some more testing to see what makes it through on the other side. In theory there should be no difference, but it looks like there is!

[bradfitz]

Here's what I see from Go's side:

$ lego -m "test10@nella.org" -s "https://acme-staging.api.letsencrypt.org/directory" run
http2: debug: Wrote [FrameHeader SETTINGS len=12]
http2: debug: Wrote [FrameHeader WINDOW_UPDATE len=4]
http2: debug: Wrote [FrameHeader SETTINGS flags=ACK len=0]
http2: debug:   writing header = ":authority" = "acme-staging.api.letsencrypt.org"
http2: debug:   writing header = ":method" = "GET"
http2: debug:   writing header = ":path" = "/directory"
http2: debug:   writing header = ":scheme" = "https"
http2: debug:   writing header = "accept-encoding" = "gzip"
http2: debug: Wrote [FrameHeader HEADERS flags=END_STREAM|END_HEADERS stream=1 len=41]
2015/12/16 20:23:29 [INFO] acme: Registering account for test10@nella.org
http2: debug:   writing header = ":authority" = "acme-staging.api.letsencrypt.org"
http2: debug:   writing header = ":method" = "HEAD"
http2: debug:   writing header = ":path" = "/directory"
http2: debug:   writing header = ":scheme" = "https"
http2: debug: Wrote [FrameHeader HEADERS flags=END_STREAM|END_HEADERS stream=3 len=9]
http2: debug:   writing header = ":authority" = "acme-staging.api.letsencrypt.org"
http2: debug:   writing header = ":method" = "POST"
http2: debug:   writing header = ":path" = "/acme/new-reg"
http2: debug:   writing header = ":scheme" = "https"
http2: debug:   writing header = "content-type" = "application/jose+json"
http2: debug:   writing header = "accept-encoding" = "gzip"
http2: debug: Wrote [FrameHeader HEADERS flags=END_HEADERS stream=5 len=34]
http2: debug: Wrote [FrameHeader DATA stream=5 len=1065]
http2: debug:  data = "{\"payload\":\"eyJyZXNvdXJjZSI6Im5ldy1yZWciLCJjb250YWN0IjpbIm1haWx0bzp0ZXN0MTBAbmVsbGEub3JnIl19\",\"protected\":\"eyJhbGciOiJSUzI1NiIsImp3ayI6eyJrdHkiOiJSU0EiLCJuIjoicldOMkNpZTdLbFl6NWpyYUhXMFh4aWptVFZhMG8xdFNnWUtVSFh2Z1NGV2xiWUxRVHNwRDhhUGJab3ItanVtZWlVTDQ0NWlLRDhvMUVwcElfZ1dveHQtVkdfNW93cXNVZ3BHcXhDZXNVdXNGMWlvbkRicVVndWtDSTY2MFA0dDJNUms4NUNuRElRaUs5UWRsT3JTMTQ0a0ZOUERwN2o2MlM5akR6clRVWlQ5ZVZ5S3VWbjZxb1BuYlBUZ0JrNl81MTNuVERFZTB4VEpMc2lZSXJzVzJTQlVhV1VZc3NubndWZ0xpaGdaeEFaaHhpZXRFNjRpMHQ4YURRanBuVEUtVEJqbzlQako2SHJsRE5OaWxUWm1xenFlN1BGMk1aZlZ1REhXN2NMT01Ea28yTjMwcUx0M2E3R0x0WldrZEp2T1I4czBYT053R1pzSkxfYTA4MzBoSHBRIiwiZSI6IkFRQUIifSwibm9uY2UiOiItYjY4aTVjRnRSRzQ1ekFGOEg3QWtJVWNRRm45Y3hsaHR2YW1WTUhlQlQwIn0\",\"signature\":\"Fe4P8K47WLFkz4UJgC0wdhwGZpX0Tx834UNn_Kb2hr8FDQRCPrlNywwVm1ZVtVBuuJOaiS3A-F4m89IiUN_Bjw69Da7V1cDwOcegLOKCoCPi08iCy6WeZ6JlxuVIjOVPysGgk185Ovwi-SqR4PswJbGj-w3JrIs3RIJoKc9GWPci3pTA-v5umhT6wKyAk0QbdJN4KWiMQunfEAuwFAtiht8UTXM1nYRzZ0_Yo-7JU_6TitIH-wb_de_2bnbuyY7txOAHP0BwcCX3qipbMJhXpHNyRBnTyd3WOoOqk2G2fGgrq6gAa7YZM3e5mLY-fBk9oQ__JbGmFbcBek-_n9uyfg\"}"
http2: debug: Wrote [FrameHeader DATA flags=END_STREAM stream=5 len=0]
http2: debug:  data = ""
2015/12/16 20:23:29 Could not complete registration
        acme: Error 400 - urn:acme:error:malformed - Unable to read/verify body :: Parse error reading JWS

My local change to debug this was: https://go-review.googlesource.com/#/c/17897 (maybe I'll make that opt-in with some environment variable)

Let me know if you need more info.

Some guesses:

• case of headers? (required to be lowercase in HTTP/2)
• the :authority vs Host header? (maybe that's my bug? will re-read)
• the http2 package's implicit "accept-encoding: gzip"? But Go's http1 does that too.

[jeffallen]

By reading the headers Brad's change logs, I can see that Akamai is using nginx. I have tried to create a repro case with:

(1) Go http/2 client POSTing
v
nginx, listening for http/2 (tip)
-----reverse-proxy----v
(2) HTTP/1.1 server echoing POST requests

1: https://github.com/jeffallen/jra-go/tree/master/cmd/h2post
2: https://github.com/jeffallen/jra-go/tree/master/cmd/echopost

I found that all the bytes POSTed in via HTTP/2 were coming back as expected. There are lots of variable to vary, but it is hard to do so without some knowledge from Akamai how they have their nginx (which version? with what patches?) configured with respect to buffers.

Brad and I are eager to diagnose this because the Go team is trying to release Go 1.6 with brand new HTTP/2 support. If this is a minor problem between Akamai and letsencrypt, yay. If this is a symptom of a bug in Go's new HTTP/2, we need to solve it before it is released.

Can we get some help from letsencrypt ops people to find out exactly what is arriving at Boulder to cause the 400? Is is an empty body? A truncated body?

[jcjones]

I don't believe Akamai is using nginx; Let's Encrypt is. When you connect to Akamai's edge, you'll be talking to a piece of software called Ghost that handles the HTTP/2 connection.

As soon as I wake up I'll look at logs to try and pick out @bradfitz's request above and see if we got the body en-route.

[bradfitz]

@jeffallen, what makes you think it's nginx somewhere? Something from the logs I posted, or other logs you saw?

@jcjones, thanks for digging. I'm eager to help as I can from my end.

[jeffallen]

When I run my "h2post" program like this:
GODEBUG=h2debug=1 ./h2post https://localhost:8443/echopost < /etc/services 2>&1 | grep Name:server

I get "{Name:server Value:nginx/1.9.9 Sensitive:false}", which is correct, I am using nginx compiled from tip locally. When I run that against letsencrypt, I get:

GODEBUG=h2debug=1 ./h2post https://acme-staging.api.letsencrypt.org/acme/new-reg < /etc/services 2>&1 | grep Name:server
2015/12/17 14:30:17 Header field: {Name:server Value:nginx Sensitive:true}

I would expect Boulder to give no Server header (the default for a Go webserver) or give "Server: boulder". So I think that whatever is doing the http2->http reverse proxy is adding the "Server: nginx".

It is circumstantial, but it is also common for service providers like Akamai to remove the version string from a Server header for "security". (Eye-roll.)

If someone from LetsEncrypt could tell me confidentially how to test against the origin server itself, that would be very helpful. Then I could run my own http/2 -> http reverse proxy for my tests, taking Akamai out of the loop.

[jcjones]

Successful run

nginx: <client IP> - - [15/Dec/2015:14:12:34 +0000] "POST /acme/new-reg HTTP/1.1" 201 1022 "-" "Go-http-client/1.1" "acme-staging.api.letsencrypt.org" "0.346" "1714" "eyJhbGciOiJSUzI1NiIsImp3ayI6eyJrdHkiOiJSU0EiLCJuIjoicEs3THVUMmh4a1duWVJsMVRjdzlpQXk5LV9UcXZIcDJ3aDZFY0hxX3dnbHNObXRweEFlOWdOR1pldld1NlQyTzFhRW1QWWtneTdRMW1lS05pZmVuRnVXaWNEY1NTZW5rTU0wSkFwZmR2ZWlWcWpCQTgxRUwwWTc2VDhpMkpvbGdnR1hiaVNhX1pSR3dHLTBGUERTSVgzSnk1bVFnT24tdC16cmhEOXlMRG4yTjd6ekZxQ0JPdHh6cnd6MUhFdE44UVdaQUZBek9jZXl5TDZDNzkxbEdPazlTWVlla3h5dVprd2t6aERFc29xUjdmTjZobXU2SWZJVThoRjVrdDhNX0dlZjMwd3Q1ZFVFU3ZjVE5kbVFtcV9MMVFZQThxWU82LVQwbUMweklwSHB3UW5BTllPU1pCQ3oxdUUtdndTMTdNbGZuVXdHa1BISlhXVGhsTVpxWm1RIiwiZSI6IkFRQUIifSwibm9uY2UiOiJUNUg2M1h3eU9IS3BBRVRGcEhSOHN0WFNraGtxaGxBWTF4VjdWc0NuT3JzIn0.eyJyZXNvdXJjZSI6Im5ldy1yZWciLCJjb250YWN0IjpbIm1haWx0bzp0ZXN0OUBuZWxsYS5vcmciXX0.PLl0S6pxs6yT-9aK6cjPrBotaQyz_Osj2EAAnpWhCM1pjcmRXWLXdSSO4p4oWmMBev58ZCfDN2uf5_MjvlAsjcJYihPlt-Hg3rgKY-5QhhSgpFV1uWUpXG-ZPttJdit3Q3ASUlM4sn8OahreJP0u34sRF-_POyd-ucsExUU_Y9608JlIx4llR5WyFvo7L-3jq-_82DJlJFSMBj1yfdvMgTuIzMmkRVdaXiqKRE4W51vGH7L6EpozKCAIxvjvc1I1W-CdgypwbGnfPhcJ8oQtHbPCL1DcqFaL-kjkLqeola8nRFDtHqK_Vu6_f2gZ11aTYdGQOw4xDh1nhyCVLcOD1w"

• user agent: Go-http-client/1.1
• request time: .346
• request length: 1714
• request body: stuff!
• bytes sent: 1022

Failed Run

nginx: <client IP> - - [15/Dec/2015:14:11:08 +0000] "POST /acme/new-reg HTTP/1.1" 400 337 "-" "-" "acme-staging.api.letsencrypt.org" "0.003" "657" "-"

• user agent: -
• request time: .003
• request length: 657
• request body: -
• bytes sent: 337

[jeffallen]

Interesting. I half expected the empty body. But the missing user agent header might be an interesting clue. Brad already posted logs showing the ua going out from lego, so it disappeared (along with the content-length, maybe?) when leaving Akamai. It would be helpful to have an Akamai person review this data if you can help make that happen... thanks.

[bradfitz]

@jeffallen, my logs above did not show a user-agent. Is that relevant to the JWS signature?

[jeffallen]

Sorry, I didn't check well enough, about the ua header.

The UA header is not involved in the JWS signature. The mental model I am working under is that there's some unwanted transformation happening in the http2->http reverse proxy step so that the body bytes presented on the http2 input side do not arrive at the http input (i.e. into boulder). So I'm looking for things that would make that happen, like losing headers. A missing content-length header will make the body of a POST appear to be missing, right?

[bradfitz]

Missing content-length is fine in both http1 and http2. It's chunking eof chunk (in http1) or END_STREAM (in http2) that says the POST body is over.

[jsha]

FWIW, Akamai's GHost rejects http1 POSTs without Content-Length by default. Not sure what it does in http2. I've emailed a contact at Akamai to look into it, and he'll take a look on Monday. I did a little testing myself, and this does seem pretty clearly like the POST body is not making it through to Nginx for some reason.