Fix traefik logs to behave like configured #2176

m3co-code · 2017-09-26T06:36:06Z

This PR accomplishes two things:

it makes sure that all traefik logs are written in the specified format. Before the first log messages were written in text, even when you specified JSON as the format. This is because some log output was produced before configuring the logs.
it makes sure that all traefik logs are written to the traefik logs file. This is implemented by using logrus.Exit() and by closing the file in a logrus.RegisterExitHandler.

I also changed that errors from http.Serve and http.ServeTLS are not logged anymore, in the case they are regular http.ErrServerClosed errors, which is expected and the normal case. Those methods will never return a non-nil error.

This fixes #2156.

timoreimann · 2017-09-26T07:08:32Z

Do we know why simply deferring isn't enough? Is this possibly related to a missed flush or a missing close? (I don't know if flushing stdout is even possible, just throwing around wild guesses here.)

m3co-code · 2017-09-26T07:44:38Z

Yes, I checked that deferring is not enough. This is basically the first example I have written in the description above (# sample of log output with closing log file).

Frankly speaking, I also don't understand yet why this does not work. AFAICS the run function is executed in the main go routine and thus when it exits, everything should exit. So my understanding of go. The output that is printed to stdout, given we close the log file in a defer of run is from other goroutines like listenSignals. I am currently digging deeper to find the reason for this.

m3co-code · 2017-09-26T08:12:57Z

@timoreimann I was able to build a solution that captures all output by using logrus.RegisterExitHandler. This way we can close the files properly and still catch all the output.

After having implemented this, there was surprisingly still output written to the stdout. Namely this: {"level":"error","msg":"Error creating server: http: Server closed","time":"2017-09-26T09:57:15+02:00"}. I had a look into the code and this is actually confusing in my opinion. This is the error returned from the http.Serve or http.ServeTLS which always return a non-nil error. I changed the logic in 20e4471 to output only real errors in order to avoid confusion and this way, we now have no more output on the stdout 🎉

Updating PR description right now.

ldez · 2017-09-26T08:44:21Z

~~Please undo the refactoring. (We can speak about this on Slack)~~
~~If it's a bug fix move the PR to 1.4 branch. (maybe split your PR in two)~~

m3co-code · 2017-10-02T14:17:55Z

@ldez and @juliens I changed and rebased the PR now according to our discussion. This was basically to keep the run method agnostic of the traefikConfiguration. PR is ready for review.

juliens

😉

juliens · 2017-10-02T14:32:11Z

cmd/traefik/traefik.go

+			// Try to fallback to traefik config file in case the file provider is enabled
+			// but it has no file name configured.
+			if fileProviderEnabled && len(globalConfiguration.File.Filename) == 0 && traefikConfigFileExists {
+				globalConfiguration.File.Filename = traefikConfiguration.ConfigFile


Can you move this code in the run func, and use the "new" config file param

I went one step further and pushed it down to SetEffectiveConfiguration as it fits there best IMO.

juliens · 2017-10-02T14:37:52Z

cmd/traefik/traefik.go

+
+	if globalConfiguration.Debug {
+		globalConfiguration.LogLevel = "DEBUG"
+	}


this code should be in setEffectiveConfiguration ? WDYT

I am not sure about that. The docs of SetEffectiveConfiguration states:

SetEffectiveConfiguration adds missing configuration parameters derived from existing ones. It also takes care of maintaining backwards compatibility.

In my perception, this is actually not the case. LogLevel is not a missing configuration parameter. It's meant to be this way.

Additionally SetEffectiveConfiguration is called after configureLogging, and that is for the good reason that the logging configuration should happen as first thing in order to achieve what this PR tries to achieve. Log all messages in the desired format and write them to a file if it is configured.

juliens · 2017-10-02T14:38:04Z

cmd/traefik/traefik.go

+	logFile := globalConfiguration.TraefikLogsFile
+	if len(logFile) > 0 {
+		log.Warn("top-level traefiklogsfile has been deprecated -- please use traefiklog.filepath")
+	}


this code should be in setEffectiveConfiguration and change the globalConfiguration.TraefikLog value ? WDYT

I don't think so, for the same reasons stated it in #2176 (comment).

m3co-code · 2017-10-02T17:05:17Z

@juliens I commented/addressed all your comments. PTAL again :-)

ldez · 2017-10-02T18:18:53Z

configuration/configuration_test.go:244:32: not enough arguments in call to gc.SetEffectiveConfiguration
	have ()
	want (string)

m3co-code · 2017-10-02T18:54:51Z

Ups. Will fix Wednesday morning probably. Holiday :D

m3co-code · 2017-10-04T13:50:39Z

@ldez @juliens PTAL again. I fixed the test failure and while doing this I realized it would be valuable to add a new test case for SetEffectiveConfiguration. So I did that.

nmengin

LGTM 👏 🗞️

ldez

LGTM

ldez · 2017-09-26T08:10:46Z

cmd/traefik/traefik.go

@@ -223,8 +211,23 @@ Complete documentation is available at https://traefik.io`,
 	os.Exit(0)
 }

