[go] net/http: add GODEBUG=httpdebug=1 to enable verbose logging.
Sameer Ajmani (Gerrit)
Sameer Ajmani has uploaded this change for review.
net/http: add GODEBUG=httpdebug=1 to enable verbose logging. http.go: define http1VerboseLogs. transport.go: log request and response/err in RoundTrip. Also log when requests are retried. server.go: log requests being served. Tested using a command line program calling http.Get. Fixes #18733 Change-Id: I20c42ea62776ddec3f09d4e9847385fdab44c076 --- M src/net/http/http.go M src/net/http/server.go M src/net/http/transport.go 3 files changed, 28 insertions(+), 1 deletion(-)
diff --git a/src/net/http/http.go b/src/net/http/http.go
index 826f7ff..a53837d 100644
--- a/src/net/http/http.go
+++ b/src/net/http/http.go
@@ -6,6 +6,7 @@
import (
"io"
+ "os"
"strconv"
"strings"
"time"
@@ -139,3 +140,14 @@
// is not supported on the underlying connection.
Push(target string, opts *PushOptions) error
}
+
+var (
+ http1VerboseLogs bool
+)
+
+func init() {
+ e := os.Getenv("GODEBUG")
+ if strings.Contains(e, "http1debug=1") {
+ http1VerboseLogs = true
+ }
+}
diff --git a/src/net/http/server.go b/src/net/http/server.go
index df70a15..948acf6 100644
--- a/src/net/http/server.go
+++ b/src/net/http/server.go
@@ -1814,6 +1814,9 @@
}
w.conn.r.startBackgroundRead()
}
+ if http1VerboseLogs {
+ log.Printf("net/http.Server(%p) serving %#v", c.server, req)
+ }
// HTTP cannot have multiple simultaneous active requests.[*]
// Until the server replies to this request, it can't read another,
diff --git a/src/net/http/transport.go b/src/net/http/transport.go
index 571943d..f5e7a1d 100644
--- a/src/net/http/transport.go
+++ b/src/net/http/transport.go
@@ -316,7 +316,16 @@
//
// For higher-level HTTP client support (such as handling of cookies
// and redirects), see Get, Post, and the Client type.
-func (t *Transport) RoundTrip(req *Request) (*Response, error) {
+func (t *Transport) RoundTrip(req *Request) (rtResp *Response, rtErr error) {
+ if http1VerboseLogs {
+ defer func() {
+ if rtErr != nil {
+ log.Printf("net/http.Transport(%p).RoundTrip(%#v) = error %v", t, req, rtErr)
+ } else {
+ log.Printf("net/http.Transport(%p).RoundTrip(%#v) = %#v", t, req, rtResp)
+ }
+ }()
+ }
t.nextProtoOnce.Do(t.onceSetNextProtoDefaults)
ctx := req.Context()
trace := httptrace.ContextClientTrace(ctx)
@@ -402,6 +411,9 @@
return nil, err
}
testHookRoundTripRetried()
+ if http1VerboseLogs {
+ log.Printf("net/http: retrying request for error %v", err)
+ }
}
}
To view, visit change 36548. To unsubscribe, visit settings.
Sameer Ajmani (Gerrit)
Sameer Ajmani uploaded patch set #2 to this change.
net/http: add GODEBUG=httpdebug=1 to enable verbose logging.
http.go: define http1VerboseLogs.
transport.go: log request and response/err in RoundTrip.
Also log when requests are retried.
server.go: log requests being served.
Tested using a command line program calling http.Get.
Output for client with bad URL:
$ GODEBUG=http1debug=1 go run client/client.go localhost:8080
2017/02/08 10:41:04 net/http.Transport(0x77e8e0).RoundTrip(&http.Request{Method:"GET", URL:(*url.URL)(0xc42001c300), Proto:"HTTP/1.1", ProtoMajor:1, ProtoMinor:1, Header:http.Header{}, Body:io.ReadCloser(nil), GetBody:(func() (io.ReadCloser, error))(nil), ContentLength:0, TransferEncoding:[]string(nil), Close:false, Host:"", Form:url.Values(nil), PostForm:url.Values(nil), MultipartForm:(*multipart.Form)(nil), Trailer:http.Header(nil), RemoteAddr:"", RequestURI:"", TLS:(*tls.ConnectionState)(nil), Cancel:(<-chan struct {})(nil), Response:(*http.Response)(nil), ctx:context.Context(nil)}) = error unsupported protocol scheme "localhost"
Output for client with good URL:
$ GODEBUG=http1debug=1 go run client/client.go http://localhost:8080/bar
2017/02/08 10:41:54 net/http.Transport(0x77e8e0).RoundTrip(&http.Request{Method:"GET", URL:(*url.URL)(0xc42001c300), Proto:"HTTP/1.1", ProtoMajor:1, ProtoMinor:1, Header:http.Header{}, Body:io.ReadCloser(nil), GetBody:(func() (io.ReadCloser, error))(nil), ContentLength:0, TransferEncoding:[]string(nil), Close:false, Host:"localhost:8080", Form:url.Values(nil), PostForm:url.Values(nil), MultipartForm:(*multipart.Form)(nil), Trailer:http.Header(nil), RemoteAddr:"", RequestURI:"", TLS:(*tls.ConnectionState)(nil), Cancel:(<-chan struct {})(nil), Response:(*http.Response)(nil), ctx:context.Context(nil)}) = &http.Response{Status:"200 OK", StatusCode:200, Proto:"HTTP/1.1", ProtoMajor:1, ProtoMinor:1, Header:http.Header{"Date":[]string{"Wed, 08 Feb 2017 15:41:54 GMT"}, "Content-Length":[]string{"13"}, "Content-Type":[]string{"text/plain; charset=utf-8"}}, Body:(*http.bodyEOFSignal)(0xc420116040), ContentLength:13, TransferEncoding:[]string(nil), Close:false, Uncompressed:false, Trailer:http.Header(nil), Request:(*http.Request)(0xc42000a800), TLS:(*tls.ConnectionState)(nil)}
Output for server:
$ GODEBUG=http1debug=1 go run server/server.go &
$ go run client/client.go http://localhost:8080/bar
2017/02/08 10:43:21 net/http.Server(0xc4200929a0) serving &http.Request{Method:"GET", URL:(*url.URL)(0xc42001c300), Proto:"HTTP/1.1", ProtoMajor:1, ProtoMinor:1, Header:http.Header{"User-Agent":[]string{"Go-http-client/1.1"}, "Accept-Encoding":[]string{"gzip"}}, Body:http.noBody{}, GetBody:(func() (io.ReadCloser, error))(nil), ContentLength:0, TransferEncoding:[]string(nil), Close:false, Host:"localhost:8080", Form:url.Values(nil), PostForm:url.Values(nil), MultipartForm:(*multipart.Form)(nil), Trailer:http.Header(nil), RemoteAddr:"127.0.0.1:44772", RequestURI:"/bar", TLS:(*tls.ConnectionState)(nil), Cancel:(<-chan struct {})(nil), Response:(*http.Response)(nil), ctx:(*context.cancelCtx)(0xc420014980)}
Fixes #18733
Change-Id: I20c42ea62776ddec3f09d4e9847385fdab44c076
---
M src/net/http/http.go
M src/net/http/server.go
M src/net/http/transport.go
3 files changed, 28 insertions(+), 1 deletion(-)
To view, visit change 36548. To unsubscribe, visit settings.
Brad Fitzpatrick (Gerrit)
Brad Fitzpatrick posted comments on this change.
Patch set 2:
The good thing about the GODEBUG=http2debug output is how readable it is.
I see now that the tricky part of this CL will be finding a compact representation.
About half that output is Go noise that could be reduced:
- don't need type names.
- Proto and ProtoMajor/ProtoMinor are redundant
- zero values can be omitted
- also don't need []string{...} when just {...} is fine
- expand *url.URL (show as string?)
And the main thing for debugging is knowing which connections things happened on (when there was reuse vs not), so each line should say which connection (maybe just %p of the net.Conn) the line is associated with.
Probably also events for new conns vs closing conns (and why: idle, requested by client, etc).
Does this also include data? The http2 format shows some of the data, but elides the middle with a "foo....bar" when it's too large.
Sameer Ajmani
Regarding showing the bodies: I see how HTTP2 does it, by writing the data to a second buffer, but I'm a little concerned about the privacy implications. Will users generally be OK with logging data that may contain user PII in debug logs?
Brad Fitzpatrick
Great, thanks for the suggestions. I'll add functions to create debug summaries of HTTP requests and responses, and I'll add messages for connection events. Probably we should just log the connection events at debug level 1 and include the requests and responses at level 2.
Regarding showing the bodies: I see how HTTP2 does it, by writing the data to a second buffer, but I'm a little concerned about the privacy implications. Will users generally be OK with logging data that may contain user PII in debug logs?
Sameer Ajmani
Please copy your reply to Gerrit.This mailing list is not archived or postable by most and doesn't feed back into Gerrit, fracturing conversations.
On Wed, Feb 8, 2017 at 2:57 PM, Sameer Ajmani <sam...@golang.org> wrote:
Great, thanks for the suggestions. I'll add functions to create debug summaries of HTTP requests and responses, and I'll add messages for connection events. Probably we should just log the connection events at debug level 1 and include the requests and responses at level 2.
Regarding showing the bodies: I see how HTTP2 does it, by writing the data to a second buffer, but I'm a little concerned about the privacy implications. Will users generally be OK with logging data that may contain user PII in debug logs?
Sameer Ajmani (Gerrit)
Sameer Ajmani posted comments on this change.
Patch set 2:
Great, thanks for the suggestions. I'll add functions to create debug summaries of HTTP requests and responses, and I'll add messages for connection events. Probably we should just log the connection events at debug level 1 and include the requests and responses at level 2.
Regarding showing the bodies: I see how HTTP2 does it, by writing the data to a second buffer, but I'm a little concerned about the privacy implications. Will users generally be OK with logging data that may contain user PII in debug logs?
To view, visit change 36548. To unsubscribe, visit settings.
Brad Fitzpatrick (Gerrit)
Brad Fitzpatrick posted comments on this change.
Patch set 2:
I'm not worried about "PII" in debug logs. It's only enabled if you enable it. And sometimes seeing the private cookies and such is a feature, not a bug.
People only enable this when they really want to see what's happening. This is an alternative mechanism to modifying the source to print out the same info.
Sameer Ajmani (Gerrit)
Sameer Ajmani posted comments on this change.
Patch set 2:
For reference, here's client output using the existing http2debug=2 support; I'll aim to provide something comparable for http1debug.
$ GODEBUG=http2debug=2 client http://http2.golang.org 2017/02/10 11:29:47 http2: Transport failed to get client conn for http2.golang.org:443: http2: no cached connection was available 2017/02/10 11:29:47 http2: Transport creating client conn 0xc420001a00 to 130.211.116.44:443 2017/02/10 11:29:47 http2: Framer 0xc42008e4e0: wrote SETTINGS len=18, settings: ENABLE_PUSH=0, INITIAL_WINDOW_SIZE=4194304, MAX_HEADER_LIST_SIZE=10485760 2017/02/10 11:29:47 http2: Framer 0xc42008e4e0: wrote WINDOW_UPDATE len=4 (conn) incr=1073741824 2017/02/10 11:29:47 http2: Transport encoding header ":authority" = "http2.golang.org" 2017/02/10 11:29:47 http2: Transport encoding header ":method" = "GET" 2017/02/10 11:29:47 http2: Transport encoding header ":path" = "/" 2017/02/10 11:29:47 http2: Transport encoding header ":scheme" = "https" 2017/02/10 11:29:47 http2: Transport encoding header "referer" = "http://http2.golang.org" 2017/02/10 11:29:47 http2: Transport encoding header "accept-encoding" = "gzip" 2017/02/10 11:29:47 http2: Transport encoding header "user-agent" = "Go-http-client/2.0" 2017/02/10 11:29:47 http2: Framer 0xc42008e4e0: read SETTINGS len=18, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896 2017/02/10 11:29:47 http2: Transport received SETTINGS len=18, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896 2017/02/10 11:29:47 http2: Framer 0xc42008e4e0: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=56 2017/02/10 11:29:47 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 1048896] 2017/02/10 11:29:47 http2: Framer 0xc42008e4e0: wrote SETTINGS flags=ACK len=0 2017/02/10 11:29:47 http2: Framer 0xc42008e4e0: read SETTINGS flags=ACK len=0 2017/02/10 11:29:47 http2: Transport received SETTINGS flags=ACK len=0 2017/02/10 11:29:47 http2: Framer 0xc42008e4e0: read HEADERS flags=END_HEADERS stream=1 len=50 2017/02/10 11:29:47 http2: decoded hpack field header field ":status" = "200" 2017/02/10 11:29:47 http2: decoded hpack field header field "content-type" = "text/html; charset=utf-8" 2017/02/10 11:29:47 http2: decoded hpack field header field "content-length" = "1593" 2017/02/10 11:29:47 http2: decoded hpack field header field "date" = "Fri, 10 Feb 2017 16:29:47 GMT" 2017/02/10 11:29:47 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=50 2017/02/10 11:29:47 http2: Framer 0xc42008e4e0: read DATA flags=END_STREAM stream=1 len=1593 data="<html>\n<body>\n<h1>Go + HTTP/2</h1>\n\n<p>Welcome to <a href=\"https://golang.org/\">the Go language</a>'s <a\nhref=\"https://http2.github.io/\">HTTP/2</a> demo & interop server.</p>\n\n<p>Congratulations, <b>you're using HTTP/2 right now</b>.</p>\n\n<p>This server ex" (1337 bytes omitted) 2017/02/10 11:29:47 http2: Transport received DATA flags=END_STREAM stream=1 len=1593 data="<html>\n<body>\n<h1>Go + HTTP/2</h1>\n\n<p>Welcome to <a href=\"https://golang.org/\">the Go language</a>'s <a\nhref=\"https://http2.github.io/\">HTTP/2</a> demo & interop server.</p>\n\n<p>Congratulations, <b>you're using HTTP/2 right now</b>.</p>\n\n<p>This server ex" (1337 bytes omitted)
Sameer Ajmani (Gerrit)
And here's http2debug=1:
$ GODEBUG=http2debug=1 client http://http2.golang.org 2017/02/10 11:32:50 http2: Transport failed to get client conn for http2.golang.org:443: http2: no cached connection was available 2017/02/10 11:32:50 http2: Transport creating client conn 0xc420001a00 to 130.211.116.44:443 2017/02/10 11:32:50 http2: Transport encoding header ":authority" = "http2.golang.org" 2017/02/10 11:32:50 http2: Transport encoding header ":method" = "GET" 2017/02/10 11:32:50 http2: Transport encoding header ":path" = "/" 2017/02/10 11:32:50 http2: Transport encoding header ":scheme" = "https" 2017/02/10 11:32:50 http2: Transport encoding header "referer" = "http://http2.golang.org" 2017/02/10 11:32:50 http2: Transport encoding header "accept-encoding" = "gzip" 2017/02/10 11:32:50 http2: Transport encoding header "user-agent" = "Go-http-client/2.0" 2017/02/10 11:32:50 http2: Transport received SETTINGS len=18, settings: MAX_FRAME_SIZE=1048576, MAX_CONCURRENT_STREAMS=250, MAX_HEADER_LIST_SIZE=1048896 2017/02/10 11:32:50 Unhandled Setting: [MAX_HEADER_LIST_SIZE = 1048896] 2017/02/10 11:32:50 http2: Transport received SETTINGS flags=ACK len=0 2017/02/10 11:32:50 http2: Transport received HEADERS flags=END_HEADERS stream=1 len=50 2017/02/10 11:32:50 http2: Transport received DATA flags=END_STREAM stream=1 len=1593 data="<html>\n<body>\n<h1>Go + HTTP/2</h1>\n\n<p>Welcome to <a href=\"https://golang.org/\">the Go language</a>'s <a\nhref=\"https://http2.github.io/\">HTTP/2</a> demo & interop server.</p>\n\n<p>Congratulations, <b>you're using HTTP/2 right now</b>.</p>\n\n<p>This server ex" (1337 bytes omitted)
Sameer Ajmani (Gerrit)
Sameer Ajmani uploaded patch set #3 to this change.
net/http: add GODEBUG=httpdebug=1 to enable verbose logging. Checkpointing, no need to review yet. Fixes #18733 Change-Id: I20c42ea62776ddec3f09d4e9847385fdab44c076 --- M src/net/http/http.go M src/net/http/server.go M src/net/http/transport.go 3 files changed, 139 insertions(+), 2 deletions(-)
To view, visit change 36548. To unsubscribe, visit settings.
Sameer Ajmani (Gerrit)
Sameer Ajmani uploaded patch set #4 to this change.
net/http: add GODEBUG=httpdebug=1 to enable verbose logging. See issue #18733 for link to doc for discussion of output format. Fixes #18733 Change-Id: I20c42ea62776ddec3f09d4e9847385fdab44c076 --- M src/net/http/http.go M src/net/http/server.go M src/net/http/transport.go 3 files changed, 146 insertions(+), 2 deletions(-)
To view, visit change 36548. To unsubscribe, visit settings.
Sameer Ajmani (Gerrit)
Sameer Ajmani uploaded patch set #5 to this change.
net/http: add GODEBUG=httpdebug=1 to enable verbose logging. See issue #18733 for link to doc for discussion of output format. Fixes #18733 Change-Id: I20c42ea62776ddec3f09d4e9847385fdab44c076 --- M src/net/http/http.go M src/net/http/server.go M src/net/http/transport.go 3 files changed, 153 insertions(+), 3 deletions(-)
To view, visit change 36548. To unsubscribe, visit settings.
Brad Fitzpatrick (Gerrit)
Brad Fitzpatrick posted comments on this change.
Patch set 5:
(2 comments)
File src/net/http/transport.go:
Patch Set #5, Line 319:
func (t *Transport) RoundTrip(req *Request) (_ *Response, rtErr error) {we don't want this signature in godoc with "rtErr" or the "_".
call a lowercase function if that's required.
Patch Set #5, Line 1394:
id int64comment
To view, visit change 36548. To unsubscribe, visit settings.
Sameer Ajmani (Gerrit)
Sameer Ajmani uploaded patch set #6 to this change.
net/http: add GODEBUG=httpdebug=1 to enable verbose logging. Doc for discussion of output format: https://docs.google.com/document/d/10FdNIgIjIyv9zfwrC7jSfdgjuWAHs6MdIrqaiz32vJU/edit# Fixes #18733 Change-Id: I20c42ea62776ddec3f09d4e9847385fdab44c076 --- M src/net/http/http.go M src/net/http/transport.go 2 files changed, 170 insertions(+), 13 deletions(-)
To view, visit change 36548. To unsubscribe, visit settings.
Sameer Ajmani (Gerrit)
Sameer Ajmani posted comments on this change.
Patch Set #5, Line 319:
func (t *Transport) RoundTrip(req *Request) (_ *Response, rtErr error) {we don't want this signature in godoc with "rtErr" or the "_".
Done
Patch Set #5, Line 1394:
id int64comment
Done
To view, visit change 36548. To unsubscribe, visit settings.
Sameer Ajmani (Gerrit)
Sameer Ajmani posted comments on this change.
Patch set 6:
(1 comment)
File src/net/http/transport.go:
id int64 nextRequestID int64
still needs a comment here
To view, visit change 36548. To unsubscribe, visit settings.
Sameer Ajmani (Gerrit)
Sameer Ajmani uploaded patch set #7 to this change.
net/http: add GODEBUG=httpdebug=1 to enable verbose logging. Doc for discussion of output format: https://docs.google.com/document/d/10FdNIgIjIyv9zfwrC7jSfdgjuWAHs6MdIrqaiz32vJU/edit# Fixes #18733 Change-Id: I20c42ea62776ddec3f09d4e9847385fdab44c076 --- M src/net/http/http.go M src/net/http/transport.go 2 files changed, 171 insertions(+), 13 deletions(-)
To view, visit change 36548. To unsubscribe, visit settings.
Sameer Ajmani (Gerrit)
Sameer Ajmani posted comments on this change.
Patch set 7:
(1 comment)
// IDs for debug logging. id int64
still needs a comment here
Done
To view, visit change 36548. To unsubscribe, visit settings.
Brad Fitzpatrick (Gerrit)
Brad Fitzpatrick posted comments on this change.
Patch set 7:
Looking at the implementation, this is logging at a different level than http2debug. The http2 logging is showing what's happening at the wire level (what's read and written). This CL is doing it after it's been interpreted by Go. They should be pretty similar, but I'm afraid that the sort of issues that will require such debugging will be the ones where they're different. And http1 has much more room for sloppiness than http2.
When I filed https://github.com/golang/go/issues/18733 I wrote at the top:
There is code in the net/http package to do a similar thing for HTTP/1, but it's not accessible via an environment variable. Should we make it accessible with GODEBUG=http1debug=...?
That code isn't used by this CL.
(It's "type loggingConn" in server.go)
I wonder if we should just use that instead, extended a bit.
When debugging is enabled, we wrap things in *loggingConn and extend it to tell it the state of things (where request boundaries are, e.g. which request/response number we're at for a given connection)
Sameer Ajmani (Gerrit)
Sameer Ajmani posted comments on this change.
Patch set 7:
I've run out of time to work on this, so I've unassigned myself from this issue. Should I abandon this CL?
Brad Fitzpatrick (Gerrit)
Brad Fitzpatrick abandoned this change.
To view, visit change 36548. To unsubscribe, visit settings.