New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
net/http: HTTP/2 POST via Akamai (maybe) corrupted #13637
Comments
With http2VerboseLogs on, here is a repro: $ ./lego -m "test12@nella.org" -s "https://acme-staging.api.letsencrypt.org/directory" -d nella.org -d blog.nella.org run Lines marked with ** above are debugging I added into lego's jws.go in order to know exactly what was passed into http.Post. You can use the repro case exactly as this. The test11@nella.org account does not exist in staging, so it will always try to make a new one and fail on the POST new-reg. The problem, as I see it, is that I can't get visibility into what's coming out of Akami's nginix and going towards letencrypt's origin server. |
Added logging to h2_bundle.go and confirmed that writeRequestBody is making one sole call to cc.fr.WriteData with all the data in the third argument, and no error returned. |
Rather than editing h2_bundle.go directly (which is kind of ugly), I find it easier to modify golang.org/x/net/http2 instead and then run the bundle command to bring it into net/http: #!/bin/bash
set -e
go get golang.org/x/tools/cmd/bundle
bundle golang.org/x/net/http2 net/http http2 > /tmp/bund.go
mv /tmp/bund.go $GOROOT/go/src/net/http/h2_bundle.go The logs above are too verbose. I think we only care about the headers and data the h1 and h2 transports write. (not read) |
I left details in letsencrypt/boulder#1279 |
Per letsencrypt/boulder#1279 (comment) , this was confirmed to be a problem on Akamai's side which they're fixing. Closing this bug. |
GODEBUG=h2debug=1 is now GODEBUG=http2debug=1, per golang/go#13611 (comment golang/go#13611 (comment)) and there is a new debugging level h2debug=2 for logging all written frames as well, which was code I originally wrote for debugging the lego/ACME/Akamai issues in golang/go#13637 and letsencrypt/boulder#1279. This also moves the common vlogf calls inside if VerboseLogs blocks, to avoid allocations. I didn't do the rare ones. Example client output, fetching https://ip.appspot.com/: 2016/01/07 23:24:52 http2: Transport failed to get client conn for ip.appspot.com:443: http2: no cached connection was available 2016/01/07 23:24:52 http2: Transport creating client conn to 64.233.183.141:443 2016/01/07 23:24:52 http2: Framer 0xc82028c420: wrote SETTINGS len=12, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304 2016/01/07 23:24:52 http2: Framer 0xc82028c420: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824 2016/01/07 23:24:52 http2: Framer 0xc82028c420: wrote SETTINGS flags=ACK len=0 2016/01/07 23:24:52 http2: Transport encoding header ":authority" = "ip.appspot.com" 2016/01/07 23:24:52 http2: Transport encoding header ":method" = "GET" 2016/01/07 23:24:52 http2: Transport encoding header ":path" = "/" 2016/01/07 23:24:52 http2: Transport encoding header ":scheme" = "https" 2016/01/07 23:24:52 http2: Transport encoding header "accept-encoding" = "gzip" 2016/01/07 23:24:52 http2: Transport encoding header "user-agent" = "Go-http-client/2.0" 2016/01/07 23:24:52 http2: Transport received WINDOW_UPDATE len=4 (conn) incr=983041 2016/01/07 23:24:52 http2: Framer 0xc82028c420: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=35 2016/01/07 23:24:52 http2: Transport received SETTINGS flags=ACK len=0 2016/01/07 23:24:52 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=123 2016/01/07 23:24:52 http2: Transport decoded header field ":status" = "200" 2016/01/07 23:24:52 http2: Transport decoded header field "content-type" = "text/plain;" 2016/01/07 23:24:52 http2: Transport decoded header field "date" = "Thu, 07 Jan 2016 23:24:52 GMT" 2016/01/07 23:24:52 http2: Transport decoded header field "server" = "Google Frontend" 2016/01/07 23:24:52 http2: Transport decoded header field "content-length" = "14" 2016/01/07 23:24:52 http2: Transport decoded header field "alternate-protocol" = "443:quic,p=1" 2016/01/07 23:24:52 http2: Transport decoded header field "alt-svc" = "quic=\":443\"; ma=604800; v=\"30,29,28,27,26,25\"" 2016/01/07 23:24:52 http2: Transport received DATA flags=END_STREAM stream=1 len=14 data="146.148.92.232" 2016/01/07 23:24:52 http2: Transport received PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00" 2016/01/07 23:24:52 http2: Framer 0xc82028c420: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00" Example server output, with a client fetching / and getting a 404: 2016/01/07 23:25:45 http2: server connection from 72.14.229.81:58273 on 0xc820066100 2016/01/07 23:25:45 http2: server: error reading preface from client 72.14.229.81:58273: EOF 2016/01/07 23:25:45 http2: Framer 0xc820228210: wrote SETTINGS len=18, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896 2016/01/07 23:25:45 http2: server connection from 72.14.229.81:6801 on 0xc820066100 2016/01/07 23:25:45 http2: Framer 0xc8202e8370: wrote SETTINGS len=18, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896 2016/01/07 23:25:45 http2: server: client 72.14.229.81:6801 said hello 2016/01/07 23:25:45 http2: server read frame SETTINGS len=12, settings: MAX_CONCURRENT_STREAMS=1000, INITIAL_WINDOW_SIZE=6291456 2016/01/07 23:25:45 http2: server processing setting [MAX_CONCURRENT_STREAMS = 1000] 2016/01/07 23:25:45 http2: server processing setting [INITIAL_WINDOW_SIZE = 6291456] 2016/01/07 23:25:45 http2: Framer 0xc8202e8370: wrote SETTINGS flags=ACK len=0 2016/01/07 23:25:45 http2: server read frame WINDOW_UPDATE len=4 (conn) incr=15663105 2016/01/07 23:25:45 http2: server read frame HEADERS flags=END_STREAM|END_HEADERS|PRIORITY stream=1 len=238 2016/01/07 23:25:45 http2: server decoded header field ":method" = "GET" 2016/01/07 23:25:45 http2: server decoded header field ":authority" = "(redacted):4430" 2016/01/07 23:25:45 http2: server decoded header field ":scheme" = "https" 2016/01/07 23:25:45 http2: server decoded header field ":path" = "/" 2016/01/07 23:25:45 http2: server decoded header field "cache-control" = "max-age=0" 2016/01/07 23:25:45 http2: server decoded header field "accept" = "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8" 2016/01/07 23:25:45 http2: server decoded header field "upgrade-insecure-requests" = "1" 2016/01/07 23:25:45 http2: server decoded header field "user-agent" = "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_2) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/47.0.2526.106 Safari/537." 2016/01/07 23:25:45 http2: server decoded header field "accept-encoding" = "gzip, deflate, sdch" 2016/01/07 23:25:45 http2: server decoded header field "accept-language" = "en-US,en;q=0.8" 2016/01/07 23:25:45 http2: server encoding header ":status" = "404" 2016/01/07 23:25:45 http2: server encoding header "content-type" = "text/plain; charset=utf-8" 2016/01/07 23:25:45 http2: server encoding header "x-content-type-options" = "nosniff" 2016/01/07 23:25:45 http2: server encoding header "content-length" = "19" 2016/01/07 23:25:45 http2: server encoding header "date" = "Thu, 07 Jan 2016 23:25:45 GMT" 2016/01/07 23:25:45 http2: Framer 0xc8202e8370: wrote HEADERS flags=END_HEADERS stream=1 len=73 2016/01/07 23:25:45 http2: Framer 0xc8202e8370: wrote DATA flags=END_STREAM stream=1 len=19 data="404 page not found\n" 2016/01/07 23:25:45 http2: server read frame SETTINGS flags=ACK len=0 Change-Id: Ifb3fe4e588ff54abd8bc3facbb419c3c3809bcba Reviewed-on: https://go-review.googlesource.com/18372 Reviewed-by: Blake Mizerany <blake.mizerany@gmail.com> Reviewed-by: Andrew Gerrand <adg@golang.org>
I am currently chasing down a poor interaction between Go's HTTP/2, github.com/xenolf/lego, github.com/letsencrypt/boulder and Akamai:
letsencrypt/boulder#1279
The server is seeing different bytes in the body of the POST depending on if the connection comes in as HTTP/2 or not.
I do not have any evidence yet that Go's HTTP/2 is implicated in this, but Brad asked me to file this while we are looking for more info.
I am using:
$ go version
go version devel +85dd62d Sat Dec 12 06:46:56 2015 +0000 darwin/amd64
lego from commit bf740fa2cafb7d6deb0911792a13f37ef5995a03
The text was updated successfully, but these errors were encountered: