Log request headers, response headers and some body as warning on 500s by jml · Pull Request #41 · weaveworks/common

jml · 2017-06-02T17:07:23Z

This is kind of a significant change, as it intercepts all incoming requests. I haven't done much in the way of testing.

Also changes the logging order slightly. Previously, when LogRequestHeaders was on, we would log headers then request/response summary (method, status, etc). Now, we log method, status, etc. then headers.

bboreham

Code is broadly fine, but I observe that it goes to a lot of work to capture response headers when they are not asked for in the original issue. I can't immediately think why they would be useful in a 5xx.

middleware/response.go

+// response headers if `statusCode` is a 5XX.
+func (b *badResponseLogger) WriteHeader(statusCode int) {
+	b.statusCode = statusCode
+	b.recorder.WriteHeader(statusCode)


middleware/response.go

+		recorder:      httptest.NewRecorder(),
+		logBody:       false,
+		bodyBytesLeft: maxResponseBodyInLogs,
+		statusCode:    http.StatusOK,


middleware/response.go

+
+	if len(data) > b.bodyBytesLeft {
+		b.recorder.Write(data[:b.bodyBytesLeft])
+		b.recorder.WriteString("…")


middleware/response.go

+
+	if len(data) > b.bodyBytesLeft {
+		b.recorder.Write(data[:b.bodyBytesLeft])
+		b.recorder.WriteString("…")


middleware/response.go

+}
+
+// WriteHeader implements http.ResponseWriter. It will immediately log the
+// response headers if `statusCode` is a 5XX.


middleware/logging.go

+			logWithRequest(r).Warnf("Is websocket request: %v\n%s", IsWSHandshakeRequest(r), string(headers))
+			response, err := i.dumpResponse()
+			if err != nil {
+				logWithRequest(r).Errorf("Could not dump response headers: %v", err)


jml · 2017-09-12T14:38:35Z

it goes to a lot of work to capture response headers when they are not asked for in the original issue. I can't immediately think why they would be useful in a 5xx.

Does it really? It's been a while since I've looked at this, but I thought most of the work was around making sure we're still streaming headers & body, and that we don't accidentally store massive bodies in memory while building up a log entry.

I'm not sure what I'd change if we wanted to stop capturing response headers. Maybe change badResponseLogger.recorder to be a simple io.Writer rather than an httptest.ResponseRecorder. Or is there some other more significant simplification I'm missing?

bboreham · 2017-09-12T14:45:00Z

work

meaning we build a data structure of headers on every response, including the 200s and 400s that we're not going to log

change badResponseLogger.recorder to be a simple io.Writer rather than an httptest.ResponseRecorder.

Exactly. Like a bytes.Buffer.

jml · 2017-09-12T15:39:28Z

Makes sense. Doing that means that MultiResponseWriter is surplus to requirements and that a more specialised approach is warranted. Have merged badResponseLogger and MultiResponseWriter, which results in same behaviour with much less code.

jml · 2017-09-12T15:39:37Z

PTAL @bboreham

bboreham · 2017-09-15T13:10:50Z

Suggest you note this PR makes a quiet change, in that the order of request and headers is reversed in the logs, when LogRequestHeaders is on.

…g on 500s (#41)" This reverts commit c8c93e3.

…g on 500s" (#56) * Revert "Use new gRPC APIs (#55)" This reverts commit df441dc. * Revert "Log request headers, response headers and some body as warning on 500s (#41)" This reverts commit c8c93e3.

jml force-pushed the log-users branch 2 times, most recently from 6176a41 to ebb5295 Compare June 16, 2017 14:53

jml changed the title ~~[WIP] Log request headers, response headers and some body as warning on 500s~~ Log request headers, response headers and some body as warning on 500s Jun 16, 2017

jml requested a review from bboreham September 8, 2017 13:55

bboreham requested changes Sep 12, 2017

View reviewed changes

jml added 2 commits September 12, 2017 15:07

Put user/orgID in request log if we have it

16ba75b

Show request & response headers in logs for 500s

e58f695

jml force-pushed the log-users branch from ebb5295 to 7db095e Compare September 12, 2017 14:38

jml added 2 commits September 12, 2017 16:15

Review feedback

ae4a975

Just store the body in a buffer, rather than a response recorder

c581377

jml force-pushed the log-users branch from 7db095e to c581377 Compare September 12, 2017 15:15

jml added 2 commits September 12, 2017 16:35

Ditch MultiResponseWriter and go for a more specialised solution

443f890

Pass through the buffer, rather than returning bytes

529d65a

Seriously

5824073

bboreham approved these changes Sep 15, 2017

View reviewed changes

jml merged commit c8c93e3 into master Sep 18, 2017

jml deleted the log-users branch September 18, 2017 10:59

This was referenced Sep 18, 2017

Update dependencies weaveworks/service#1364

Merged

Revert "Update dependencies" weaveworks/service#1365

Merged

jml added a commit that referenced this pull request Sep 18, 2017

Revert "Log request headers, response headers and some body as warnin…

ebfb502

…g on 500s (#41)" This reverts commit c8c93e3.

jml mentioned this pull request Sep 18, 2017

Revert "Log request headers, response headers and some body as warning on 500s" #56

Merged

jml mentioned this pull request Sep 20, 2017

Log request headers, response headers and some body as warning on 500s #59

Merged

Conversation

jml commented Jun 2, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

bboreham left a comment

Choose a reason for hiding this comment

Uh oh!

This comment was marked as abuse.

Uh oh!

This comment was marked as abuse.

Uh oh!

This comment was marked as abuse.

Uh oh!

This comment was marked as abuse.

Uh oh!

This comment was marked as abuse.

Uh oh!

This comment was marked as abuse.

Uh oh!

This comment was marked as abuse.

Uh oh!

This comment was marked as abuse.

Uh oh!

jml commented Sep 12, 2017

Uh oh!

bboreham commented Sep 12, 2017

Uh oh!

jml commented Sep 12, 2017

Uh oh!

jml commented Sep 12, 2017

Uh oh!

bboreham commented Sep 15, 2017

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

jml commented Jun 2, 2017 •

edited

Loading