logging: unify pkg/log and plugin/log #2245

miekg · 2018-10-27T14:38:37Z

Default to using pkg/log for all logging output and make that always use
UTC.

Signed-off-by: Miek Gieben miek@miek.nl

corbot · 2018-10-27T14:38:40Z

Thank you for your contribution. I've just checked the OWNERS files to find a suitable reviewer. This search was successful and I've asked fastest963 (via /OWNERS) for a review.

If you have questions or suggestions for this bot, please file an issue against the miekg/dreck repository.

The bot understands the commands that are listed here.

codecov-io · 2018-10-27T14:49:39Z

Codecov Report

Merging #2245 into master will increase coverage by 0.04%.
The diff coverage is 85.71%.

@@            Coverage Diff             @@
##           master    #2245      +/-   ##
==========================================
+ Coverage    56.3%   56.35%   +0.04%     
==========================================
  Files         203      203              
  Lines       10137    10138       +1     
==========================================
+ Hits         5708     5713       +5     
+ Misses       3996     3995       -1     
+ Partials      433      430       -3

Impacted Files	Coverage Δ
plugin/log/setup.go	`86.44% <ø> (+5.48%)`	⬆️
coremain/run.go	`31.3% <0%> (ø)`	⬆️
plugin/log/log.go	`76% <100%> (ø)`	⬆️
plugin/pkg/replacer/replacer.go	`42.85% <100%> (+4.58%)`	⬆️
plugin/etcd/handler.go	`89.28% <0%> (-3.58%)`	⬇️
plugin/route53/route53.go	`82.4% <0%> (-2.78%)`	⬇️
plugin/etcd/etcd.go	`74.07% <0%> (-2.47%)`	⬇️
core/dnsserver/listen_go111.go	`0% <0%> (ø)`	⬆️
plugin/loop/setup.go	`46.8% <0%> (+0.97%)`	⬆️
plugin/cache/cache.go	`78.09% <0%> (+1.09%)`	⬆️
... and 3 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update cfbfa5c...d0e3081. Read the comment docs.

fturib

See my comments about UTC information proposition.

glitch in one comment.

fturib · 2018-10-29T14:31:50Z

plugin/log/README.md

@@ -7,7 +7,7 @@
 ## Description

 By just using *log* you dump all queries (and parts for the reply) on standard output. Options exist
-to tweak the output a little.
+to tweak the output a little. The timezone is used is always UTC.


typo. "The timezone is always UTC"

fturib · 2018-10-29T14:53:16Z

coremain/run.go

@@ -62,7 +62,7 @@ func Run() {
 	}

 	log.SetOutput(os.Stdout)
-	log.SetFlags(log.LstdFlags)
+	log.SetFlags(log.Ldate | log.Ltime | log.LUTC)


Changing to UTC will surprise everyone, and the date does not say the TZ.
So maybe, while waiting we implement a complete date with TZ in our pkg/log, we can output an info here:

clog.Info("log output - all dates are UTC")

Result is:

API server listening at: 127.0.0.1:55958 2018/10/29 14:51:55 [INFO] log output - all dates are UTC .:1053 .:1054 2018/10/29 14:51:55 [INFO] CoreDNS-1.2.5 2018/10/29 14:51:55 [INFO] darwin/amd64, go1.10.2, CoreDNS-1.2.5 darwin/amd64, go1.10.2, 2018/10/29 14:51:55 [INFO] plugin/reload: Running configuration MD5 = 67fbea4124263c10c9c1aa0fb55a538f

miekg · 2018-10-29T20:08:33Z

[ Quoting <notifications@github.com> in "Re: [coredns/coredns] logging: unif..." ]

+to tweak the output a little. The timezone is used is always UTC. typo. "The timezone is always UTC"

done.

> @@ -62,7 +62,7 @@ func Run() { } log.SetOutput(os.Stdout) - log.SetFlags(log.LstdFlags) + log.SetFlags(log.Ldate | log.Ltime | log.LUTC) Changing to UTC will surprise everyone, and the date does not say the TZ.

it does not say the timezone because it's UTC, but I agree the std log package is pretty brain dead in this regard. Logging in local time with a time zone is even crazier. ~~~

2018/10/29 14:51:55 [INFO] log output - all dates are UTC

~~~ this doesn't add much to saying it in the README (i.e. both will not be read) /Miek

…

-- Miek Gieben

miekg · 2018-10-30T15:54:16Z

I'll update this to spit the date in w/ a timezone and RFC3339

fturib

LGTM

miekg · 2018-10-30T20:58:32Z

[ Quoting <notifications@github.com> in "Re: [coredns/coredns] logging: unif..." ]

fturib approved this pull request. LGTM

