x/net/http2: log encoded hpack field header when GODEBUG=http2debug is set

[KeiichiHirobe]

In HTTP/2, header received is logged like this:

http2: Framer 0xc000890000: read HEADERS flags=END_STREAM|END_HEADERS stream=1 len=63
http2: decoded hpack field header field ":status" = "200"
http2: decoded hpack field header field "server" = "awselb/2.0"
http2: decoded hpack ...
...

But, header sended is logged like this:

http2: Framer 0xc000890000: wrote HEADERS flags=END_HEADERS stream=1 len=775

I'd like to suggest to log hpack field header field not only when decode but also when encode because it is very helpful for debug.

As far as I read code,

Decode log here:
https://github.com/golang/net/blob/fe42d452be8f3a2de6a60623c315a49bd37f0a9a/http2/frame.go#L1497-L1499

To add logging when encode too, maybe we should add logging around here:
https://github.com/golang/net/blob/fe42d452be8f3a2de6a60623c315a49bd37f0a9a/http2/hpack/encode.go#L81

But, we don't have a reference to framer there.
I don't have a good solution for that.

[mknyszek]

CC @tombergan @bradfitz via https://dev.golang.org/owners

Also CC @neild, maybe?

[mknyszek]

This is kind of like a feature request? Correct me if I'm wrong @KeiichiHirobe, but you're asking for different behavior of a GODEBUG variable, right?

[KeiichiHirobe]

@mknyszek

This is kind of like a feature request?

Yes!

you're asking for different behavior of a GODEBUG variable, right

Yes!

[networkimprov]

@fraenkel is the go-to guy for HTTP2 matters.

[fraenkel]

I am a bit confused, we already log the outbound headers.

    http2_test.go:66: 2021/05/27 19:05:39 http2: Transport encoding header ":authority" = "127.0.0.1:45689"
    http2_test.go:66: 2021/05/27 19:05:39 http2: Transport encoding header ":method" = "GET"
    http2_test.go:66: 2021/05/27 19:05:39 http2: Transport encoding header ":path" = "/"
    http2_test.go:66: 2021/05/27 19:05:39 http2: Transport encoding header ":scheme" = "https"
    http2_test.go:66: 2021/05/27 19:05:39 http2: Transport encoding header "accept-encoding" = "gzip"
    http2_test.go:66: 2021/05/27 19:05:39 http2: Transport encoding header "user-agent" = "Go-http-client/2.0"

[KeiichiHirobe]

@fraenkel

Sorry for the late reply, and I was mistaken.
I am a user of https://github.com/grpc/grpc-go, and maybe this is a problem of grpc-go.

grpc-go logs decoded hpack field through net/http2/frame.go, but never logs encoded hpack field at https://github.com/grpc/grpc-go/blob/4faa31f0a5809a5064ee128c9d855c0bedc1c783/internal/transport/controlbuf.go#L682.

Anyway, this is not a issue for golang/go, So I close this issue.