Configurable access logger with JSON support #1293

rickb777 · 2017-03-14T16:45:21Z

This is a new access logger derived from (and replacing) the old one. It exists in its own accesslog package under middlewares and has similar-ish net/http filters to the existing solution. Its first concern is to implement the existing extended Common Log Format behaviour, to provide a clean upgrade path for existing users.

But it's now split into pluggable parts, the important part being its formatter (the CLF formatter being the default). A new JSON formatter exists.

The file writing part is termed the log appender and is slightly enhanced: it allows buffered writing, or gzipped writing, and/or asynchronous writing via a channel/goroutine.

The final area of change is to the configuration: new settings are needed to control the new features. This is done with a new AccessLog type in types.go.

Notice that there are now three middlewares:

the first is the 'main' logger that tracks each request, builds log events, and despatches these to the log appender;
the second inserts knowledge about the frontend into the log-data context;
the third inserts knowledge about the backend into the log-data context.
There had previously been an error in tracking the frontend data: it operated on the incorrect assumption that there is a 1:N mapping from frontends to backends.

rickb777 · 2017-03-14T17:14:41Z

This PR supersedes #1230.

Fixes race condition when concurrently writing to the log file. Added HTTPRequestLine to the core data available for logging. Fixed some test issues.

…nsistent with ClientRemoteAddr.

…tent (OriginStatusLine, DownstreamStatusLine). Request body size is now captured when present.

# Conflicts: # server.go

timoreimann

I'm about half way through this PR; sending out comments accumulated up until this point to give author a chance to respond.

A few general remarks:

