net/http: reconsider bad request logging

[bradfitz]

https://golang.org/cl/27950 (84ded8b) adds logging of bad requests from clients.

@rsc writes (in https://go-review.googlesource.com/c/33244/7/doc/go1.8.html#594):

I think this may be a mistake. When I saw the CL I thought "log" meant write to some hook that lets you generate an apache style log. But this actually means "print to standard error (or else s.ErrorLog). Previously all the logging of that form was for actual errors on the server side: misuse of Hijack, unexpected Accept errors, and so on. This new logging is for bad input sent by a client. That's a very different case and quite possibly not a door we want to open.

In any event if it's kept then "logs" should be defined better. But probably it should go.

Is this the first time we're logging on bad input from users?

If so, @rsc makes a good point, that this might open the doors to let outside users spam server logs.

Maybe it should be a hook instead, or an alternate logger. But it's probably too late for Go 1.8 and we should make API addition decisions in Go 1.9 instead.

But if there's precedent for logging on invalid input, maybe it's fine to keep.

Thoughts?

/cc @kennygrant @rsc @dsnet @tombergan

[kennygrant]

server.logf is called for TLS handshake error which I guess bad clients could trigger? Otherwise it looks like internal server errors only.

Also see original discussion on #12745 - the original suggestion was to make sure a response was sent to clients and/or write to the log. I'd be happy without the logging as if we send a response body it's obvious to the client what is wrong with their request which is why I closed it with the first CL, but someone else did request logging too after it was closed.

[bmhatfield]

I was just reviewing the 1.8 milestone and saw this issue.

I'm a little unclear on if this logging can be optionally disabled. If not, I would like to request that this is not included in 1.8, as some of our very high request-per-second endpoints would be negatively impacted by this. Specifically, we receive a fair number of malformed requests, and have more-or-less disabled logging for performance and reliability (ie, filling disk space) reasons.

Non-optionally logging malformed input would likely cause a substantial performance degradation and risk our systems over-logging, requiring excessive rotation or other techniques to deal with.

Thanks.

[tombergan]

Thanks for cc'ing me. I didn't realize http.Server can generate 4xx error responses internally, without calling the request handler. This is a clear logging hole that makes me sympathize with https://golang.org/cl/27950. I run a service that logs metadata about every request/response pair. I didn't realize that our logs are missing a whole class of responses. (In practice, this is not a big deal, since we run behind a frontend that will reject most malformed requests, but still, there should be some hook that can be used to log such responses.)

At the same time, I agree with Russ: spamming stderr is not a good default behavior for this case. I vote to revert the logging portion of https://golang.org/cl/27950 for 1.8. Long term, I think something httptrace-like is the way to go, although I've given approximately zero thought to what such an API would look like.

[kennygrant]

@bradfitz perhaps we should just remove lines 1766 and 1780 so that the server returns a message to the client along with the status code but does no logging for now on 400 or 431 errors?

[gopherbot]

CL https://golang.org/cl/33617 mentions this issue.

[bradfitz]

Okay, it's removed for Go 1.8. We can reconsider what to do in Go 1.9.

[kennygrant]

For future ref, here is a summary of the current calls to logf in server.go:

ERRORS ACCEPTING CONNECTION:

// Accept error - things like hitting file limits 
srv.logf("http: Accept error: %v; retrying in %v", e, tempDelay)

ERRORS WRITING HEADERS:
// Caller error - writing on hijacked connection
w.conn.server.logf("http: response.WriteHeader on hijacked connection")

// Caller error - writing headers multiple times
w.conn.server.logf("http: multiple response.WriteHeader calls")

// Caller error - incorrect content length
w.conn.server.logf("http: invalid Content-Length of %q", cl)

// Caller error - incorrect mix of content length and transfer encoding
w.conn.server.logf("http: WriteHeader called with both Transfer-Encoding of %q and a Content-Length of %d",te, w.contentLength)

ERRORS WRITING RESPONSE:

// Caller error - trying to write on hijacked connection
w.conn.server.logf("http: response.Write on hijacked connection")

HANDLER ERRORS:

// Generic 500 error (server error - panic in handler)
c.server.logf("http: panic serving %v: %v\n%s", c.remoteAddr, err, buf)

CLIENT ERRORS:

// TLS handshake error (client error?)
c.server.logf("http: TLS handshake error from %s: %v", c.rwc.RemoteAddr(), err)

CLIENT ERRORS NOT LOGGED:
431 Request Header Fields Too Large
400 Bad Request (various reasons, mostly headers or url)

Info passed on with these current errors: RemoteAddr, contentLength, error string

There are also some related issues I think: #3344 #15949 #14205 #9383

[kennygrant]

So perhaps the best solution here is to add a ServerTrace to pkg httptrace with a handler for errors, which passes some info on to the caller about the reason for failure. See also the work started at #18997 for other tracing options for servers, this would extend that to provide a hook for errors.

I'm not sure on the signature for this error hook, to avoid leaking things like the connection, perhaps a struct containing some ConnInfo like the error, RemoteAddr, connection state, and perhaps an http status code?

[tombergan]

This is now a dup of #18997. See the following comment:
#18997 (comment)