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 <blake.mizerany@gmail.com>
Reviewed-by: Andrew Gerrand <adg@golang.org>

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<<i)
+				fmt.Fprintf(buf, "0x%x", 1<<i)
 			}
 		}
 	}
 	if h.StreamID != 0 {
-		fmt.Fprintf(&buf, " stream=%d", h.StreamID)
+		fmt.Fprintf(buf, " stream=%d", h.StreamID)
 	}
-	fmt.Fprintf(&buf, " len=%d]", h.Length)
-	return buf.String()
+	fmt.Fprintf(buf, " len=%d", h.Length)
 }
 
 func (h *FrameHeader) checkValid() {
@@ -294,6 +300,9 @@ type Framer struct {
 	// we're in the middle of a header block and a
 	// non-Continuation or Continuation on a different stream is
 	// attempted to be written.
+
+	debugFramer    *Framer // only use for logging written writes
+	debugFramerBuf *bytes.Buffer
 }
 
 func (f *Framer) startWrite(ftype FrameType, flags Flags, streamID uint32) {
@@ -321,6 +330,10 @@ func (f *Framer) endWrite() error {
 		byte(length>>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()
+}

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

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

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
 }

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()
 

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
 	}

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)
 		}
 	}
 }