thanks we have to decide how backwards incompatible this is; can we just push it in the next or will this lead to any degraded experience.

fturib · 2018-10-30T21:18:35Z

I was thinking that if you enable Log plugin, then you already know you will have no perf ...
But maybe I am wrong.

I know Log is not enable on the default Corefile for Kubernetes

@rdrozhdzh, @drazhanski, @huynhmb359 - will you be impacted if the log is less performant ?

rdrozhdzh

LGTM
I don't think we'll get any significant performance penalty with this implementation. Earlier, golang log library did time formatting for us, now we do similar formatting ourselves.

plugin/pkg/log/log.go

jameshartig

LGTM

drazhanski · 2018-10-31T17:16:42Z

@drazhanski - will you be impacted if the log is less performant ?
I don't expect performance problems with this implementation. And usually we log only error/denial classes of responses, so it can't be so critical.

miekg · 2018-10-31T19:25:17Z

I'll make those changes and then merge.

…

On Wed, 31 Oct 2018, 17:27 Dzmitry Razhanski ***@***.*** wrote: @drazhanski <https://github.com/drazhanski> - will you be impacted if the log is less performant ? I don't expect performance problems with this implementation. And usually we log only error/denial classes of responses, so it can't be so critical. — You are receiving this because you modified the open/close state. Reply to this email directly, view it on GitHub <#2245 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAVkWxXi2jlUgqx1Bd9qKd7PCxXt_QG7ks5uqd17gaJpZM4X9dsE> .

Default to using pkg/log for all logging and use a fixed time prefix which is RFC3339Millli (doesn't exist in time, so we just extended RFC3339), i.e. Nano might be pushing it. Logs go from: 2018/10/30 19:14:55 [INFO] CoreDNS-1.2.5 2018/10/30 19:14:55 [INFO] linux/amd64, go1.11, to: 2018-10-30T19:10:07.547Z [INFO] CoreDNS-1.2.5 2018-10-30T19:10:07.547Z [INFO] linux/amd64, go1.11, Which includes the timezone - which oddly the std log package doesn't natively do. Signed-off-by: Miek Gieben <miek@miek.nl>

corbot bot requested a review from jameshartig October 27, 2018 14:38

miekg mentioned this pull request Oct 27, 2018

The date format in logs should be the same #2114

Closed

fturib reviewed Oct 29, 2018

View reviewed changes

miekg closed this Oct 30, 2018

miekg reopened this Oct 30, 2018

miekg force-pushed the logging branch from d4e1993 to b32392c Compare October 30, 2018 19:16

fturib approved these changes Oct 30, 2018

View reviewed changes

rdrozhdzh approved these changes Oct 31, 2018

View reviewed changes

plugin/pkg/log/log.go Outdated Show resolved Hide resolved

jameshartig approved these changes Oct 31, 2018

View reviewed changes

miekg force-pushed the logging branch from 863a49d to d0e3081 Compare October 31, 2018 21:20

miekg merged commit 2456416 into master Oct 31, 2018

corbot bot deleted the logging branch October 31, 2018 21:32

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

logging: unify pkg/log and plugin/log #2245

logging: unify pkg/log and plugin/log #2245

miekg commented Oct 27, 2018

corbot bot commented Oct 27, 2018

codecov-io commented Oct 27, 2018 •

edited

Loading

fturib left a comment

fturib Oct 29, 2018

fturib Oct 29, 2018

miekg commented Oct 29, 2018 via email

miekg commented Oct 30, 2018

fturib left a comment

miekg commented Oct 30, 2018 via email

fturib commented Oct 30, 2018

rdrozhdzh left a comment

jameshartig left a comment

drazhanski commented Oct 31, 2018

miekg commented Oct 31, 2018 via email

logging: unify pkg/log and plugin/log #2245

logging: unify pkg/log and plugin/log #2245

Conversation

miekg commented Oct 27, 2018

corbot bot commented Oct 27, 2018

codecov-io commented Oct 27, 2018 • edited Loading

Codecov Report

fturib left a comment

Choose a reason for hiding this comment

fturib Oct 29, 2018

Choose a reason for hiding this comment

fturib Oct 29, 2018

Choose a reason for hiding this comment

miekg commented Oct 29, 2018 via email

miekg commented Oct 30, 2018

fturib left a comment

Choose a reason for hiding this comment

miekg commented Oct 30, 2018 via email

fturib commented Oct 30, 2018

rdrozhdzh left a comment

Choose a reason for hiding this comment

jameshartig left a comment

Choose a reason for hiding this comment

drazhanski commented Oct 31, 2018

miekg commented Oct 31, 2018 via email

codecov-io commented Oct 27, 2018 •

edited

Loading