From 415f1917e1dbc946ec834288a8a1e5ff6eee2900 Mon Sep 17 00:00:00 2001 From: Brad Fitzpatrick Date: Wed, 16 Dec 2015 20:28:38 +0000 Subject: [PATCH] http2: clean up debugging, rename GODEBUG key GODEBUG=h2debug=1 is now GODEBUG=http2debug=1, per golang/go#13611 (comment https://github.com/golang/go/issues/13611#issuecomment-169534496) 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 Reviewed-by: Andrew Gerrand --- http2/frame.go | 81 +++++++++++++++++++++++++++++++++++++++++--- http2/hpack/hpack.go | 8 +++++ http2/http2.go | 16 ++++++++- http2/server.go | 39 ++++++++++++++------- http2/server_test.go | 2 ++ http2/transport.go | 19 +++++++---- http2/write.go | 23 ++++++++----- 7 files changed, 155 insertions(+), 33 deletions(-) diff --git a/http2/frame.go b/http2/frame.go index ec3f7966..238fb9b5 100644 --- a/http2/frame.go +++ b/http2/frame.go @@ -10,6 +10,7 @@ import ( "errors" "fmt" "io" + "log" "sync" ) @@ -171,6 +172,12 @@ func (h FrameHeader) Header() FrameHeader { return h } func (h FrameHeader) String() string { var buf bytes.Buffer buf.WriteString("[FrameHeader ") + h.writeDebug(&buf) + buf.WriteByte(']') + return buf.String() +} + +func (h FrameHeader) writeDebug(buf *bytes.Buffer) { buf.WriteString(h.Type.String()) if h.Flags != 0 { buf.WriteString(" flags=") @@ -187,15 +194,14 @@ func (h FrameHeader) String() string { if name != "" { buf.WriteString(name) } else { - fmt.Fprintf(&buf, "0x%x", 1<>16), byte(length>>8), byte(length)) + if logFrameWrites { + f.logWrite() + } + n, err := f.w.Write(f.wbuf) if err == nil && n != len(f.wbuf) { err = io.ErrShortWrite @@ -328,6 +341,23 @@ func (f *Framer) endWrite() error { return err } +func (f *Framer) logWrite() { + if f.debugFramer == nil { + f.debugFramerBuf = new(bytes.Buffer) + f.debugFramer = NewFramer(nil, f.debugFramerBuf) + // Let us read anything, even if we accidentally wrote it + // in the wrong order: + f.debugFramer.AllowIllegalReads = true + } + f.debugFramerBuf.Write(f.wbuf) + fr, err := f.debugFramer.ReadFrame() + if err != nil { + log.Printf("http2: Framer %p: failed to decode just-written frame", f) + return + } + log.Printf("http2: Framer %p: wrote %v", f, summarizeFrame(fr)) +} + func (f *Framer) writeByte(v byte) { f.wbuf = append(f.wbuf, v) } func (f *Framer) writeBytes(v []byte) { f.wbuf = append(f.wbuf, v...) } func (f *Framer) writeUint16(v uint16) { f.wbuf = append(f.wbuf, byte(v>>8), byte(v)) } @@ -1187,3 +1217,46 @@ type streamEnder interface { type headersEnder interface { HeadersEnded() bool } + +func summarizeFrame(f Frame) string { + var buf bytes.Buffer + f.Header().writeDebug(&buf) + switch f := f.(type) { + case *SettingsFrame: + n := 0 + f.ForeachSetting(func(s Setting) error { + n++ + if n == 1 { + buf.WriteString(", settings:") + } + fmt.Fprintf(&buf, " %v=%v,", s.ID, s.Val) + return nil + }) + if n > 0 { + buf.Truncate(buf.Len() - 1) // remove trailing comma + } + case *DataFrame: + data := f.Data() + const max = 256 + if len(data) > max { + data = data[:max] + } + fmt.Fprintf(&buf, " data=%q", data) + if len(f.Data()) > max { + fmt.Fprintf(&buf, " (%d bytes omitted)", len(f.Data())-max) + } + case *WindowUpdateFrame: + if f.StreamID == 0 { + buf.WriteString(" (conn)") + } + fmt.Fprintf(&buf, " incr=%v", f.Increment) + case *PingFrame: + fmt.Fprintf(&buf, " ping=%q", f.Data[:]) + case *GoAwayFrame: + fmt.Fprintf(&buf, " LastStreamID=%v ErrCode=%v Debug=%q", + f.LastStreamID, f.ErrCode, f.debugData) + case *RSTStreamFrame: + fmt.Fprintf(&buf, " ErrCode=%v", f.ErrCode) + } + return buf.String() +} diff --git a/http2/hpack/hpack.go b/http2/hpack/hpack.go index 329a8d03..2ea4949a 100644 --- a/http2/hpack/hpack.go +++ b/http2/hpack/hpack.go @@ -41,6 +41,14 @@ type HeaderField struct { Sensitive bool } +func (hf HeaderField) String() string { + var suffix string + if hf.Sensitive { + suffix = " (sensitive)" + } + return fmt.Sprintf("header field %q = %q%s", hf.Name, hf.Value, suffix) +} + func (hf *HeaderField) size() uint32 { // http://http2.github.io/http2-spec/compression.html#rfc.section.4.1 // "The size of the dynamic table is the sum of the size of diff --git a/http2/http2.go b/http2/http2.go index de6a6b4a..a3ec93c6 100644 --- a/http2/http2.go +++ b/http2/http2.go @@ -26,7 +26,21 @@ import ( "sync" ) -var VerboseLogs = strings.Contains(os.Getenv("GODEBUG"), "h2debug=1") +var ( + VerboseLogs bool + logFrameWrites bool +) + +func init() { + e := os.Getenv("GODEBUG") + if strings.Contains(e, "http2debug=1") { + VerboseLogs = true + } + if strings.Contains(e, "http2debug=2") { + VerboseLogs = true + logFrameWrites = true + } +} const ( // ClientPreface is the string that must be sent by new diff --git a/http2/server.go b/http2/server.go index d2aebefb..69cc81b3 100644 --- a/http2/server.go +++ b/http2/server.go @@ -309,7 +309,7 @@ func isBadCipher(cipher uint16) bool { } func (sc *serverConn) rejectConn(err ErrCode, debug string) { - sc.vlogf("REJECTING conn: %v, %s", err, debug) + sc.vlogf("http2: server rejecting conn: %v, %s", err, debug) // ignoring errors. hanging up anyway. sc.framer.WriteGoAway(0, err, []byte(debug)) sc.bw.Flush() @@ -497,7 +497,9 @@ func (sc *serverConn) condlogf(err error, format string, args ...interface{}) { func (sc *serverConn) onNewHeaderField(f hpack.HeaderField) { sc.serveG.check() - sc.vlogf("got header field %+v", f) + if VerboseLogs { + sc.vlogf("http2: server decoded %v", f) + } switch { case !validHeader(f.Name): sc.req.invalidHeader = true @@ -547,7 +549,9 @@ func (sc *serverConn) onNewHeaderField(f hpack.HeaderField) { func (st *stream) onNewTrailerField(f hpack.HeaderField) { sc := st.sc sc.serveG.check() - sc.vlogf("got trailer field %+v", f) + if VerboseLogs { + sc.vlogf("http2: server decoded trailer %v", f) + } switch { case !validHeader(f.Name): sc.req.invalidHeader = true @@ -674,7 +678,9 @@ func (sc *serverConn) serve() { defer sc.stopShutdownTimer() defer close(sc.doneServing) // unblocks handlers trying to send - sc.vlogf("HTTP/2 connection from %v on %p", sc.conn.RemoteAddr(), sc.hs) + if VerboseLogs { + sc.vlogf("http2: server connection from %v on %p", sc.conn.RemoteAddr(), sc.hs) + } sc.writeFrame(frameWriteMsg{ write: writeSettings{ @@ -691,7 +697,7 @@ func (sc *serverConn) serve() { sc.unackedSettings++ if err := sc.readPreface(); err != nil { - sc.condlogf(err, "error reading preface from client %v: %v", sc.conn.RemoteAddr(), err) + sc.condlogf(err, "http2: server: error reading preface from client %v: %v", sc.conn.RemoteAddr(), err) return } // Now that we've got the preface, get us out of the @@ -757,7 +763,9 @@ func (sc *serverConn) readPreface() error { return errors.New("timeout waiting for client preface") case err := <-errc: if err == nil { - sc.vlogf("client %v said hello", sc.conn.RemoteAddr()) + if VerboseLogs { + sc.vlogf("http2: server: client %v said hello", sc.conn.RemoteAddr()) + } } return err } @@ -1035,7 +1043,9 @@ func (sc *serverConn) processFrameFromReader(res readFrameResult) bool { } } else { f := res.f - sc.vlogf("got %v: %#v", f.Header(), f) + if VerboseLogs { + sc.vlogf("http2: server read frame %v", summarizeFrame(f)) + } err = sc.processFrame(f) if err == nil { return true @@ -1050,14 +1060,14 @@ func (sc *serverConn) processFrameFromReader(res readFrameResult) bool { sc.goAway(ErrCodeFlowControl) return true case ConnectionError: - sc.logf("%v: %v", sc.conn.RemoteAddr(), ev) + sc.logf("http2: server connection error from %v: %v", sc.conn.RemoteAddr(), ev) sc.goAway(ErrCode(ev)) return true // goAway will handle shutdown default: if res.err != nil { - sc.logf("disconnecting; error reading frame from client %s: %v", sc.conn.RemoteAddr(), err) + sc.logf("http2: server closing client connection; error reading frame from client %s: %v", sc.conn.RemoteAddr(), err) } else { - sc.logf("disconnection due to other error: %v", err) + sc.logf("http2: server closing client connection: %v", err) } return false } @@ -1096,7 +1106,7 @@ func (sc *serverConn) processFrame(f Frame) error { // frame as a connection error (Section 5.4.1) of type PROTOCOL_ERROR. return ConnectionError(ErrCodeProtocol) default: - sc.vlogf("Ignoring frame: %v", f.Header()) + sc.vlogf("http2: server ignoring frame: %v", f.Header()) return nil } } @@ -1207,7 +1217,9 @@ func (sc *serverConn) processSetting(s Setting) error { if err := s.Valid(); err != nil { return err } - sc.vlogf("processing setting %v", s) + if VerboseLogs { + sc.vlogf("http2: server processing setting %v", s) + } switch s.ID { case SettingHeaderTableSize: sc.headerTableSize = s.Val @@ -1226,6 +1238,9 @@ func (sc *serverConn) processSetting(s Setting) error { // Unknown setting: "An endpoint that receives a SETTINGS // frame with any unknown or unsupported identifier MUST // ignore that setting." + if VerboseLogs { + sc.vlogf("http2: server ignoring unknown setting %v", s) + } } return nil } diff --git a/http2/server_test.go b/http2/server_test.go index 7280a307..e2f42ff2 100644 --- a/http2/server_test.go +++ b/http2/server_test.go @@ -2472,6 +2472,7 @@ func TestCompressionErrorOnWrite(t *testing.T) { serverConfig = ts.Config serverConfig.MaxHeaderBytes = maxStrLen }) + st.addLogFilter("connection error: COMPRESSION_ERROR") defer st.Close() st.greet() @@ -2515,6 +2516,7 @@ func TestCompressionErrorOnClose(t *testing.T) { st := newServerTester(t, func(w http.ResponseWriter, r *http.Request) { // No response body. }) + st.addLogFilter("connection error: COMPRESSION_ERROR") defer st.Close() st.greet() diff --git a/http2/transport.go b/http2/transport.go index bed148e6..916a4e22 100644 --- a/http2/transport.go +++ b/http2/transport.go @@ -276,7 +276,7 @@ func (t *Transport) RoundTripOpt(req *http.Request, opt RoundTripOpt) (*http.Res for { cc, err := t.connPool().GetClientConn(req, addr) if err != nil { - t.vlogf("failed to get client conn: %v", err) + t.vlogf("http2: Transport failed to get client conn for %s: %v", addr, err) return nil, err } res, err := cc.RoundTrip(req) @@ -365,7 +365,7 @@ func (t *Transport) dialTLSDefault(network, addr string, cfg *tls.Config) (net.C func (t *Transport) NewClientConn(c net.Conn) (*ClientConn, error) { if VerboseLogs { - t.vlogf("creating client conn to %v", c.RemoteAddr()) + t.vlogf("http2: Transport creating client conn to %v", c.RemoteAddr()) } if _, err := c.Write(clientPreface); err != nil { t.vlogf("client preface write error: %v", err) @@ -899,6 +899,9 @@ func (cc *ClientConn) encodeTrailers(req *http.Request) []byte { } func (cc *ClientConn) writeHeader(name, value string) { + if VerboseLogs { + log.Printf("http2: Transport encoding header %q = %q", name, value) + } cc.henc.WriteField(hpack.HeaderField{Name: name, Value: value}) } @@ -1014,7 +1017,9 @@ func (rl *clientConnReadLoop) run() error { } else if err != nil { return err } - cc.vlogf("Transport received %v: %#v", f.Header(), f) + if VerboseLogs { + cc.vlogf("http2: Transport received %s", summarizeFrame(f)) + } switch f := f.(type) { case *HeadersFrame: @@ -1253,9 +1258,6 @@ func (rl *clientConnReadLoop) processData(f *DataFrame) error { return nil } data := f.Data() - if VerboseLogs { - rl.cc.logf("DATA: %q", data) - } // Check connection-level flow control. cc.mu.Lock() @@ -1455,7 +1457,7 @@ func (rl *clientConnReadLoop) checkHeaderField(f hpack.HeaderField) bool { func (rl *clientConnReadLoop) onNewHeaderField(f hpack.HeaderField) { cc := rl.cc if VerboseLogs { - cc.logf("Header field: %+v", f) + cc.logf("http2: Transport decoded %v", f) } if !rl.checkHeaderField(f) { @@ -1498,6 +1500,9 @@ func (rl *clientConnReadLoop) onNewHeaderField(f hpack.HeaderField) { } func (rl *clientConnReadLoop) onNewTrailerField(cs *clientStream, f hpack.HeaderField) { + if VerboseLogs { + rl.cc.logf("http2: Transport decoded trailer %v", f) + } if !rl.checkHeaderField(f) { return } diff --git a/http2/write.go b/http2/write.go index 6c8c15a1..020d0fce 100644 --- a/http2/write.go +++ b/http2/write.go @@ -7,6 +7,7 @@ package http2 import ( "bytes" "fmt" + "log" "net/http" "sort" "time" @@ -136,27 +137,31 @@ type writeResHeaders struct { contentLength string } +func encKV(enc *hpack.Encoder, k, v string) { + if VerboseLogs { + log.Printf("http2: server encoding header %q = %q", k, v) + } + enc.WriteField(hpack.HeaderField{Name: k, Value: v}) +} + func (w *writeResHeaders) writeFrame(ctx writeContext) error { enc, buf := ctx.HeaderEncoder() buf.Reset() if w.httpResCode != 0 { - enc.WriteField(hpack.HeaderField{ - Name: ":status", - Value: httpCodeString(w.httpResCode), - }) + encKV(enc, ":status", httpCodeString(w.httpResCode)) } encodeHeaders(enc, w.h, w.trailers) if w.contentType != "" { - enc.WriteField(hpack.HeaderField{Name: "content-type", Value: w.contentType}) + encKV(enc, "content-type", w.contentType) } if w.contentLength != "" { - enc.WriteField(hpack.HeaderField{Name: "content-length", Value: w.contentLength}) + encKV(enc, "content-length", w.contentLength) } if w.date != "" { - enc.WriteField(hpack.HeaderField{Name: "date", Value: w.date}) + encKV(enc, "date", w.date) } headerBlock := buf.Bytes() @@ -206,7 +211,7 @@ type write100ContinueHeadersFrame struct { func (w write100ContinueHeadersFrame) writeFrame(ctx writeContext) error { enc, buf := ctx.HeaderEncoder() buf.Reset() - enc.WriteField(hpack.HeaderField{Name: ":status", Value: "100"}) + encKV(enc, ":status", "100") return ctx.Framer().WriteHeaders(HeadersFrameParam{ StreamID: w.streamID, BlockFragment: buf.Bytes(), @@ -242,7 +247,7 @@ func encodeHeaders(enc *hpack.Encoder, h http.Header, keys []string) { if isTE && v != "trailers" { continue } - enc.WriteField(hpack.HeaderField{Name: k, Value: v}) + encKV(enc, k, v) } } }