From 24564164445b1e2b5ad24cf559e95ae97f4eac6c Mon Sep 17 00:00:00 2001 From: Miek Gieben Date: Wed, 31 Oct 2018 21:32:23 +0000 Subject: [PATCH] logging: unify pkg/log and plugin/log (#2245) 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 --- coremain/run.go | 2 +- plugin/log/README.md | 14 ++++++++++---- plugin/log/log.go | 7 +++---- plugin/log/log_test.go | 15 +++++++++------ plugin/log/setup.go | 12 ------------ plugin/pkg/log/log.go | 27 ++++++++++++++++----------- plugin/pkg/replacer/replacer.go | 17 ++++++----------- 7 files changed, 45 insertions(+), 49 deletions(-) diff --git a/coremain/run.go b/coremain/run.go index 033f60077..63ac6f354 100644 --- a/coremain/run.go +++ b/coremain/run.go @@ -62,7 +62,7 @@ func Run() { } log.SetOutput(os.Stdout) - log.SetFlags(log.LstdFlags) + log.SetFlags(0) // Set to 0 because we're doing our own time, with timezone if version { showVersion() diff --git a/plugin/log/README.md b/plugin/log/README.md index 65cca19c8..8ecc39680 100644 --- a/plugin/log/README.md +++ b/plugin/log/README.md @@ -7,9 +7,10 @@ ## 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 date/time prefix on log lines is RFC3339 formatted with +milliseconds. -Note that for busy servers this will incur a performance hit. +Note that for busy servers logging will incur a performance hit. ## Syntax @@ -59,7 +60,6 @@ The following place holders are supported: * `{name}`: qname of the request * `{class}`: qclass of the request * `{proto}`: protocol used (tcp or udp) -* `{when}`: time of the query * `{remote}`: client's IP address, for IPv6 addresses these are enclosed in brackets: `[::1]` * `{size}`: request size in bytes * `{port}`: client's port @@ -76,9 +76,15 @@ The following place holders are supported: The default Common Log Format is: ~~~ txt -`{remote}:{port} - [{when}] {>id} "{type} {class} {name} {proto} {size} {>do} {>bufsize}" {rcode} {>rflags} {rsize} {duration}` +`{remote}:{port} - {>id} "{type} {class} {name} {proto} {size} {>do} {>bufsize}" {rcode} {>rflags} {rsize} {duration}` ~~~ +Each of these logs will be outputted with `log.Infof`, so a typical example looks like this: + +~~~ txt +2018-10-30T19:10:07.547Z [INFO] [::1]:50759 - 29008 "A IN example.org. udp 41 false 4096" NOERROR qr,rd,ra,ad 68 0.037990251s +~~~~ + ## Examples Log all requests to stdout diff --git a/plugin/log/log.go b/plugin/log/log.go index f52a70344..685c55191 100644 --- a/plugin/log/log.go +++ b/plugin/log/log.go @@ -3,12 +3,12 @@ package log import ( "context" - "log" "time" "github.com/coredns/coredns/plugin" "github.com/coredns/coredns/plugin/metrics/vars" "github.com/coredns/coredns/plugin/pkg/dnstest" + clog "github.com/coredns/coredns/plugin/pkg/log" "github.com/coredns/coredns/plugin/pkg/rcode" "github.com/coredns/coredns/plugin/pkg/replacer" "github.com/coredns/coredns/plugin/pkg/response" @@ -58,7 +58,7 @@ func (l Logger) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) // and we shouldn't have an empty rule.Class. if rule.Class[response.All] || rule.Class[class] { rep := replacer.New(r, rrw, CommonLogEmptyValue) - rule.Log.Println(rep.Replace(rule.Format)) + clog.Infof(rep.Replace(rule.Format)) } return rc, err @@ -75,12 +75,11 @@ type Rule struct { NameScope string Class map[response.Class]bool Format string - Log *log.Logger } const ( // CommonLogFormat is the common log format. - CommonLogFormat = `{remote}:{port} ` + CommonLogEmptyValue + ` [{when}] {>id} "{type} {class} {name} {proto} {size} {>do} {>bufsize}" {rcode} {>rflags} {rsize} {duration}` + CommonLogFormat = `{remote}:{port} ` + CommonLogEmptyValue + ` {>id} "{type} {class} {name} {proto} {size} {>do} {>bufsize}" {rcode} {>rflags} {rsize} {duration}` // CommonLogEmptyValue is the common empty log value. CommonLogEmptyValue = "-" // CombinedLogFormat is the combined log format. diff --git a/plugin/log/log_test.go b/plugin/log/log_test.go index d1ff8d36d..6d74f23ad 100644 --- a/plugin/log/log_test.go +++ b/plugin/log/log_test.go @@ -18,14 +18,15 @@ import ( func init() { clog.Discard() } func TestLoggedStatus(t *testing.T) { - var f bytes.Buffer rule := Rule{ NameScope: ".", Format: DefaultLogFormat, - Log: log.New(&f, "", 0), Class: map[response.Class]bool{response.All: true}, } + var f bytes.Buffer + log.SetOutput(&f) + logger := Logger{ Rules: []Rule{rule}, Next: test.ErrorHandler(), @@ -49,14 +50,15 @@ func TestLoggedStatus(t *testing.T) { } func TestLoggedClassDenial(t *testing.T) { - var f bytes.Buffer rule := Rule{ NameScope: ".", Format: DefaultLogFormat, - Log: log.New(&f, "", 0), Class: map[response.Class]bool{response.Denial: true}, } + var f bytes.Buffer + log.SetOutput(&f) + logger := Logger{ Rules: []Rule{rule}, Next: test.ErrorHandler(), @@ -77,14 +79,15 @@ func TestLoggedClassDenial(t *testing.T) { } func TestLoggedClassError(t *testing.T) { - var f bytes.Buffer rule := Rule{ NameScope: ".", Format: DefaultLogFormat, - Log: log.New(&f, "", 0), Class: map[response.Class]bool{response.Error: true}, } + var f bytes.Buffer + log.SetOutput(&f) + logger := Logger{ Rules: []Rule{rule}, Next: test.ErrorHandler(), diff --git a/plugin/log/setup.go b/plugin/log/setup.go index 1f9501d68..c3c1af4ca 100644 --- a/plugin/log/setup.go +++ b/plugin/log/setup.go @@ -1,9 +1,6 @@ package log import ( - "log" - "os" - "github.com/coredns/coredns/core/dnsserver" "github.com/coredns/coredns/plugin" "github.com/coredns/coredns/plugin/pkg/response" @@ -25,15 +22,6 @@ func setup(c *caddy.Controller) error { return plugin.Error("log", err) } - // Open the log files for writing when the server starts - c.OnStartup(func() error { - for i := 0; i < len(rules); i++ { - rules[i].Log = log.New(os.Stdout, "", 0) - } - - return nil - }) - dnsserver.GetConfig(c).AddPlugin(func(next plugin.Handler) plugin.Handler { return Logger{Next: next, Rules: rules, ErrorFunc: dnsserver.DefaultErrorFunc} }) diff --git a/plugin/pkg/log/log.go b/plugin/pkg/log/log.go index f05dce03a..2c8971e1d 100644 --- a/plugin/pkg/log/log.go +++ b/plugin/pkg/log/log.go @@ -1,11 +1,11 @@ // Package log implements a small wrapper around the std lib log package. -// It implements log levels by prefixing the logs with [INFO], [DEBUG], -// [WARNING] or [ERROR]. +// It implements log levels by prefixing the logs with the current time +// with in RFC3339Milli and [INFO], [DEBUG], [WARNING] or [ERROR]. // Debug logging is available and enabled if the *debug* plugin is used. // // log.Info("this is some logging"), will log on the Info level. // -// log.Debug("this is debug output"), will log in the Debug level. +// log.Debug("this is debug output"), will log in the Debug level, etc. package log import ( @@ -13,19 +13,24 @@ import ( "io/ioutil" golog "log" "os" + "time" ) // D controls whether we should output debug logs. If true, we do. var D bool +// RFC3339Milli doesn't exist, invent it here. +func clock() string { return time.Now().Format("2006-01-02T15:04:05.999Z07:00") } + // logf calls log.Printf prefixed with level. func logf(level, format string, v ...interface{}) { - s := level + fmt.Sprintf(format, v...) - golog.Print(s) + golog.Print(clock(), level, fmt.Sprintf(format, v...)) } // log calls log.Print prefixed with level. -func log(level string, v ...interface{}) { s := level + fmt.Sprint(v...); golog.Print(s) } +func log(level string, v ...interface{}) { + golog.Print(clock(), level, fmt.Sprint(v...)) +} // Debug is equivalent to log.Print(), but prefixed with "[DEBUG] ". It only outputs something // if D is true. @@ -75,9 +80,9 @@ func Fatalf(format string, v ...interface{}) { logf(fatal, format, v...); os.Exi func Discard() { golog.SetOutput(ioutil.Discard) } const ( - debug = "[DEBUG] " - err = "[ERROR] " - fatal = "[FATAL] " - info = "[INFO] " - warning = "[WARNING] " + debug = " [DEBUG] " + err = " [ERROR] " + fatal = " [FATAL] " + info = " [INFO] " + warning = " [WARNING] " ) diff --git a/plugin/pkg/replacer/replacer.go b/plugin/pkg/replacer/replacer.go index b9e1fcaa6..695e9e392 100644 --- a/plugin/pkg/replacer/replacer.go +++ b/plugin/pkg/replacer/replacer.go @@ -35,13 +35,11 @@ func New(r *dns.Msg, rr *dnstest.Recorder, emptyValue string) Replacer { req := request.Request{W: rr, Req: r} rep := replacer{ replacements: map[string]string{ - "{type}": req.Type(), - "{name}": req.Name(), - "{class}": req.Class(), - "{proto}": req.Proto(), - "{when}": func() string { - return time.Now().Format(timeFormat) - }(), + "{type}": req.Type(), + "{name}": req.Name(), + "{class}": req.Class(), + "{proto}": req.Proto(), + "{when}": "", // made a noop "{size}": strconv.Itoa(req.Len()), "{remote}": addrToRFC3986(req.IP()), "{port}": req.Port(), @@ -163,7 +161,4 @@ func addrToRFC3986(addr string) string { return addr } -const ( - timeFormat = "02/Jan/2006:15:04:05 -0700" - headerReplacer = "{>" -) +const headerReplacer = "{>"