New access logger #1408

rjshep · 2017-04-10T08:47:55Z

As requested in #1293, splitting new access logger into smaller commits to aid PR process.

This first PR adds the new access logger alongside the existing one, allowing information to be captured but at this stage not output. Additional functionality will follow in subsequent PRs.

timoreimann

It looks like the new code isn't test-covered completely yet. Do you plan on adding more tests?

Nit-pick: Could you try to fit the commit message into 80 characters?

timoreimann · 2017-04-10T20:48:16Z

middlewares/accesslog/capture_response_writer.go

+	if h, ok := crw.rw.(http.Hijacker); ok {
+		return h.Hijack()
+	}
+	return nil, nil, fmt.Errorf("Not a Hijacker: %T", crw.rw)


Decapitalize error messages please.

timoreimann · 2017-04-10T20:51:31Z

middlewares/accesslog/logger.go

+const (
+	// DataTableKey is the key within the request context used to
+	// store the Log Data Table
+	DataTableKey key = iota


Is this to be extended, or why does it hold a single value only?

timoreimann · 2017-04-10T20:56:13Z

middlewares/accesslog/logger.go

+	now := time.Now().UTC()
+	core := make(CoreLogData)
+
+	logDataTable := &LogData{core, req.Header, nil, nil}


I'd prefer to use key-indexed syntax and drop the nil values. This way, the code won't break should we add additional fields in the future.

timoreimann · 2017-04-10T21:08:33Z

middlewares/accesslog/logger.go

+const (
+	// DataTableKey is the key within the request context used to
+	// store the Log Data Table
+	DataTableKey key = iota


Is there a particular reason why we use 0/iota as the key here? Why not a more meaningful, human-readable string?

At least, this would make debugging easier.

Changed to string - more descriptive as you say.

timoreimann · 2017-04-10T21:09:29Z

middlewares/accesslog/logger.go

+
+	var crr *captureRequestReader
+	if req.Body != nil {
+		crr = &captureRequestReader{req.Body, 0}


Again, my preference goes towards a key-indexed definition.

timoreimann · 2017-04-10T21:13:43Z

middlewares/accesslog/logger.go

+	return nil
+}
+
+func silentSplitHostPort(value string) (string, string) {


Can we name the return parameters host and port, respectively, for documentary reasons?

timoreimann · 2017-04-10T21:19:32Z

middlewares/accesslog/logdata.go

+}
+
+// CoreLogData holds the fields computed from the request/response.
+type CoreLogData map[string]interface{}


I notice we have to do quite a bit of type casting due to the interface{} mapee.

Couldn't we just use a strongly typed struct instead of a map?

We went with the map so as to minimise the amount of effort needed to add additional log data in the future.

Could you elaborate please? How would a strongly typed struct increase the effort? What extra work would be needed that the map does not demand?

Personally, I tend to accept a bit more effort if it brings us compile-time safety. I don't see the full picture yet to understand the different trade-offs though.

timoreimann · 2017-04-10T21:20:44Z

middlewares/accesslog/logger.go

+	if original, ok := core[OriginContentSize]; ok {
+		o64 := original.(int64)
+		if o64 != crw.Size() {
+			// n.b divide-by-zero is tolerated here and dealt with elsewhere as appropriate


What do you mean by "is tolerated here"? Wouldn't the code panic if crw.Size() turned out to be zero?

You're right it would panic. I've changed the code to avoid divide by zero.

timoreimann · 2017-04-10T21:25:01Z

middlewares/accesslog/save_backend.go

+	return &SaveBackend{next, backendName}
+}
+
+func copyHeaders(src http.Header) http.Header {


Our vulcand/oxy dependency already brings a header copying functionality. Not sure if you can use it though since it does not override headers.

Code changed to use the existing header copying function.

timoreimann · 2017-04-10T21:27:08Z

middlewares/logger_test.go

+	// Temporary - until new access logger is fully implemented
+	// create the data table and populate frontend and backend
+	core := make(accesslog.CoreLogData)
+	logDataTable := &accesslog.LogData{core, r.Header, nil, nil}


Keyed index.

rjshep · 2017-04-11T09:13:44Z

I've made the requested modifications and addressed the other comments.

In terms of tests, yes there are more to come with the rest of the changes which will introduce an appender for the new logger as well as formatters for JSON and the common logging format.

The change to the existing access logger to get frontend and backend name is covered by an existing test modified in this PR.

timoreimann · 2017-04-12T23:27:19Z

middlewares/accesslog/save_backend.go

+
+import (
+	"fmt"
+	"github.com/vulcand/oxy/utils"


Please group the non-stdlib imports at the bottom, separated by a blank line.

timoreimann · 2017-04-12T23:27:59Z

middlewares/logger_test.go

@@ -10,6 +10,8 @@ import (
 	"runtime"
 	"testing"

+	"context"


Please move this import right below the other stdlib ones and use the blank line to separate from the non-stdlib imports following.

timoreimann · 2017-04-12T23:32:46Z

middlewares/accesslog/logdata.go

+}
+
+// CoreLogData holds the fields computed from the request/response.
+type CoreLogData map[string]interface{}


Could you elaborate please? How would a strongly typed struct increase the effort? What extra work would be needed that the map does not demand?

Personally, I tend to accept a bit more effort if it brings us compile-time safety. I don't see the full picture yet to understand the different trade-offs though.

rjshep · 2017-04-13T08:47:19Z

The intention for the new access logger is to provide a configurable output format, where the format, ordering and naming of the fields is based on user-supplied configuration. In order to do this simply the map was chosen so that, based on configuration, we can simply lookup the necessary values to output.

I appreciate that, as this PR doesn't include the log appenders, it's not easy to see why having the map is preferred.

If we choose a strongly typed struct we would (I believe) need to use either reflection or a large switch/case statement in order to achieve the same goal. So I guess the question is whether this is preferable to using the existing map?

If based on the above you would still like to replace the map with a struct I'll look at doing that, though my preference is to retain the map :-)

timoreimann · 2017-04-13T22:29:46Z

@rjshep thanks for elaborating. I'm okay with keeping the map for now. Let's revisit the decision once the follow-up PRs are coming in and enable a better understanding as you said.

timoreimann

This looks good for me, approving. 👍

Thanks again for taking the time to chop down the original PR into smaller pieces. I'd be happy to review any successor PRs.

emilevauge

@rjshep Thanks a lot for your contribution :)
I have one question: I think it may be safer to add these new middlewares into the chain if and only if access logs are enabled in the config. WDYT?

emilevauge · 2017-04-14T08:50:38Z

middlewares/accesslog/capture_response_writer.go

+	"net"
+	"net/http"
+)
+


Could you add this here ?

var ( _ http.ResponseWriter = &captureResponseWriter{} _ http.Hijacker = &captureResponseWriter{} _ http.Flusher = &captureResponseWriter{} _ http.CloseNotifier = &captureResponseWriter{} )

rjshep · 2017-04-14T10:43:05Z

@emilevauge In terms of only adding the access log middleware when access logging is enabled in config, I think that is a good idea. If it's okay with you I propose to make that change in the next PR which will replace the current access logger with the new one?

emilevauge · 2017-04-19T15:49:10Z

@rjshep

I propose to make that change in the next PR which will replace the current access logger with the new one?

If you can make this PR in the next days, I'm not against that (we will freeze the code for v1.3 soon).

rjshep · 2017-04-19T15:54:22Z

@emilevauge Yes I can submit the next PR in a few days.

ldez · 2017-04-19T16:04:17Z

middlewares/accesslog/logger.go

+	core[StartUTC] = now
+	core[StartLocal] = now.Local()
+
+	r2 := req.WithContext(context.WithValue(req.Context(), DataTableKey, logDataTable))


can you use a more explicit variable naming for r2

ldez · 2017-04-19T16:04:34Z

middlewares/accesslog/logger.go

+		core[RequestHost], core[RequestPort] = silentSplitHostPort(req.Host)
+	}
+	// copy the URL without the scheme, hostname etc
+	u := &url.URL{


can you use a more explicit variable naming for u

ldez · 2017-04-19T16:05:17Z

middlewares/accesslog/logger.go

+		ForceQuery: req.URL.ForceQuery,
+		Fragment:   req.URL.Fragment,
+	}
+	us := u.String()


can you use a more explicit variable naming for us

ldez · 2017-04-19T16:05:32Z

middlewares/accesslog/logger.go

+
+func usernameIfPresent(u *url.URL) string {
+	username := "-"
+	if u.User != nil {


can you use a more explicit variable naming for u

ldez · 2017-04-19T16:06:11Z

middlewares/accesslog/save_backend.go

+	return &SaveBackend{next, backendName}
+}
+
+func (sb *SaveBackend) ServeHTTP(rw http.ResponseWriter, r *http.Request) {


can you use a more explicit variable naming for rw and r

I've left this the same as it's consistent with all of the other middlewares :-)

ldez · 2017-04-19T16:06:30Z

middlewares/accesslog/save_backend.go

+	return &SaveFrontend{next, frontendName}
+}
+
+func (sb *SaveFrontend) ServeHTTP(rw http.ResponseWriter, r *http.Request) {


can you use a more explicit variable naming for rw and r

I've left this the same as it's consistent with all of the other middlewares :-)

rjshep · 2017-04-20T09:24:07Z

@emilevauge @ldez @timoreimann Hi all, is there anything further required before this PR can be merged? I'm keen to press on with the next PR.

timoreimann · 2017-04-20T10:46:16Z

As far as my review is concerned, I'm fine with the status quo.

emilevauge

Thanks a lot @rjshep !
LGTM (after rebased) 🎉

…t appenders.

rjshep mentioned this pull request Apr 10, 2017

Configurable access logger with JSON support #1293

Closed

emilevauge added status/1-needs-design-review status/2-needs-review labels Apr 10, 2017

timoreimann suggested changes Apr 10, 2017

View reviewed changes

timoreimann reviewed Apr 12, 2017

View reviewed changes

timoreimann approved these changes Apr 13, 2017

View reviewed changes

emilevauge reviewed Apr 14, 2017

View reviewed changes

emilevauge added the priority/P1 need to be fixed in next release label Apr 19, 2017

ldez reviewed Apr 19, 2017

View reviewed changes

emilevauge approved these changes Apr 20, 2017

View reviewed changes

emilevauge added status/3-needs-merge and removed status/1-needs-design-review status/2-needs-review labels Apr 20, 2017

timoreimann force-pushed the access-logging branch from f85e935 to 38a0acf Compare April 22, 2017 22:45

First stage of access logging middleware. Initially without any outpu…

73a1b17

…t appenders.

timoreimann force-pushed the access-logging branch from 38a0acf to 73a1b17 Compare April 22, 2017 22:46

timoreimann merged commit f38d117 into traefik:master Apr 22, 2017

ldez modified the milestone: 1.3 Apr 23, 2017

rjshep mentioned this pull request Apr 24, 2017

Switch to new access logger and add JSON format #1485

Closed

andrzejressel mentioned this pull request Apr 24, 2017

Add more prometheus metrics #1405

Closed

ldez added the kind/enhancement a new or improved feature. label Apr 29, 2017

ldez removed the priority/P1 need to be fixed in next release label Apr 29, 2017

emilevauge mentioned this pull request May 3, 2017

Revert "New access logger" #1541

Merged

ldez modified the milestones: 1.4, 1.3 May 6, 2017

ldez mentioned this pull request May 9, 2017

Restore: First stage of access logging middleware. #1571

Merged

ldez modified the milestones: 1.3, 1.4 May 19, 2017

ldez added area/logs and removed status/3-needs-merge labels May 19, 2017

New access logger #1408

New access logger #1408

Conversation

rjshep commented Apr 10, 2017

timoreimann left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

timoreimann Apr 10, 2017 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rjshep commented Apr 11, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rjshep commented Apr 13, 2017

timoreimann commented Apr 13, 2017

timoreimann left a comment

Choose a reason for hiding this comment

emilevauge left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rjshep commented Apr 14, 2017 • edited

emilevauge commented Apr 19, 2017

rjshep commented Apr 19, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rjshep commented Apr 20, 2017

timoreimann commented Apr 20, 2017

emilevauge left a comment

Choose a reason for hiding this comment

timoreimann Apr 10, 2017 •

edited

rjshep commented Apr 14, 2017 •

edited