Switch access logging to logrus #1647

rjshep · 2017-05-21T21:31:37Z

Building on some initial work to introduce a new access logging framework, this PR uses logrus as the log handler to write access logs using information collected in the log data table.

A logrus Formatter implements Traefik Common Log Format producing logs which are backward compatible with the current access logs.

Also includes applicable changes from #1507

ldez · 2017-05-21T23:01:45Z

server/server.go

@@ -544,7 +541,6 @@ func (server *Server) loadConfig(configurations configs, globalConfiguration Glo
 	redirectHandlers := make(map[string]negroni.Handler)
 	backends := map[string]http.Handler{}
 	backendsHealthcheck := map[string]*healthcheck.BackendHealthCheck{}
-	backend2FrontendMap := map[string]string{}


why you have remove this line?

Because the backend to frontend map was only used by the old logger. The new framework, added during a previous PR, uses accesslog.NewSaveBackend and accesslog.NewSaveFrontend to achieve the same thing.

emilevauge

Hey @rjshep !

Thanks a lot for this new (smaller) PR :)

I would like to suggest a design change.
In order to remove all if l.logger != nil from logger.go: NewLogHandler should return an error in case fileName is empty. And we should not add this middleware into the chain in this use case.

Could you also remove saveBackend & saveFrontend middlewares from server.go when we don't have access logs enabled?

I also made few comments/suggestions in the code :)

emilevauge · 2017-05-22T14:45:10Z

middlewares/accesslog/logger_formatters.go

+
+	timestamp := entry.Data[StartUTC].(time.Time).Format(commonLogTimeFormat)
+	elapsedMillis := entry.Data[Duration].(time.Duration).Nanoseconds() / 1000000
+	referer := entry.Data["request_Referer"]


Maybe there is a constant in standard lib or in lorgus ?

emilevauge · 2017-05-22T14:45:16Z

middlewares/accesslog/logger_formatters.go

+	if referer == nil {
+		referer = ""
+	}
+	userAgent := entry.Data["request_User-Agent"]


Maybe there is a constant in standard lib or in lorgus ?

emilevauge · 2017-05-22T15:17:42Z

middlewares/accesslog/logger_formatters.go

+	}
+
+	return "-"
+}


WDYT of this kind of refactoring?

func toLogString(v interface{}) string { defaultValue := "-" if v == nil { return defaultValue } switch s := v.(type) { case string: return quoted(s, defaultValue) case fmt.Stringer: return quoted(s.String(), defaultValue) default: return defaultValue } } func quoted(s string, defaultValue string) string { if len(s) == 0 { return defaultValue } return `"` + s + `"` }

LGTM I've added it in. It has meant that the log format is not fully backward compatible. Referer and User Agent fields are now specified as a hyphen if not present, previously they were just missing. I believe the new format is actually correct, however.

rjshep · 2017-05-22T21:03:02Z

Hi @emilevauge I've made the requested changes. Thanks for the design change, that is a better solution :)

timoreimann

Thanks! I left a few comments.

timoreimann · 2017-05-23T19:04:50Z

integration/access_log_test.go

-			c.Assert(regexp.MustCompile(`^\d+ms$`).MatchString(tokens[12]), checker.True)
+			c.Assert(tokens[10], checker.Equals, fmt.Sprintf("%d", i+1))
+			c.Assert(strings.HasPrefix(tokens[11], "frontend"), checker.True)
+			c.Assert(strings.HasPrefix(tokens[12], "http://127.0.0.1:808"), checker.True)


Comprehension question: why do we have to change the indices?

The Referer and User Agent fields are now specified as a hyphen if not present, previously they were just missing. I believe the new format is actually correct, however.

timoreimann · 2017-05-23T19:05:29Z

middlewares/accesslog/logger.go

@@ -23,11 +29,34 @@ const (
 // Note: Current implementation collects log data but does not have the facility to


Is this comment still valid?

timoreimann · 2017-05-23T19:06:59Z

middlewares/accesslog/logger.go

 }

 // NewLogHandler creates a new LogHandler