This PR is way too big. Could you please consider moving out parts that are not strictly needed for an initial implementation of JSON logging into separate PRs? I'm thinking that both compression and asynchronous writing could easily be handled as follow-up PRs. Even if I made it through it some point, we should make it as simple as possible for the second reviewer.
Could you please use snake case instead of camel case for all file names (e.g., log_appender.go instead of logAppender.go?
Design-wise, I very much like the changes introduced by this PR, so 👍 .

timoreimann · 2017-04-01T05:30:14Z

.gitignore

@@ -5,6 +5,7 @@
 *.iml
 /traefik
 /traefik.toml
+vendor/


That folder must not be ignored as we have switched to vendoring a while ago.

pls exclude that change to .gitignore.

Point 1 is the tricky one. I've already had three attempts at writing this PR and in the end it seemed more satisfactory to complete the implementation instead of feeding small parts of it one by one. I'm open to persuasion though.

Point 2 - the existing codebase uses both styles. We should make it consistent as a separate PR I think.

We still need to include the vendor folder.

What did point 2 refer to again? Seems like the comment was placed at the wrong spot, or the Github UI is fooling us once again.

timoreimann · 2017-04-01T05:34:46Z

Makefile

@@ -59,13 +59,13 @@ build-no-cache: dist
 shell: build ## start a shell inside the build env
 	$(DOCKER_RUN_TRAEFIK) /bin/bash

-image: binary ## build a docker traefik image
+image: build ## build a docker traefik image


This effectively reverts #1329.

Was this a mistake, or do you have a particular reason to return to the old behavior?

pls exclude that change.

timoreimann · 2017-04-02T09:07:49Z

Makefile

@@ -82,5 +82,9 @@ lint:

 fmt:
 	gofmt -s -l -w $(SRCS)
+
+clean:
+	sudo rm -rf dist static site autogen/gen.go traefik


Does the Makefile ever compile a Traefik binary into ./traefik? If not, then we should maybe not remove it.

./traefik is created by go build ..

There is a structural problem with the Makefile: artefacts built using Docker are owned by root, not by the current user.

It should be possible to make clean. When make clean is executed, all generated artefacts should be deleted. This is an important requirement for developers. As it stands, it may be necessary to sudo make clean, which is an adequate interim compromise. Ideally this problem would be solved more completely.

Strange, I never had a problem with deleting files created by the build container. Not in front of my laptop right now, but is this maybe something happening on some platforms other than Mac OS X only?

I'm okay with creating a clean target (though I personally never needed it). Does our Makefile call go build without specifying an output file somewhere below dist/ though? If not, then I still believe traefik (in the root directory) should not be removed.

timoreimann · 2017-04-02T09:09:39Z

docs/toml.md

-# Optional
-#
-# accessLogsFile = "log/access.log"
-


We shouldn't remove it from the docs while the parameter is still available. Better leave a deprecation warning.

timoreimann · 2017-04-02T17:14:27Z

docs/toml.md

+```
+
+The file can be gzipped as it is written if you require; just add a
+`.gz` extension:


Easy yet effective way to enable compression. I like this. 👍

timoreimann · 2017-04-03T21:06:14Z

middlewares/accesslog/linearWriter_test.go

+	wg.Add(n)
+	for i := 0; i < n; i++ {
+		go func(j int) {
+			fmt.Fprintf(lw, "Line %d\n", j)


Can we remove the Line prefix to make the assertion below more readable?

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

middlewares/accesslog/linearWriter_test.go

+	scanner := bufio.NewScanner(r)
+	for i := 0; i < n; i++ {
+		assert.True(t, scanner.Scan())
+		line := scanner.Text()


How about using ioutil/ReadFile instead and just casting each byte value into a string?

timoreimann · 2017-04-03T21:10:07Z

middlewares/accesslog/linearWriter_test.go

+	}
+
+	for i := 0; i < n; i++ {
+		assert.Equal(t, 1, counts[i], "Line %d should have count=1 but was %d", i, counts[i])


We should be able to inline this check into the main test loop body.

timoreimann · 2017-04-03T21:10:14Z

middlewares/accesslog/logAppender.go

+	"compress/gzip"
+	"fmt"
+	"github.com/containous/traefik/log"
+	"github.com/containous/traefik/types"


Import order.

timoreimann · 2017-04-03T21:18:48Z

middlewares/accesslog/jsonLogFormatter.go

+func (l jsonLogFormatter) Write(w io.Writer, logDataTable *LogData) error {
+
+	buf := &bytes.Buffer{}
+	buf.WriteString("{")


I see that we are producing JSON (braces here, objects below) manually. Can we try to populate our content in some map/struct and call json.Marshal on it instead?

Implementing json.Marshaler on some type might be helpful too.

We could do that and we started with that. But the handling of some fields requires bespoke treatment. We considered copying the data into a map (formatting values at the copy stage) and then marshalling the map. But the decision was taken to do the implementation as you see, handling the top-level of the JSON document explicitly and only using json.Marshal for the string values. It's a similar amount of code and requires less copying / memory footprint.

There is possibly scope for improving this.

emilevauge

Wow @rickb777, what a PR !
Like @timoreimann, I think it is way too big. It's really difficult for a reviewer to validate such a change set.
Would you consider splitting this one into smaller PRs ?

timoreimann

Addressed two open points.

Prior to moving forward with the review, we definitely need to carve out or drop parts which are not strictly needed for an initial implementation of structured logging, namely the compression and asynchronous features. I realize that will mean more work on your end, but a ~3,000 LOC PR is just not reviewable otherwise. It should be possible to create follow-up PRs and make them base on each predecessor, respectively, in terms of target branches to merge into.

Again, I really like the overall improvement in design, but we need to get it into a digestible shape.

timoreimann · 2017-04-09T08:12:12Z

.gitignore

@@ -5,6 +5,7 @@
 *.iml
 /traefik
 /traefik.toml
+vendor/


We still need to include the vendor folder.

timoreimann · 2017-04-09T08:17:50Z

Makefile

@@ -82,5 +82,9 @@ lint:

 fmt:
 	gofmt -s -l -w $(SRCS)
+
+clean:
+	sudo rm -rf dist static site autogen/gen.go traefik


Strange, I never had a problem with deleting files created by the build container. Not in front of my laptop right now, but is this maybe something happening on some platforms other than Mac OS X only?

I'm okay with creating a clean target (though I personally never needed it). Does our Makefile call go build without specifying an output file somewhere below dist/ though? If not, then I still believe traefik (in the root directory) should not be removed.

timoreimann · 2017-04-09T08:19:58Z

.gitignore

@@ -5,6 +5,7 @@
 *.iml
 /traefik
 /traefik.toml
+vendor/


What did point 2 refer to again? Seems like the comment was placed at the wrong spot, or the Github UI is fooling us once again.

timoreimann · 2017-04-09T08:21:22Z

docs/toml.md

+ * `coreFields` : data gleaned from the HTTP request.
+ * `requestHeaders` : the set of headers received in the request.
+ * `originResponseHeaders` : the set of headers received from the origin (a.k.a. upstream) server
+ * `downstreamResponseHeaders` : the set of headers passed back to the client


Gotcha. 👍

rjshep · 2017-04-10T08:51:36Z

In order to progress this new access logger I am going to submit a series of smaller PRs. Hopefully these will be easier to review :-)

I have created PR #1408 as the first set of changes.

timoreimann · 2017-04-15T09:17:50Z

@rjshep shall we close this one in favor of #1408 and other PRs which are yet to come?

rjshep · 2017-04-18T12:44:38Z

@timoreimann Yes, please close this PR. I'll follow up with additional PRs with the rest of the functionality once #1408 is accepted.

timoreimann · 2017-04-18T22:16:16Z

Thanks for the update.

rickb777 mentioned this pull request Mar 14, 2017

Configurable access logger with JSON support #1230

Closed

rickb777 force-pushed the json-logging branch from 8ae6bc1 to 09a2fce Compare March 15, 2017 16:28

Configurable JSON / Common Log Format access logging implemented

dfe3096

Fixes race condition when concurrently writing to the log file. Added HTTPRequestLine to the core data available for logging. Fixed some test issues.

rickb777 force-pushed the json-logging branch from 09a2fce to dfe3096 Compare March 15, 2017 16:36

rickb777 and others added 5 commits March 15, 2017 17:16

Merge branch 'master' into json-logging

b27f723

lint

dd44fe6

Add HTTPRequestLine to core logging fields

04533a7

HTTPHost divided into HTTPAddr, HTTPHost and HTTPPort. This is now co…

0d51917

…nsistent with ClientRemoteAddr.

HTTPHost divided into HTTPAddr, HTTPHost and HTTPPort. This is now co…

6a65d10

…nsistent with ClientRemoteAddr.

rickb777 changed the title ~~Configurable access logger with JSON support~~ WIP: Configurable access logger with JSON support Mar 17, 2017

Rick and others added 10 commits March 17, 2017 15:30

GzipRatio is elided when its value is 1.

e163569

Small twea:; dead code removed, doc correction

b98b2fe

Added more fields to CoreData and renamed some to be more self-consis…

6d4e0da

…tent (OriginStatusLine, DownstreamStatusLine). Request body size is now captured when present.

Merge remote-tracking branch 'upstream/master' into json-logging

0ee892a

Added BackendAddr to the CoreLogData fields.

d676ea8

Minor test improvement

f85df21

Merge remote-tracking branch 'upstream/master' into json-logging

d76cbb7

# Conflicts: # server.go

merged

03ad503

minor: shared var is now an array instead of a slice

fb8f28a

Merge branch 'master' into json-logging

7b97625

rickb777 changed the title ~~WIP: Configurable access logger with JSON support~~ Configurable access logger with JSON support Mar 29, 2017

Merge branch 'master' into json-logging

5eb8cac

timoreimann self-requested a review April 3, 2017 16:56

timoreimann suggested changes Apr 3, 2017

View reviewed changes

emilevauge reviewed Apr 4, 2017

View reviewed changes

Rick added 4 commits April 4, 2017 12:13

Renamed files to use snake-case.

55e3255

imports

4a004c0

test simplification

b0bf3d6

Merge remote-tracking branch 'upstream/master' into json-logging

d44f17f

Rick added 2 commits April 5, 2017 12:12

further reviewer-suggested changes, including removal of async writing

7d5f649

whitespace

6adb72d

emilevauge mentioned this pull request Apr 5, 2017

New middleware #1391

Closed

emilevauge added the contributor/waiting-for-corrections label Apr 6, 2017

timoreimann suggested changes Apr 9, 2017

View reviewed changes

rjshep mentioned this pull request Apr 10, 2017

New access logger #1408

Merged

timoreimann closed this Apr 18, 2017

timoreimann mentioned this pull request Apr 30, 2017

Switch to new access logger and add JSON format #1485

Closed

altovedo deleted the json-logging branch September 12, 2018 08:58

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Configurable access logger with JSON support #1293

Configurable access logger with JSON support #1293

rickb777 commented Mar 14, 2017

rickb777 commented Mar 14, 2017

timoreimann left a comment

timoreimann Apr 1, 2017

rickb777 Apr 4, 2017 •

edited

rickb777 Apr 4, 2017

rickb777 Apr 4, 2017 •

edited

timoreimann Apr 9, 2017

timoreimann Apr 9, 2017

timoreimann Apr 1, 2017

rickb777 Apr 4, 2017

timoreimann Apr 2, 2017

rickb777 Apr 5, 2017

timoreimann Apr 9, 2017

timoreimann Apr 2, 2017

rickb777 Apr 4, 2017

timoreimann Apr 2, 2017

timoreimann Apr 3, 2017

timoreimann Apr 3, 2017

timoreimann Apr 3, 2017

timoreimann Apr 3, 2017

timoreimann Apr 3, 2017

rickb777 Apr 4, 2017 •

edited

emilevauge left a comment

timoreimann left a comment

timoreimann Apr 9, 2017

timoreimann Apr 9, 2017

timoreimann Apr 9, 2017

timoreimann Apr 9, 2017

rjshep commented Apr 10, 2017

timoreimann commented Apr 15, 2017

rjshep commented Apr 18, 2017

timoreimann commented Apr 18, 2017

Configurable access logger with JSON support #1293

Configurable access logger with JSON support #1293

Conversation

rickb777 commented Mar 14, 2017

rickb777 commented Mar 14, 2017

timoreimann left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rickb777 Apr 4, 2017 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rickb777 Apr 4, 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

Choose a reason for hiding this comment

rickb777 Apr 4, 2017 • edited

Choose a reason for hiding this comment

emilevauge left a comment

Choose a reason for hiding this comment

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

rjshep commented Apr 10, 2017

timoreimann commented Apr 15, 2017

rjshep commented Apr 18, 2017

timoreimann commented Apr 18, 2017

rickb777 Apr 4, 2017 •

edited

rickb777 Apr 4, 2017 •

edited

rickb777 Apr 4, 2017 •

edited