Skip to content
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

Closed
jeffallen opened this issue Dec 16, 2015 · 5 comments

Comments

Projects
None yet
3 participants
@jeffallen
Copy link
Contributor

commented Dec 16, 2015

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

@bradfitz bradfitz added this to the Go1.6 milestone Dec 16, 2015

@bradfitz bradfitz self-assigned this Dec 16, 2015

@bradfitz bradfitz changed the title HTTP/2 POST via Akamai (maybe) corrupted net/http: HTTP/2 POST via Akamai (maybe) corrupted Dec 16, 2015

@jeffallen

This comment has been minimized.

Copy link
Contributor Author

commented Dec 16, 2015

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
2015/12/16 11:47:40 No key found for account test12@nella.org. Generating a 2048 bit key.
2015/12/16 11:47:41 Saved key to /Users/jra/src/github.com/xenolf/lego/.lego/accounts/acme-staging.api.letsencrypt.org/test12@nella.org/keys/test12@nella.org.key
2015/12/16 11:47:41 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 16384]
2015/12/16 11:47:41 Transport received [FrameHeader WINDOW_UPDATE len=4]: &http.http2WindowUpdateFrame{http2FrameHeader:http.http2FrameHeader{valid:true, Type:0x8, Flags:0x0, Length:0x4, StreamID:0x0}, Increment:0x1}
2015/12/16 11:47:41 Transport received [FrameHeader SETTINGS flags=ACK len=0]: &http.http2SettingsFrame{http2FrameHeader:http.http2FrameHeader{valid:true, Type:0x4, Flags:0x1, Length:0x0, StreamID:0x0}, p:[]uint8{}}
2015/12/16 11:47:42 Transport received [FrameHeader HEADERS flags=END_HEADERS stream=1 len=244]: &http.http2HeadersFrame{http2FrameHeader:http.http2FrameHeader{valid:true, Type:0x1, Flags:0x4, Length:0xf4, StreamID:0x1}, Priority:http.http2PriorityParam{StreamDep:0x0, Exclusive:false, Weight:0x0}, headerFragBuf:[]uint8{0x88, 0x1f, 0x27, 0x5, 0x6e, 0x67, 0x69, 0x6e, 0x78, 0x1f, 0x10, 0x10, 0x61, 0x70, 0x70, 0x6c, 0x69, 0x63, 0x61, 0x74, 0x69, 0x6f, 0x6e, 0x2f, 0x6a, 0x73, 0x6f, 0x6e, 0x1f, 0xd, 0x3, 0x32, 0x37, 0x39, 0x10, 0xc, 0x72, 0x65, 0x70, 0x6c, 0x61, 0x79, 0x2d, 0x6e, 0x6f, 0x6e, 0x63, 0x65, 0x2b, 0x71, 0x51, 0x58, 0x63, 0x6b, 0x32, 0x78, 0x51, 0x52, 0x7a, 0x70, 0x79, 0x4f, 0x68, 0x67, 0x79, 0x49, 0x32, 0x52, 0x42, 0x55, 0x6b, 0x47, 0x76, 0x58, 0x44, 0x33, 0x32, 0x74, 0x56, 0x56, 0x32, 0x42, 0x5a, 0x79, 0x42, 0x56, 0x49, 0x35, 0x70, 0x58, 0x79, 0x34, 0x10, 0xf, 0x78, 0x2d, 0x66, 0x72, 0x61, 0x6d, 0x65, 0x2d, 0x6f, 0x70, 0x74, 0x69, 0x6f, 0x6e, 0x73, 0x4, 0x44, 0x45, 0x4e, 0x59, 0x1f, 0x29, 0xe, 0x6d, 0x61, 0x78, 0x2d, 0x61, 0x67, 0x65, 0x3d, 0x36, 0x30, 0x34, 0x38, 0x30, 0x30, 0x1f, 0x15, 0x1d, 0x57, 0x65, 0x64, 0x2c, 0x20, 0x31, 0x36, 0x20, 0x44, 0x65, 0x63, 0x20, 0x32, 0x30, 0x31, 0x35, 0x20, 0x30, 0x35, 0x3a, 0x34, 0x37, 0x3a, 0x34, 0x33, 0x20, 0x47, 0x4d, 0x54, 0x1f, 0x9, 0x1d, 0x6d, 0x61, 0x78, 0x2d, 0x61, 0x67, 0x65, 0x3d, 0x30, 0x2c, 0x20, 0x6e, 0x6f, 0x2d, 0x63, 0x61, 0x63, 0x68, 0x65, 0x2c, 0x20, 0x6e, 0x6f, 0x2d, 0x73, 0x74, 0x6f, 0x72, 0x65, 0x10, 0x6, 0x70, 0x72, 0x61, 0x67, 0x6d, 0x61, 0x8, 0x6e, 0x6f, 0x2d, 0x63, 0x61, 0x63, 0x68, 0x65, 0x1f, 0x12, 0x1d, 0x57, 0x65, 0x64, 0x2c, 0x20, 0x31, 0x36, 0x20, 0x44, 0x65, 0x63, 0x20, 0x32, 0x30, 0x31, 0x35, 0x20, 0x30, 0x35, 0x3a, 0x34, 0x37, 0x3a, 0x34, 0x33, 0x20, 0x47, 0x4d, 0x54}}
2015/12/16 11:47:42 Header field: {Name::status Value:200 Sensitive:false}
2015/12/16 11:47:42 Header field: {Name:server Value:nginx Sensitive:true}
2015/12/16 11:47:42 Header field: {Name:content-type Value:application/json Sensitive:true}
2015/12/16 11:47:42 Header field: {Name:content-length Value:279 Sensitive:true}
2015/12/16 11:47:42 Header field: {Name:replay-nonce Value:qQXck2xQRzpyOhgyI2RBUkGvXD32tVV2BZyBVI5pXy4 Sensitive:true}
2015/12/16 11:47:42 Header field: {Name:x-frame-options Value:DENY Sensitive:true}
2015/12/16 11:47:42 Header field: {Name:strict-transport-security Value:max-age=604800 Sensitive:true}
2015/12/16 11:47:42 Header field: {Name:expires Value:Wed, 16 Dec 2015 05:47:43 GMT Sensitive:true}
2015/12/16 11:47:42 Header field: {Name:cache-control Value:max-age=0, no-cache, no-store Sensitive:true}
2015/12/16 11:47:42 Header field: {Name:pragma Value:no-cache Sensitive:true}
2015/12/16 11:47:42 Header field: {Name:date Value:Wed, 16 Dec 2015 05:47:43 GMT Sensitive:true}
2015/12/16 11:47:42 Transport received [FrameHeader DATA stream=1 len=279]: &http.http2DataFrame{http2FrameHeader:http.http2FrameHeader{valid:true, Type:0x0, Flags:0x0, Length:0x117, StreamID:0x1}, data:[]uint8{0x7b, 0x22, 0x6e, 0x65, 0x77, 0x2d, 0x61, 0x75, 0x74, 0x68, 0x7a, 0x22, 0x3a, 0x22, 0x68, 0x74, 0x74, 0x70, 0x73, 0x3a, 0x2f, 0x2f, 0x61, 0x63, 0x6d, 0x65, 0x2d, 0x73, 0x74, 0x61, 0x67, 0x69, 0x6e, 0x67, 0x2e, 0x61, 0x70, 0x69, 0x2e, 0x6c, 0x65, 0x74, 0x73, 0x65, 0x6e, 0x63, 0x72, 0x79, 0x70, 0x74, 0x2e, 0x6f, 0x72, 0x67, 0x2f, 0x61, 0x63, 0x6d, 0x65, 0x2f, 0x6e, 0x65, 0x77, 0x2d, 0x61, 0x75, 0x74, 0x68, 0x7a, 0x22, 0x2c, 0x22, 0x6e, 0x65, 0x77, 0x2d, 0x63, 0x65, 0x72, 0x74, 0x22, 0x3a, 0x22, 0x68, 0x74, 0x74, 0x70, 0x73, 0x3a, 0x2f, 0x2f, 0x61, 0x63, 0x6d, 0x65, 0x2d, 0x73, 0x74, 0x61, 0x67, 0x69, 0x6e, 0x67, 0x2e, 0x61, 0x70, 0x69, 0x2e, 0x6c, 0x65, 0x74, 0x73, 0x65, 0x6e, 0x63, 0x72, 0x79, 0x70, 0x74, 0x2e, 0x6f, 0x72, 0x67, 0x2f, 0x61, 0x63, 0x6d, 0x65, 0x2f, 0x6e, 0x65, 0x77, 0x2d, 0x63, 0x65, 0x72, 0x74, 0x22, 0x2c, 0x22, 0x6e, 0x65, 0x77, 0x2d, 0x72, 0x65, 0x67, 0x22, 0x3a, 0x22, 0x68, 0x74, 0x74, 0x70, 0x73, 0x3a, 0x2f, 0x2f, 0x61, 0x63, 0x6d, 0x65, 0x2d, 0x73, 0x74, 0x61, 0x67, 0x69, 0x6e, 0x67, 0x2e, 0x61, 0x70, 0x69, 0x2e, 0x6c, 0x65, 0x74, 0x73, 0x65, 0x6e, 0x63, 0x72, 0x79, 0x70, 0x74, 0x2e, 0x6f, 0x72, 0x67, 0x2f, 0x61, 0x63, 0x6d, 0x65, 0x2f, 0x6e, 0x65, 0x77, 0x2d, 0x72, 0x65, 0x67, 0x22, 0x2c, 0x22, 0x72, 0x65, 0x76, 0x6f, 0x6b, 0x65, 0x2d, 0x63, 0x65, 0x72, 0x74, 0x22, 0x3a, 0x22, 0x68, 0x74, 0x74, 0x70, 0x73, 0x3a, 0x2f, 0x2f, 0x61, 0x63, 0x6d, 0x65, 0x2d, 0x73, 0x74, 0x61, 0x67, 0x69, 0x6e, 0x67, 0x2e, 0x61, 0x70, 0x69, 0x2e, 0x6c, 0x65, 0x74, 0x73, 0x65, 0x6e, 0x63, 0x72, 0x79, 0x70, 0x74, 0x2e, 0x6f, 0x72, 0x67, 0x2f, 0x61, 0x63, 0x6d, 0x65, 0x2f, 0x72, 0x65, 0x76, 0x6f, 0x6b, 0x65, 0x2d, 0x63, 0x65, 0x72, 0x74, 0x22, 0x7d}}
2015/12/16 11:47:42 DATA: "{"new-authz":"https://acme-staging.api.letsencrypt.org/acme/new-authz\",\"new-cert\":\"https://acme-staging.api.letsencrypt.org/acme/new-cert\",\"new-reg\":\"https://acme-staging.api.letsencrypt.org/acme/new-reg\",\"revoke-cert\":\"https://acme-staging.api.letsencrypt.org/acme/revoke-cert\"}"
2015/12/16 11:47:42 Transport received [FrameHeader DATA flags=END_STREAM stream=1 len=0]: &http.http2DataFrame{http2FrameHeader:http.http2FrameHeader{valid:true, Type:0x0, Flags:0x1, Length:0x0, StreamID:0x1}, data:[]uint8{}}
2015/12/16 11:47:42 directory: acme.directory{NewAuthzURL:"https://acme-staging.api.letsencrypt.org/acme/new-authz", NewCertURL:"https://acme-staging.api.letsencrypt.org/acme/new-cert", NewRegURL:"https://acme-staging.api.letsencrypt.org/acme/new-reg", RevokeCertURL:"https://acme-staging.api.letsencrypt.org/acme/revoke-cert"}
2015/12/16 11:47:42 DATA: ""
2015/12/16 11:47:42 [INFO] acme: Registering account for test12@nella.org
2015/12/16 11:47:42 Transport received [FrameHeader HEADERS flags=END_HEADERS stream=3 len=242]: &http.http2HeadersFrame{http2FrameHeader:http.http2FrameHeader{valid:true, Type:0x1, Flags:0x4, Length:0xf2, StreamID:0x3}, Priority:http.http2PriorityParam{StreamDep:0x0, Exclusive:false, Weight:0x0}, headerFragBuf:[]uint8{0x88, 0x1f, 0x27, 0x5, 0x6e, 0x67, 0x69, 0x6e, 0x78, 0x1f, 0x10, 0x10, 0x61, 0x70, 0x70, 0x6c, 0x69, 0x63, 0x61, 0x74, 0x69, 0x6f, 0x6e, 0x2f, 0x6a, 0x73, 0x6f, 0x6e, 0x10, 0xc, 0x72, 0x65, 0x70, 0x6c, 0x61, 0x79, 0x2d, 0x6e, 0x6f, 0x6e, 0x63, 0x65, 0x2b, 0x51, 0x41, 0x30, 0x76, 0x5f, 0x62, 0x31, 0x2d, 0x6c, 0x75, 0x44, 0x77, 0x51, 0x42, 0x6c, 0x6e, 0x4b, 0x55, 0x6f, 0x42, 0x6b, 0x53, 0x44, 0x4e, 0x6d, 0x6f, 0x75, 0x6b, 0x32, 0x55, 0x45, 0x77, 0x65, 0x77, 0x48, 0x54, 0x43, 0x34, 0x66, 0x56, 0x58, 0x46, 0x59, 0x10, 0xf, 0x78, 0x2d, 0x66, 0x72, 0x61, 0x6d, 0x65, 0x2d, 0x6f, 0x70, 0x74, 0x69, 0x6f, 0x6e, 0x73, 0x4, 0x44, 0x45, 0x4e, 0x59, 0x1f, 0x29, 0xe, 0x6d, 0x61, 0x78, 0x2d, 0x61, 0x67, 0x65, 0x3d, 0x36, 0x30, 0x34, 0x38, 0x30, 0x30, 0x1f, 0xd, 0x1, 0x30, 0x1f, 0x15, 0x1d, 0x57, 0x65, 0x64, 0x2c, 0x20, 0x31, 0x36, 0x20, 0x44, 0x65, 0x63, 0x20, 0x32, 0x30, 0x31, 0x35, 0x20, 0x30, 0x35, 0x3a, 0x34, 0x37, 0x3a, 0x34, 0x34, 0x20, 0x47, 0x4d, 0x54, 0x1f, 0x9, 0x1d, 0x6d, 0x61, 0x78, 0x2d, 0x61, 0x67, 0x65, 0x3d, 0x30, 0x2c, 0x20, 0x6e, 0x6f, 0x2d, 0x63, 0x61, 0x63, 0x68, 0x65, 0x2c, 0x20, 0x6e, 0x6f, 0x2d, 0x73, 0x74, 0x6f, 0x72, 0x65, 0x10, 0x6, 0x70, 0x72, 0x61, 0x67, 0x6d, 0x61, 0x8, 0x6e, 0x6f, 0x2d, 0x63, 0x61, 0x63, 0x68, 0x65, 0x1f, 0x12, 0x1d, 0x57, 0x65, 0x64, 0x2c, 0x20, 0x31, 0x36, 0x20, 0x44, 0x65, 0x63, 0x20, 0x32, 0x30, 0x31, 0x35, 0x20, 0x30, 0x35, 0x3a, 0x34, 0x37, 0x3a, 0x34, 0x34, 0x20, 0x47, 0x4d, 0x54}}
2015/12/16 11:47:42 Header field: {Name::status Value:200 Sensitive:false}
2015/12/16 11:47:42 Header field: {Name:server Value:nginx Sensitive:true}
2015/12/16 11:47:42 Header field: {Name:content-type Value:application/json Sensitive:true}
2015/12/16 11:47:42 Header field: {Name:replay-nonce Value:QA0v_b1-luDwQBlnKUoBkSDNmouk2UEwewHTC4fVXFY Sensitive:true}
2015/12/16 11:47:43 Header field: {Name:x-frame-options Value:DENY Sensitive:true}
2015/12/16 11:47:43 Header field: {Name:strict-transport-security Value:max-age=604800 Sensitive:true}
2015/12/16 11:47:43 Header field: {Name:content-length Value:0 Sensitive:true}
2015/12/16 11:47:43 Header field: {Name:expires Value:Wed, 16 Dec 2015 05:47:44 GMT Sensitive:true}
2015/12/16 11:47:43 Header field: {Name:cache-control Value:max-age=0, no-cache, no-store Sensitive:true}
2015/12/16 11:47:43 Header field: {Name:pragma Value:no-cache Sensitive:true}
2015/12/16 11:47:43 Header field: {Name:date Value:Wed, 16 Dec 2015 05:47:44 GMT Sensitive:true}
2015/12/16 11:47:43 Transport received [FrameHeader DATA flags=END_STREAM stream=3 len=0]: &http.http2DataFrame{http2FrameHeader:http.http2FrameHeader{valid:true, Type:0x0, Flags:0x1, Length:0x0, StreamID:0x3}, data:[]uint8{}}
2015/12/16 11:47:43 DATA: ""
2015/12/16 11:47:43 POST https://acme-staging.api.letsencrypt.org/acme/new-reg
2015/12/16 11:47:43 {"payload":"eyJyZXNvdXJjZSI6Im5ldy1yZWciLCJjb250YWN0IjpbIm1haWx0bzp0ZXN0MTJAbmVsbGEub3JnIl19","protected":"eyJhbGciOiJSUzI1NiIsImp3ayI6eyJrdHkiOiJSU0EiLCJuIjoidmpBYTk5QXpXWTBLTjhrNXhGZlAyNW90WVRMUGJtTWpuZ29fNmduU0t6NDBxU2Q1bl95R0t5OXJsOFRza1RQUWZLN1hFZWJ4Y2ZmeG5VUUNSbUxCNlZBTU96T0VsMThVb05lZmJ4YXc5RjhWZTVyVzBmY29ScFpvUVZfQlFnTUFjQ041SE5iSk1fNE5kTWU5UDMtcjdhaVZjRXd5RHJic0xPOEh6bEdlQlJRT2dMZzdTUlVJbW5LZS1xR3F0SVhyZDd3bjZVM3hOOHNhZGFpcTktdWlYUEw5eG11elJuMUp2Ync2aGs1ZVlNalR5SUpZS1UxbDFXMFgxVDczODVSN2hOMG1CeWpfWUp6VFJ0Uy1LU19XR3RLZnRuQWgzTUFQNlowZkRicmR3bFNqV1RfMG1FeHhLWkh0cUNrZTR5bkZ5cURNZUNlZTBrTnI1cjAzcHFTSmNRIiwiZSI6IkFRQUIifSwibm9uY2UiOiJRQTB2X2IxLWx1RHdRQmxuS1VvQmtTRE5tb3VrMlVFd2V3SFRDNGZWWEZZIn0","signature":"e1wVw0AEDYnxXN6fEhKkMkBpYRmYftkri-PIchejHfwvz_HP8VXEsceXUrwG3BCVDD9KEMbm0ysb5okX7RTqPQimjiew-nMYUG__loSmEtoUPKaLUT5tz-Eh4Uc8Vk74NV0greqMHvf6rSbR-L7cUWgncYwpovx_Eck5M1_qi1xEZWP3oKOD8klQRKJ7U83QcslkKdtBc4Xrd_LJcFdMqrUfFYwgkdXvSh43-9A-pEXMZo5rUNZ_bR5iDs-WiYL4feNpXBEWqIyxCGwwZf99xiAyQ-PEN30PvEaEdinftcFeNClnH9p77Pqb29zC5XRDfeTYmXS7eMuPSd1Na1PA0g"}
2015/12/16 11:47:43 Transport received [FrameHeader HEADERS flags=END_HEADERS stream=5 len=213]: &http.http2HeadersFrame{http2FrameHeader:http.http2FrameHeader{valid:true, Type:0x1, Flags:0x4, Length:0xd5, StreamID:0x5}, Priority:http.http2PriorityParam{StreamDep:0x0, Exclusive:false, Weight:0x0}, headerFragBuf:[]uint8{0x8c, 0x1f, 0x27, 0x5, 0x6e, 0x67, 0x69, 0x6e, 0x78, 0x1f, 0x10, 0x18, 0x61, 0x70, 0x70, 0x6c, 0x69, 0x63, 0x61, 0x74, 0x69, 0x6f, 0x6e, 0x2f, 0x70, 0x72, 0x6f, 0x62, 0x6c, 0x65, 0x6d, 0x2b, 0x6a, 0x73, 0x6f, 0x6e, 0x1f, 0xd, 0x3, 0x31, 0x31, 0x33, 0x10, 0xc, 0x72, 0x65, 0x70, 0x6c, 0x61, 0x79, 0x2d, 0x6e, 0x6f, 0x6e, 0x63, 0x65, 0x2b, 0x61, 0x76, 0x49, 0x37, 0x58, 0x56, 0x66, 0x48, 0x75, 0x70, 0x55, 0x43, 0x4c, 0x6d, 0x4e, 0x42, 0x45, 0x73, 0x75, 0x48, 0x38, 0x64, 0x31, 0x47, 0x39, 0x6b, 0x5a, 0x51, 0x74, 0x48, 0x34, 0x33, 0x44, 0x42, 0x41, 0x4c, 0x63, 0x6a, 0x6f, 0x56, 0x58, 0x37, 0x41, 0x1f, 0x15, 0x1d, 0x57, 0x65, 0x64, 0x2c, 0x20, 0x31, 0x36, 0x20, 0x44, 0x65, 0x63, 0x20, 0x32, 0x30, 0x31, 0x35, 0x20, 0x30, 0x35, 0x3a, 0x34, 0x37, 0x3a, 0x34, 0x34, 0x20, 0x47, 0x4d, 0x54, 0x1f, 0x9, 0x1d, 0x6d, 0x61, 0x78, 0x2d, 0x61, 0x67, 0x65, 0x3d, 0x30, 0x2c, 0x20, 0x6e, 0x6f, 0x2d, 0x63, 0x61, 0x63, 0x68, 0x65, 0x2c, 0x20, 0x6e, 0x6f, 0x2d, 0x73, 0x74, 0x6f, 0x72, 0x65, 0x10, 0x6, 0x70, 0x72, 0x61, 0x67, 0x6d, 0x61, 0x8, 0x6e, 0x6f, 0x2d, 0x63, 0x61, 0x63, 0x68, 0x65, 0x1f, 0x12, 0x1d, 0x57, 0x65, 0x64, 0x2c, 0x20, 0x31, 0x36, 0x20, 0x44, 0x65, 0x63, 0x20, 0x32, 0x30, 0x31, 0x35, 0x20, 0x30, 0x35, 0x3a, 0x34, 0x37, 0x3a, 0x34, 0x34, 0x20, 0x47, 0x4d, 0x54}}
2015/12/16 11:47:43 Header field: {Name::status Value:400 Sensitive:false}
2015/12/16 11:47:43 Header field: {Name:server Value:nginx Sensitive:true}
2015/12/16 11:47:43 Header field: {Name:content-type Value:application/problem+json Sensitive:true}
2015/12/16 11:47:43 Header field: {Name:content-length Value:113 Sensitive:true}
2015/12/16 11:47:43 Header field: {Name:replay-nonce Value:avI7XVfHupUCLmNBEsuH8d1G9kZQtH43DBALcjoVX7A Sensitive:true}
2015/12/16 11:47:43 Header field: {Name:expires Value:Wed, 16 Dec 2015 05:47:44 GMT Sensitive:true}
2015/12/16 11:47:43 Header field: {Name:cache-control Value:max-age=0, no-cache, no-store Sensitive:true}
2015/12/16 11:47:43 Header field: {Name:pragma Value:no-cache Sensitive:true}
2015/12/16 11:47:43 Header field: {Name:date Value:Wed, 16 Dec 2015 05:47:44 GMT Sensitive:true}
2015/12/16 11:47:43 Transport received [FrameHeader DATA stream=5 len=113]: &http.http2DataFrame{http2FrameHeader:http.http2FrameHeader{valid:true, Type:0x0, Flags:0x0, Length:0x71, StreamID:0x5}, data:[]uint8{0x7b, 0x22, 0x74, 0x79, 0x70, 0x65, 0x22, 0x3a, 0x22, 0x75, 0x72, 0x6e, 0x3a, 0x61, 0x63, 0x6d, 0x65, 0x3a, 0x65, 0x72, 0x72, 0x6f, 0x72, 0x3a, 0x6d, 0x61, 0x6c, 0x66, 0x6f, 0x72, 0x6d, 0x65, 0x64, 0x22, 0x2c, 0x22, 0x64, 0x65, 0x74, 0x61, 0x69, 0x6c, 0x22, 0x3a, 0x22, 0x55, 0x6e, 0x61, 0x62, 0x6c, 0x65, 0x20, 0x74, 0x6f, 0x20, 0x72, 0x65, 0x61, 0x64, 0x2f, 0x76, 0x65, 0x72, 0x69, 0x66, 0x79, 0x20, 0x62, 0x6f, 0x64, 0x79, 0x20, 0x3a, 0x3a, 0x20, 0x50, 0x61, 0x72, 0x73, 0x65, 0x20, 0x65, 0x72, 0x72, 0x6f, 0x72, 0x20, 0x72, 0x65, 0x61, 0x64, 0x69, 0x6e, 0x67, 0x20, 0x4a, 0x57, 0x53, 0x22, 0x2c, 0x22, 0x73, 0x74, 0x61, 0x74, 0x75, 0x73, 0x22, 0x3a, 0x34, 0x30, 0x30, 0x7d}}
2015/12/16 11:47:43 DATA: "{"type":"urn:acme:error:malformed","detail":"Unable to read/verify body :: Parse error reading JWS","status":400}"
2015/12/16 11:47:43 Transport received [FrameHeader DATA flags=END_STREAM stream=5 len=0]: &http.http2DataFrame{http2FrameHeader:http.http2FrameHeader{valid:true, Type:0x0, Flags:0x1, Length:0x0, StreamID:0x5}, data:[]uint8{}}
2015/12/16 11:47:43 DATA: ""
2015/12/16 11:47:43 Could not complete registration
acme: Error 400 - urn:acme:error:malformed - Unable to read/verify body :: Parse error reading JWS

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.

@jeffallen

This comment has been minimized.

Copy link
Contributor Author

commented Dec 16, 2015

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.

@bradfitz

This comment has been minimized.

Copy link
Member

commented Dec 16, 2015

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)

@bradfitz

This comment has been minimized.

Copy link
Member

commented Dec 16, 2015

I left details in letsencrypt/boulder#1279

@bradfitz

This comment has been minimized.

Copy link
Member

commented Jan 6, 2016

Per letsencrypt/boulder#1279 (comment) , this was confirmed to be a problem on Akamai's side which they're fixing. Closing this bug.

@bradfitz bradfitz closed this Jan 6, 2016

bradfitz added a commit to golang/net that referenced this issue Jan 7, 2016

http2: clean up debugging, rename GODEBUG key
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>

@golang golang locked and limited conversation to collaborators Jan 7, 2017

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
You can’t perform that action at this time.