-func run(globalConfiguration *configuration.GlobalConfiguration) {
-	fmtlog.SetFlags(fmtlog.Lshortfile | fmtlog.LstdFlags)
+func run(traefikConfiguration *TraefikConfiguration) {


use high order function (and rename):

func runTraefikCmd(traefikConfiguration *TraefikConfiguration) func() error { return func() error { globalConfiguration := &traefikConfiguration.GlobalConfiguration // ... } }

traefikConfiguration := NewTraefikConfiguration() traefikPointersConfiguration := NewTraefikDefaultPointersConfiguration() //traefik Command init traefikCmd := &flaeg.Command{ Name: "traefik", Description: `traefik is a modern HTTP reverse proxy and load balancer made to deploy microservices with ease. Complete documentation is available at https://traefik.io`, Config: traefikConfiguration, DefaultPointersConfig: traefikPointersConfiguration, Run: runTraefikCmd(traefikConfiguration), }

Is this something I should address in a follow-up PR?

Also, can you explain a bit the benefit you see in this? We were discussing with @juliens that you want to keep run function to not know anything about the traefikConfiguration, because of a future feature you were working on. Is this still aligned with this effort?

The functions http.Serve and http.ServeTLS always return a non-nil error. In the "success" case, when the server is closed normally, they return ErrServerClosed. So we should only log when it is not that error.

traefiker added size/S status/0-needs-triage labels Sep 26, 2017

timoreimann added kind/bug/fix a bug fix status/2-needs-review and removed status/0-needs-triage labels Sep 26, 2017

ldez added status/2-needs-review and removed status/2-needs-review labels Sep 26, 2017

ldez added status/1-needs-design-review status/2-needs-review and removed status/2-needs-review status/1-needs-design-review labels Sep 26, 2017

ldez added this to the 1.5 milestone Sep 28, 2017

ldez added the contributor/waiting-for-corrections label Sep 28, 2017

m3co-code force-pushed the capture-all-traefik-log-in-file branch from 20e4471 to ad9a21c Compare October 2, 2017 14:15

juliens requested changes Oct 2, 2017

View reviewed changes

ldez removed the contributor/waiting-for-corrections label Oct 2, 2017

ldez added the contributor/waiting-for-corrections label Oct 2, 2017

ldez removed the contributor/waiting-for-corrections label Oct 4, 2017

nmengin approved these changes Oct 10, 2017

View reviewed changes

ldez approved these changes Oct 10, 2017

View reviewed changes

juliens approved these changes Oct 11, 2017

View reviewed changes

juliens added status/3-needs-merge and removed status/2-needs-review labels Oct 11, 2017

traefiker added the status/4-merge-in-progress label Oct 11, 2017

m3co-code added 5 commits October 11, 2017 08:24

capture all traefik logs in output file

94b9ac4

only log server error creation when real error occurs

a5fa636

The functions http.Serve and http.ServeTLS always return a non-nil error. In the "success" case, when the server is closed normally, they return ErrServerClosed. So we should only log when it is not that error.

move fallback of FileProvider file to SetEffectiveConfiguration

a6e60af

add test case for SetEffectiveConfiguration

e2b89e1

fix typo in test name

9cea757

traefiker force-pushed the capture-all-traefik-log-in-file branch from 416d7aa to 9cea757 Compare October 11, 2017 08:24

traefiker removed the status/4-merge-in-progress label Oct 11, 2017

traefiker merged commit 871d097 into traefik:master Oct 11, 2017

traefiker removed the status/3-needs-merge label Oct 11, 2017

ldez added the area/logs label Nov 24, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix traefik logs to behave like configured #2176

Fix traefik logs to behave like configured #2176

m3co-code commented Sep 26, 2017 •

edited

Loading

timoreimann commented Sep 26, 2017

m3co-code commented Sep 26, 2017

m3co-code commented Sep 26, 2017 •

edited

Loading

ldez commented Sep 26, 2017 •

edited

Loading

m3co-code commented Oct 2, 2017

juliens left a comment

juliens Oct 2, 2017

m3co-code Oct 2, 2017

juliens Oct 2, 2017

m3co-code Oct 2, 2017

juliens Oct 2, 2017

m3co-code Oct 2, 2017

m3co-code commented Oct 2, 2017

ldez commented Oct 2, 2017

m3co-code commented Oct 2, 2017

m3co-code commented Oct 4, 2017 •

edited

Loading

nmengin left a comment

ldez left a comment

ldez Sep 26, 2017

m3co-code Oct 11, 2017

Fix traefik logs to behave like configured #2176

Fix traefik logs to behave like configured #2176

Conversation

m3co-code commented Sep 26, 2017 • edited Loading

timoreimann commented Sep 26, 2017

m3co-code commented Sep 26, 2017

m3co-code commented Sep 26, 2017 • edited Loading

ldez commented Sep 26, 2017 • edited Loading

m3co-code commented Oct 2, 2017

juliens 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

m3co-code commented Oct 2, 2017

ldez commented Oct 2, 2017

m3co-code commented Oct 2, 2017

m3co-code commented Oct 4, 2017 • edited Loading

nmengin left a comment

Choose a reason for hiding this comment

ldez left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

m3co-code commented Sep 26, 2017 •

edited

Loading

m3co-code commented Sep 26, 2017 •

edited

Loading

ldez commented Sep 26, 2017 •

edited

Loading

m3co-code commented Oct 4, 2017 •

edited

Loading