-func NewLogHandler() *LogHandler {
-	return &LogHandler{}
+func NewLogHandler(fileName string) (*LogHandler, error) {


Nit-pick: I'd probably call the variable filePath.

timoreimann · 2017-05-23T19:07:22Z

middlewares/accesslog/logger.go

+		dir := filepath.Dir(fileName)
+
+		err := os.MkdirAll(dir, 0755)
+		if err != nil {


Can be merged with previous line.

timoreimann · 2017-05-23T19:08:04Z

middlewares/accesslog/logger.go

+
+		err := os.MkdirAll(dir, 0755)
+		if err != nil {
+			log.Errorf("Failed to create log path %s: %s", dir, err)


Shouldn't we return an error here?

timoreimann · 2017-05-23T19:12:20Z

middlewares/accesslog/logger.go

+
+		file, err := os.OpenFile(fileName, os.O_RDWR|os.O_CREATE|os.O_APPEND, 0664)
+		if err != nil {
+			log.Error("Error opening file", err)


Shouldn't we return an error instead?

timoreimann · 2017-05-23T19:14:20Z

middlewares/accesslog/logger.go

+		return &LogHandler{logger: logger, file: file}, nil
+	}
+
+	return nil, errors.New("Empty file name specified for accessLogsFile")


Please move this return at the very top of the file, right after a check for fileName == "". That way, we can save one level of indentation.

timoreimann · 2017-05-23T19:21:34Z

middlewares/accesslog/logger_test.go

@@ -47,16 +42,15 @@ func TestLogger(t *testing.T) {

 	logfilePath := filepath.Join(tmp, logfileNameSuffix)

-	logger = NewLogger(logfilePath)
+	logger, err = NewLogHandler(logfilePath)
+	assert.NoError(t, err)


We have added testify.require by now. Please use it here and wherever continuation of a test does not make sense anymore in case of a failed assertion.

ldez

Great job!!! 🎉

LGTM

timoreimann

One tiny thing left. :-)

timoreimann · 2017-05-23T20:40:32Z

middlewares/accesslog/logger.go

+	dir := filepath.Dir(filePath)
+
+	if err := os.MkdirAll(dir, 0755); err != nil {
+		log.Errorf("Failed to create log path %s: %s", dir, err)


Logging an error and returning an error normally do not go together; instead, we should return an error containing sufficient context and let the caller log.

Could you please pass the (de-capitalized) log message content to an fmt.Errorf call and just return that?

Same for lines 48:49.

rjshep · 2017-05-23T21:01:42Z

@timoreimann change made and commits squashed.

timoreimann

LGTM, thanks a lot!

emilevauge

@rjshep Just 2 minor comments :)
Other than that looks good!

emilevauge · 2017-05-24T10:22:20Z

middlewares/accesslog/logger.go

@@ -85,6 +110,7 @@ func (l *LogHandler) ServeHTTP(rw http.ResponseWriter, req *http.Request, next h

 // Close closes the Logger (i.e. the file etc).
 func (l *LogHandler) Close() error {
+	l.file.Close()


I think it should be return l.file.Close() ;)

emilevauge · 2017-05-24T10:23:11Z

server/server.go

-	server.loggerMiddleware.Close()
-	server.accessLoggerMiddleware.Close()
+	if server.accessLoggerMiddleware != nil {
+		server.accessLoggerMiddleware.Close()


You should check the return error here.

rjshep · 2017-05-24T11:00:37Z

Thanks @emilevauge. Changes made :)

emilevauge

Thanks @rjshep for this great PR!
We really appreciate your exemplary attitude 👏 👏 👏

rjshep force-pushed the logrus-access-logging branch from 2812422 to 84a8bdc Compare May 21, 2017 21:41

ldez requested review from timoreimann and emilevauge May 21, 2017 22:49

ldez added area/logs kind/enhancement a new or improved feature. labels May 21, 2017

ldez added this to the 1.4 milestone May 21, 2017

rjshep force-pushed the logrus-access-logging branch from 84a8bdc to 98523e0 Compare May 21, 2017 23:02

ldez suggested changes May 21, 2017

View reviewed changes

ldez added status/1-needs-design-review status/2-needs-review and removed status/1-needs-design-review labels May 22, 2017

emilevauge reviewed May 22, 2017

View reviewed changes

rjshep force-pushed the logrus-access-logging branch 2 times, most recently from 8d4399e to 05ab100 Compare May 22, 2017 20:27

timoreimann suggested changes May 23, 2017

View reviewed changes

ldez approved these changes May 23, 2017

View reviewed changes

timoreimann suggested changes May 23, 2017

View reviewed changes

rjshep force-pushed the logrus-access-logging branch from 974d1f0 to 147b9b0 Compare May 23, 2017 20:57

timoreimann approved these changes May 23, 2017

View reviewed changes

emilevauge requested changes May 24, 2017

View reviewed changes

Switch access logging to logrus

6ee1a2b

rjshep force-pushed the logrus-access-logging branch from 147b9b0 to 6ee1a2b Compare May 24, 2017 10:42

emilevauge approved these changes May 24, 2017

View reviewed changes

emilevauge merged commit 64e8b31 into traefik:master May 24, 2017

emilevauge removed the status/2-needs-review label May 24, 2017

emilevauge mentioned this pull request May 24, 2017

Switch to new access logger and add JSON format #1485

Closed

rjshep mentioned this pull request May 25, 2017

Add JSON as access logging format #1669

Merged

altovedo deleted the logrus-access-logging branch September 12, 2018 08:59

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Switch access logging to logrus #1647

Switch access logging to logrus #1647

rjshep commented May 21, 2017 •

edited

Loading

ldez May 21, 2017

rjshep May 21, 2017 •

edited

Loading

emilevauge left a comment

emilevauge May 22, 2017

emilevauge May 22, 2017

emilevauge May 22, 2017

rjshep May 22, 2017

rjshep commented May 22, 2017

timoreimann left a comment

timoreimann May 23, 2017

rjshep May 23, 2017

timoreimann May 23, 2017

timoreimann May 23, 2017

rjshep May 23, 2017

timoreimann May 23, 2017

rjshep May 23, 2017

timoreimann May 23, 2017

rjshep May 23, 2017

timoreimann May 23, 2017

rjshep May 23, 2017

timoreimann May 23, 2017

rjshep May 23, 2017

timoreimann May 23, 2017

rjshep May 23, 2017

ldez left a comment

timoreimann left a comment

timoreimann May 23, 2017

rjshep commented May 23, 2017

timoreimann left a comment

emilevauge left a comment

emilevauge May 24, 2017

emilevauge May 24, 2017

rjshep commented May 24, 2017

emilevauge left a comment

		@@ -23,11 +29,34 @@ const (
		// Note: Current implementation collects log data but does not have the facility to

Switch access logging to logrus #1647

Switch access logging to logrus #1647

Conversation

rjshep commented May 21, 2017 • edited Loading

Choose a reason for hiding this comment

rjshep May 21, 2017 • edited Loading

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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rjshep commented May 22, 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

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

ldez 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

rjshep commented May 23, 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 May 24, 2017

emilevauge left a comment

Choose a reason for hiding this comment

rjshep commented May 21, 2017 •

edited

Loading

rjshep May 21, 2017 •

edited

Loading