diff --git a/README.md b/README.md index f0b6dc045..605ce0141 100644 --- a/README.md +++ b/README.md @@ -108,6 +108,32 @@ $ dig @127.0.0.1 google.com ## Examples +### JSON Logging + +Start CoreDNS with `-log-format=json` to emit operational logs as single-line JSON. +The default `-log-format=text` retains the existing text output. The format applies +to the whole process, including all server blocks, and persists across Corefile +reloads. Query logging still requires the `log` plugin. + +```sh +./coredns -conf Corefile -log-format=json +``` + +Records contain `time` (RFC3339 with fractional seconds), `level` (`DEBUG`, `INFO`, +`WARN`, `ERROR`, or `FATAL`), and `msg`. Named plugin loggers also include `plugin`. +Messages, including embedded newlines and DNS escapes, are JSON-encoded rather +than concatenated into JSON templates. Debug output still requires `debug`. +See the [log plugin](plugin/log/README.md#json-output) for typed query fields. + +The standard library's default logger (including Caddy's lifecycle messages) is +routed through the same backend at `INFO` level; its original message is retained +without guessing severity or fields from text. Independently configured third-party +loggers, direct stdout/stderr writes, and Go runtime diagnostics are not intercepted. +Command-line help, flag parsing errors, `-version`, and `-plugins` remain human-readable. +Normal startup, Corefile errors, and query/error plugin logs use the selected format. + +### Querying CoreDNS + When starting CoreDNS without any configuration, it loads the [*whoami*](https://coredns.io/plugins/whoami) and [*log*](https://coredns.io/plugins/log) plugins and starts listening on port 53 (override with `-dns.port`), it should show the following: diff --git a/core/dnsserver/onstartup.go b/core/dnsserver/onstartup.go index 6b84d6b8d..2400478e4 100644 --- a/core/dnsserver/onstartup.go +++ b/core/dnsserver/onstartup.go @@ -7,8 +7,17 @@ import ( "strings" "github.com/coredns/coredns/plugin/pkg/dnsutil" + "github.com/coredns/coredns/plugin/pkg/log" ) +func printStartup(out string) { + if log.IsJSON() { + log.Info(strings.TrimSuffix(out, "\n")) + return + } + fmt.Print(out) +} + // checkZoneSyntax() checks whether the given string match 1035 Preferred Syntax or not. // The root zone, and all reverse zones always return true even though they technically don't meet 1035 Preferred Syntax func checkZoneSyntax(zone string) bool { diff --git a/core/dnsserver/server.go b/core/dnsserver/server.go index 372001805..5a14f9b3d 100644 --- a/core/dnsserver/server.go +++ b/core/dnsserver/server.go @@ -43,7 +43,6 @@ package dnsserver import ( "context" - "fmt" "maps" "net" "runtime/debug" @@ -504,7 +503,7 @@ func (s *Server) OnStartupComplete() { out := startUpZones("", s.Addr, s.zones) if out != "" { - fmt.Print(out) + printStartup(out) } } diff --git a/core/dnsserver/server_grpc.go b/core/dnsserver/server_grpc.go index d23cc25cf..03102f380 100644 --- a/core/dnsserver/server_grpc.go +++ b/core/dnsserver/server_grpc.go @@ -156,7 +156,7 @@ func (s *ServergRPC) OnStartupComplete() { out := startUpZones(transport.GRPC+"://", s.Addr, s.zones) if out != "" { - fmt.Print(out) + printStartup(out) } } diff --git a/core/dnsserver/server_https.go b/core/dnsserver/server_https.go index 56e775540..414d0d22f 100644 --- a/core/dnsserver/server_https.go +++ b/core/dnsserver/server_https.go @@ -185,7 +185,7 @@ func (s *ServerHTTPS) OnStartupComplete() { out := startUpZones(transport.HTTPS+"://", s.Addr, s.zones) if out != "" { - fmt.Print(out) + printStartup(out) } } diff --git a/core/dnsserver/server_https3.go b/core/dnsserver/server_https3.go index 56c1bb862..a996c3bcc 100644 --- a/core/dnsserver/server_https3.go +++ b/core/dnsserver/server_https3.go @@ -203,7 +203,7 @@ func (s *ServerHTTPS3) OnStartupComplete() { } out := startUpZones(transport.HTTPS3+"://", s.Addr, s.zones) if out != "" { - fmt.Print(out) + printStartup(out) } } diff --git a/core/dnsserver/server_quic.go b/core/dnsserver/server_quic.go index 102ac83b6..e471a4c0e 100644 --- a/core/dnsserver/server_quic.go +++ b/core/dnsserver/server_quic.go @@ -315,7 +315,7 @@ func (s *ServerQUIC) OnStartupComplete() { out := startUpZones(transport.QUIC+"://", s.Addr, s.zones) if out != "" { - fmt.Print(out) + printStartup(out) } } diff --git a/core/dnsserver/server_tls.go b/core/dnsserver/server_tls.go index 3607f4aeb..c9b7342bc 100644 --- a/core/dnsserver/server_tls.go +++ b/core/dnsserver/server_tls.go @@ -3,7 +3,6 @@ package dnsserver import ( "context" "crypto/tls" - "fmt" "net" "time" @@ -100,6 +99,6 @@ func (s *ServerTLS) OnStartupComplete() { out := startUpZones(transport.TLS+"://", s.Addr, s.zones) if out != "" { - fmt.Print(out) + printStartup(out) } } diff --git a/coremain/run.go b/coremain/run.go index 57778c429..e7350f5d5 100644 --- a/coremain/run.go +++ b/coremain/run.go @@ -12,6 +12,7 @@ import ( "github.com/coredns/caddy" "github.com/coredns/coredns/core/dnsserver" + clog "github.com/coredns/coredns/plugin/pkg/log" "go.uber.org/automaxprocs/maxprocs" ) @@ -29,6 +30,7 @@ func init() { flag.StringVar(&caddy.PidFile, "pidfile", "", "Path to write pid file") flag.BoolVar(&version, "version", false, "Show version") flag.BoolVar(&dnsserver.Quiet, "quiet", false, "Quiet mode (no initialization output)") + flag.StringVar(&logFormat, "log-format", "text", "Log format (text or json)") caddy.RegisterCaddyfileLoader("flag", caddy.LoaderFunc(confLoader)) caddy.SetDefaultCaddyfileLoader("default", caddy.LoaderFunc(defaultLoader)) @@ -44,13 +46,20 @@ func init() { func Run() { caddy.TrapSignals() flag.Parse() + if logFormat != "text" { + if err := clog.Configure(logFormat, os.Stdout); err != nil { + mustLogFatal(err) + } + } if len(flag.Args()) > 0 { mustLogFatal(fmt.Errorf("extra command line arguments: %s", flag.Args())) } - log.SetOutput(os.Stdout) - log.SetFlags(LogFlags) + clog.SetOutput(os.Stdout) + if !clog.IsJSON() { + log.SetFlags(LogFlags) + } if version { showVersion() @@ -63,7 +72,7 @@ func Run() { _, err := maxprocs.Set(maxprocs.Logger(log.Printf)) if err != nil { - log.Println("[WARNING] Failed to set GOMAXPROCS:", err) + clog.Warningf("Failed to set GOMAXPROCS: %v", err) } // Get Corefile input @@ -79,7 +88,14 @@ func Run() { } if !dnsserver.Quiet { - showVersion() + if clog.IsJSON() { + clog.Info(strings.TrimSuffix(versionString()+releaseString(), "\n")) + if devBuild && gitShortStat != "" { + clog.Infof("%s\n%s", gitShortStat, gitFilesModified) + } + } else { + showVersion() + } } // Twiddle your thumbs @@ -94,7 +110,10 @@ func Run() { // log and exits. func mustLogFatal(args ...any) { if !caddy.IsUpgrade() { - log.SetOutput(os.Stderr) + clog.SetOutput(os.Stderr) + } + if clog.IsJSON() { + clog.Fatal(args...) } log.Fatal(args...) } @@ -176,9 +195,10 @@ func setVersion() { // Flags that control program flow or startup var ( - conf string - version bool - plugins bool + conf string + version bool + plugins bool + logFormat string // LogFlags are initially set to 0 for no extra output LogFlags int diff --git a/plugin/debug/pcap_test.go b/plugin/debug/pcap_test.go index 6b263c883..75209038d 100644 --- a/plugin/debug/pcap_test.go +++ b/plugin/debug/pcap_test.go @@ -21,7 +21,6 @@ func msg() *dns.Msg { } func TestNoDebug(t *testing.T) { - // Must come first, because set log.D.Set() which is impossible to undo. var f bytes.Buffer golog.SetOutput(&f) @@ -45,6 +44,7 @@ func ExampleHexdump() { } func TestHexdump(t *testing.T) { + t.Cleanup(log.D.Clear) var f bytes.Buffer golog.SetOutput(&f) log.D.Set() @@ -59,6 +59,7 @@ func TestHexdump(t *testing.T) { } func TestHexdumpf(t *testing.T) { + t.Cleanup(log.D.Clear) var f bytes.Buffer golog.SetOutput(&f) log.D.Set() diff --git a/plugin/log/README.md b/plugin/log/README.md index 5c3ebc511..2e3461a13 100644 --- a/plugin/log/README.md +++ b/plugin/log/README.md @@ -88,12 +88,51 @@ The default Common Log Format is: `{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: +In the default text mode, each of these logs is output with `log.Info`, so a typical example looks like this: ~~~ txt [INFO] [::1]:50759 - 29008 "A IN example.org. udp 41 false 4096" NOERROR qr,rd,ra,ad 68 0.037990251s ~~~ +## JSON Output + +Start CoreDNS with `-log-format=json` to select JSON output for the entire process. +This is a command-line flag, not a Corefile directive. `-log-format=text` is the default. +The `log` plugin's name and response-class filters work identically in both modes. + +Each query produces one JSON record with common fields `time`, `level`, `msg`, and +`plugin` (always `log` for query records), plus these typed fields: + +| Field | Type | Meaning | +| --- | --- | --- | +| `client_ip` | string | Client address, without brackets around IPv6 addresses | +| `client_port` | number | Client port | +| `qname` | string | Lowercase, fully qualified query name, in DNS presentation format | +| `qtype`, `qclass` | string | Query type and class, including numeric forms for unknown values | +| `protocol` | string | `udp` or `tcp`, as for `{proto}` | +| `id`, `opcode` | number | Query ID and opcode | +| `request_size` | number | Request size in bytes, as for `{size}` | +| `dnssec_ok` | boolean | Query's DNSSEC OK bit | +| `bufsize` | number | Effective response buffer size, as for `{>bufsize}` | +| `rcode` | string or null | Response RCODE, or null if no DNS response was recorded | +| `response_size` | number | Recorded response size in bytes, as for `{rsize}` | +| `duration_seconds` | number | Elapsed handling time in seconds | + +As in text mode, response sizes describe recorded, uncompressed messages, not +necessarily the bytes delivered to the client. Deferred errors (such as SERVFAIL) +use the response CoreDNS will generate after the plugin chain returns. A dropped +request has `rcode: null`; it is not logged as a successful response. Raw `Write` +calls contribute to the size but do not provide a decoded response RCODE. + +`FORMAT` still controls `msg`, including custom formats and metadata placeholders. +It does not replace the JSON schema or define new top-level fields. The DNS fields +come directly from the request and response, not from parsing `msg`. For example, +with `log . "{name} {rcode}"`: + +```json +{"time":"2026-09-15T08:00:00Z","level":"INFO","msg":"example.org. NOERROR","plugin":"log","client_ip":"127.0.0.1","client_port":40212,"qname":"example.org.","qtype":"A","qclass":"IN","protocol":"udp","id":42,"opcode":0,"request_size":29,"dnssec_ok":false,"bufsize":512,"rcode":"NOERROR","response_size":29,"duration_seconds":0.001} +``` + ## Additional metadata The log plugin adds the following metadata to allow for granular differentiation of NOERROR denial vs success messages. These are mapped from `plugin/pkg/response/classify.go` and `plugin/pkg/response/typify.go`. diff --git a/plugin/log/json.go b/plugin/log/json.go new file mode 100644 index 000000000..4916d20e9 --- /dev/null +++ b/plugin/log/json.go @@ -0,0 +1,44 @@ +package log + +import ( + "log/slog" + "strconv" + "time" + + "github.com/coredns/coredns/plugin/pkg/dnstest" + clog "github.com/coredns/coredns/plugin/pkg/log" + "github.com/coredns/coredns/request" + + "github.com/miekg/dns" +) + +func logJSON(msg string, state request.Request, rr *dnstest.Recorder) { + // A missing response is not NOERROR (for example an ACL drop). Deferred + // errors have already been synthesized by ServeDNS, just as in text mode. + rcode := slog.Any("rcode", nil) + if rr.Msg != nil { + rc := dns.RcodeToString[rr.Rcode] + if rc == "" { + rc = strconv.Itoa(rr.Rcode) + } + rcode = slog.String("rcode", rc) + } + port, _ := strconv.Atoi(state.Port()) + clog.InfoAttrs(msg, + slog.String("plugin", "log"), + slog.String("client_ip", state.IP()), + slog.Int("client_port", port), + slog.String("qname", state.Name()), + slog.String("qtype", state.Type()), + slog.String("qclass", state.Class()), + slog.String("protocol", state.Proto()), + slog.Int("id", int(state.Req.Id)), + slog.Int("opcode", state.Req.Opcode), + slog.Int("request_size", state.Len()), + slog.Bool("dnssec_ok", state.Do()), + slog.Int("bufsize", state.Size()), + rcode, + slog.Int("response_size", rr.Len), + slog.Float64("duration_seconds", time.Since(rr.Start).Seconds()), + ) +} diff --git a/plugin/log/json_test.go b/plugin/log/json_test.go new file mode 100644 index 000000000..2753bb135 --- /dev/null +++ b/plugin/log/json_test.go @@ -0,0 +1,205 @@ +package log + +import ( + "bytes" + "context" + "encoding/json" + "errors" + "io" + golog "log" + "strings" + "testing" + + "github.com/coredns/coredns/plugin" + "github.com/coredns/coredns/plugin/metadata" + "github.com/coredns/coredns/plugin/pkg/dnstest" + clog "github.com/coredns/coredns/plugin/pkg/log" + "github.com/coredns/coredns/plugin/pkg/replacer" + "github.com/coredns/coredns/plugin/pkg/response" + "github.com/coredns/coredns/plugin/test" + "github.com/coredns/coredns/request" + + "github.com/miekg/dns" +) + +func jsonQueryOutput(tb testing.TB, format string, w io.Writer) { + tb.Helper() + output, flags, prefix := golog.Writer(), golog.Flags(), golog.Prefix() + tb.Cleanup(func() { + if err := clog.Configure("text", output); err != nil { + tb.Error(err) + } + golog.SetFlags(flags) + golog.SetPrefix(prefix) + }) + if err := clog.Configure(format, w); err != nil { + tb.Fatal(err) + } +} + +func TestJSONQueryEscaping(t *testing.T) { + for _, name := range []string{"Example.ORG.", `a\.b.example.`, `a\001b.example.`, `a\"b.example.`, `a\\b.example.`} { + t.Run(name, func(t *testing.T) { + var out bytes.Buffer + jsonQueryOutput(t, "json", &out) + ctx := metadata.ContextWithMetadata(t.Context()) + value := "arbitrary \"metadata\"\nwith\t\\escapes" + metadata.SetValueFunc(ctx, "test/value", func() string { return value }) + r := new(dns.Msg) + r.SetQuestion(name, dns.TypeA) + r.SetEdns0(1232, true) + r.Id = 42 + wire, err := r.Pack() + if err != nil { + t.Fatal(err) + } + if err := r.Unpack(wire); err != nil { + t.Fatal(err) + } + state := request.Request{Req: r} + logger := Logger{ + Rules: []Rule{{NameScope: ".", Class: map[response.Class]struct{}{response.All: {}}, + Format: `{"name":"{name}","metadata":"{/test/value}"}`}}, + Next: test.NextHandler(dns.RcodeRefused, nil), + } + rec := dnstest.NewRecorder(&test.ResponseWriter{TCP: true, RemoteIP: "2001:db8::1"}) + rc, err := logger.ServeDNS(ctx, rec, r) + if rc != dns.RcodeRefused || err != nil || rec.Msg != nil { + t.Fatalf("logging changed deferred response: rc=%d, err=%v, msg=%v", rc, err, rec.Msg) + } + if strings.Count(out.String(), "\n") != 1 { + t.Fatalf("not one physical line: %q", out.String()) + } + var record map[string]any + if err := json.Unmarshal(out.Bytes(), &record); err != nil { + t.Fatalf("invalid JSON %q: %v", out.String(), err) + } + want := map[string]any{ + "plugin": "log", "level": "INFO", "qname": state.Name(), "qtype": "A", "qclass": "IN", + "client_ip": "2001:db8::1", "client_port": float64(40212), "protocol": "tcp", + "id": float64(42), "opcode": float64(0), "request_size": float64(r.Len()), + "dnssec_ok": true, "bufsize": float64(dns.MaxMsgSize), "rcode": "REFUSED", + "msg": `{"name":"` + state.Name() + `","metadata":"` + value + `"}`, + } + for field, value := range want { + if record[field] != value { + t.Errorf("%s = %v, want %v", field, record[field], value) + } + } + if d, ok := record["duration_seconds"].(float64); !ok || d < 0 { + t.Errorf("invalid duration: %v", record["duration_seconds"]) + } + response := new(dns.Msg) + response.SetRcode(r, dns.RcodeRefused) + if record["response_size"] != float64(response.Len()) { + t.Errorf("unexpected deferred response size: %v", record) + } + }) + } +} + +func TestJSONQueryResponses(t *testing.T) { + writeErr := errors.New("test write failure") + for _, tc := range []struct { + name string + rcode int + write bool + nodata bool + fail bool + class response.Class + logged bool + }{ + {"success", dns.RcodeSuccess, true, false, false, response.Success, true}, + {"nxdomain", dns.RcodeNameError, true, false, false, response.Denial, true}, + {"nodata", dns.RcodeSuccess, true, true, false, response.Denial, true}, + {"servfail", dns.RcodeServerFailure, false, false, false, response.Error, true}, + {"refused", dns.RcodeRefused, false, false, false, response.Error, true}, + {"drop", dns.RcodeSuccess, false, false, false, response.All, true}, + {"write-error", dns.RcodeSuccess, true, false, true, response.All, true}, + {"unknown-rcode", 4095, true, false, false, response.All, true}, + {"denial-filtered", dns.RcodeNameError, true, false, false, response.Success, false}, + {"error-filtered", dns.RcodeServerFailure, false, false, false, response.Denial, false}, + } { + t.Run(tc.name, func(t *testing.T) { + var out bytes.Buffer + jsonQueryOutput(t, "json", &out) + r := new(dns.Msg) + r.SetQuestion("example.org.", dns.TypeA) + logger := Logger{ + Rules: []Rule{{NameScope: "example.org.", Class: map[response.Class]struct{}{tc.class: {}}, Format: DefaultLogFormat}}, + Next: plugin.HandlerFunc(func(_ context.Context, w dns.ResponseWriter, r *dns.Msg) (int, error) { + if !tc.write { + return tc.rcode, nil + } + m := new(dns.Msg) + m.SetRcode(r, tc.rcode) + if tc.nodata { + m.Ns = []dns.RR{test.SOA("example.org. 60 IN SOA ns.example.org. hostmaster.example.org. 1 2 3 4 5")} + } + return tc.rcode, w.WriteMsg(m) + }), + } + w := &jsonFailWriter{err: nil} + if tc.fail { + w.err = writeErr + } + rc, err := logger.ServeDNS(t.Context(), w, r) + if rc != tc.rcode || !errors.Is(err, w.err) { + t.Fatalf("return changed: rc=%d err=%v", rc, err) + } + if !tc.logged { + if out.Len() != 0 { + t.Fatalf("class filter ignored: %s", &out) + } + return + } + var record map[string]any + if err := json.Unmarshal(out.Bytes(), &record); err != nil { + t.Fatal(err) + } + if tc.name == "drop" { + if rc, exists := record["rcode"]; !exists || rc != nil || record["response_size"] != float64(0) { + t.Errorf("missing response misrepresented: %v", record) + } + } else if tc.name == "unknown-rcode" { + if record["rcode"] != "4095" { + t.Errorf("unknown rcode lost: %v", record) + } + } else if record["rcode"] != dns.RcodeToString[tc.rcode] { + t.Errorf("wrong rcode: %v", record) + } + out.Reset() + r.SetQuestion("outside.example.net.", dns.TypeA) + logger.ServeDNS(t.Context(), w, r) + if out.Len() != 0 { + t.Fatalf("name filter ignored: %s", &out) + } + }) + } +} + +type jsonFailWriter struct { + test.ResponseWriter + err error +} + +func (w *jsonFailWriter) WriteMsg(_ *dns.Msg) error { return w.err } + +func BenchmarkQueryLogFormat(b *testing.B) { + for _, format := range []string{"text", "json"} { + b.Run(format, func(b *testing.B) { + jsonQueryOutput(b, format, io.Discard) + logger := Logger{ + Rules: []Rule{{NameScope: ".", Class: map[response.Class]struct{}{response.All: {}}, Format: DefaultLogFormat}}, + Next: test.NextHandler(dns.RcodeRefused, nil), repl: replacer.New(), + } + r := new(dns.Msg) + r.SetQuestion("example.org.", dns.TypeA) + w := &test.ResponseWriter{} + b.ReportAllocs() + for b.Loop() { + logger.ServeDNS(b.Context(), w, r) + } + }) + } +} diff --git a/plugin/log/log.go b/plugin/log/log.go index 2e68780f8..cf8dd9ec1 100644 --- a/plugin/log/log.go +++ b/plugin/log/log.go @@ -62,7 +62,11 @@ func (l Logger) ServeDNS(ctx context.Context, w dns.ResponseWriter, r *dns.Msg) } if ok || ok1 { logstr := l.repl.Replace(ctx, state, rrw, rule.Format) - clog.Info(logstr) + if clog.IsJSON() { + logJSON(logstr, state, rrw) + } else { + clog.Info(logstr) + } } return rc, err diff --git a/plugin/pkg/log/json.go b/plugin/pkg/log/json.go new file mode 100644 index 000000000..649f52c4a --- /dev/null +++ b/plugin/pkg/log/json.go @@ -0,0 +1,131 @@ +package log + +import ( + "context" + "fmt" + "io" + golog "log" + "log/slog" + "strings" + "sync" + "sync/atomic" +) + +var jsonBackend atomic.Pointer[jsonLogger] + +type jsonLogger struct { + logger *slog.Logger + output *logOutput + flags int + prefix string +} + +// Configure selects text (the default) or JSON logging and its destination. +// Call it at process startup, before starting servers. The format is process-wide +// and should not be changed by individual plugins or during a Corefile reload. +// JSON mode also routes the standard library's default logger through this +// backend, at INFO level, without interpreting message text as structured data. +func Configure(format string, output io.Writer) error { + if format != "text" && format != "json" { + return fmt.Errorf("unknown log format %q: expected text or json", format) + } + if output == nil { + return fmt.Errorf("log output must not be nil") + } + + flags, prefix := golog.Flags(), golog.Prefix() + if previous := jsonBackend.Load(); previous != nil { + flags, prefix = previous.flags, previous.prefix + } + if format == "text" { + jsonBackend.Store(nil) + golog.SetOutput(output) + golog.SetFlags(flags) + golog.SetPrefix(prefix) + return nil + } + + w := &logOutput{writer: output} + l := slog.New(slog.NewJSONHandler(w, &slog.HandlerOptions{ + Level: slog.LevelDebug, + ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr { + if a.Key == slog.LevelKey { + if level, ok := a.Value.Any().(slog.Level); ok && level == levelFatal { + return slog.String(slog.LevelKey, "FATAL") + } + } + return a + }, + })) + jsonBackend.Store(&jsonLogger{logger: l, output: w, flags: flags, prefix: prefix}) + golog.SetFlags(0) + golog.SetPrefix("") + golog.SetOutput(standardWriter{logger: l}) + return nil +} + +// IsJSON reports whether structured logging is enabled. +func IsJSON() bool { return jsonBackend.Load() != nil } + +// SetOutput changes the destination of both CoreDNS and standard-library logs. +// Use this instead of log.SetOutput when JSON logging is enabled. +func SetOutput(w io.Writer) { + if b := jsonBackend.Load(); b != nil { + b.output.mu.Lock() + b.output.writer = w + b.output.mu.Unlock() + return + } + golog.SetOutput(w) +} + +// InfoAttrs logs msg with typed attributes in JSON mode. In text mode it is +// equivalent to Info(msg). Like Info, it does not call named-plugin listeners. +func InfoAttrs(msg string, attrs ...slog.Attr) { + if b := jsonBackend.Load(); b != nil { + b.logger.LogAttrs(context.Background(), slog.LevelInfo, msg, attrs...) + return + } + Info(msg) +} + +func (b *jsonLogger) log(level, plugin, msg string) { + lvl := slog.LevelInfo + switch level { + case debug: + lvl = slog.LevelDebug + case warning: + lvl = slog.LevelWarn + case err: + lvl = slog.LevelError + case fatal: + lvl = levelFatal + } + if plugin != "" { + b.logger.LogAttrs(context.Background(), lvl, msg, slog.String("plugin", plugin)) + return + } + b.logger.LogAttrs(context.Background(), lvl, msg) +} + +const levelFatal = slog.Level(12) + +// The adapter writes directly to the shared handler, not back through golog. +// This preserves multiline messages as one JSON record without recursion. +type standardWriter struct{ logger *slog.Logger } + +func (w standardWriter) Write(p []byte) (int, error) { + w.logger.Info(strings.TrimSuffix(string(p), "\n")) + return len(p), nil +} + +type logOutput struct { + mu sync.Mutex + writer io.Writer +} + +func (w *logOutput) Write(p []byte) (int, error) { + w.mu.Lock() + defer w.mu.Unlock() + return w.writer.Write(p) +} diff --git a/plugin/pkg/log/json_test.go b/plugin/pkg/log/json_test.go new file mode 100644 index 000000000..9c37052aa --- /dev/null +++ b/plugin/pkg/log/json_test.go @@ -0,0 +1,286 @@ +package log + +import ( + "bytes" + "encoding/json" + "fmt" + "io" + golog "log" + "log/slog" + "os" + "os/exec" + "strings" + "sync" + "testing" + "time" +) + +func configureTestLog(tb testing.TB, format string, w io.Writer) { + tb.Helper() + output, flags, prefix, debug := golog.Writer(), golog.Flags(), golog.Prefix(), D.Value() + tb.Cleanup(func() { + if err := Configure("text", output); err != nil { + tb.Error(err) + } + golog.SetFlags(flags) + golog.SetPrefix(prefix) + if debug { + D.Set() + } else { + D.Clear() + } + }) + if err := Configure(format, w); err != nil { + tb.Fatal(err) + } +} + +func TestJSONLevels(t *testing.T) { + var out bytes.Buffer + configureTestLog(t, "json", &out) + D.Set() + p := NewWithPlugin("test\"\nplugin") + for _, tc := range []struct { + level string + plain func(...any) + args func(string, ...any) + named func(...any) + fmt func(string, ...any) + }{ + {"DEBUG", Debug, Debugf, p.Debug, p.Debugf}, + {"INFO", Info, Infof, p.Info, p.Infof}, + {"WARN", Warning, Warningf, p.Warning, p.Warningf}, + {"ERROR", Error, Errorf, p.Error, p.Errorf}, + } { + t.Run(tc.level, func(t *testing.T) { + msg := "quoted \"value\"\nnext\rline\t\\end" + tc.plain(msg) + tc.args("%s", msg) + tc.named(msg) + tc.fmt("%s", msg) + lines := strings.Split(strings.TrimSuffix(out.String(), "\n"), "\n") + if len(lines) != 4 { + t.Fatalf("expected four JSON lines, got %q", out.String()) + } + for i, line := range lines { + var record map[string]any + if err := json.Unmarshal([]byte(line), &record); err != nil { + t.Fatalf("invalid JSON: %s: %v", line, err) + } + if record["level"] != tc.level || record["msg"] != msg { + t.Errorf("unexpected record: %v", record) + } + stamp, ok := record["time"].(string) + if !ok { + t.Fatal("missing timestamp") + } + if _, err := time.Parse(time.RFC3339Nano, stamp); err != nil { + t.Error(err) + } + if i < 2 { + if _, ok := record["plugin"]; ok { + t.Errorf("global log has plugin: %v", record) + } + } else if record["plugin"] != p.name { + t.Errorf("plugin identity lost: %v", record) + } + } + out.Reset() + }) + } + D.Clear() + Debug("hidden") + Debugf("%s", "hidden") + p.Debug("hidden") + p.Debugf("%s", "hidden") + if out.Len() != 0 { + t.Fatalf("debug logs emitted while disabled: %s", &out) + } +} + +func TestJSONStandardLoggerAndOutput(t *testing.T) { + var out, redirected bytes.Buffer + configureTestLog(t, "json", &out) + golog.Print("first\nsecond") + InfoAttrs("query", slog.Int("size", 12), slog.Bool("do", false)) + dec := json.NewDecoder(&out) + for i := range 2 { + var record map[string]any + if err := dec.Decode(&record); err != nil { + t.Fatal(err) + } + if i == 0 && record["msg"] != "first\nsecond" { + t.Fatalf("standard logger message changed: %v", record) + } + if i == 1 && (record["size"] != float64(12) || record["do"] != false) { + t.Fatalf("attributes lost their types: %v", record) + } + } + SetOutput(&redirected) + golog.Print("redirected standard") + Info("redirected CoreDNS") + if strings.Count(redirected.String(), "\n") != 2 { + t.Fatalf("expected two redirected records, got %q", redirected.String()) + } + before := redirected.String() + Discard() + golog.Print("discarded standard") + Info("discarded CoreDNS") + if redirected.String() != before { + t.Fatal("Discard did not stop all output") + } +} + +func TestJSONListeners(t *testing.T) { + var out bytes.Buffer + configureTestLog(t, "json", &out) + listener := &jsonListener{mockListener: *NewMockListener("json-test")} + if err := RegisterListener(listener); err != nil { + t.Fatal(err) + } + t.Cleanup(func() { + if err := DeregisterListener(listener); err != nil { + t.Error(err) + } + }) + NewWithPlugin("example").Info("unchanged", 1) + InfoAttrs("query", slog.String("plugin", "log")) + if listener.calls != 1 || listener.plugin != "plugin/example: " || listener.msg != "unchanged1" { + t.Fatalf("listener contract changed: %+v", listener) + } + if strings.Count(out.String(), "\n") != 2 { + t.Fatalf("listener caused missing or duplicate output: %q", out.String()) + } +} + +type jsonListener struct { + mockListener + calls int + plugin string + msg string +} + +func (l *jsonListener) Info(plugin string, v ...any) { + l.calls++ + l.plugin, l.msg = plugin, fmt.Sprint(v...) +} + +func TestJSONConcurrent(t *testing.T) { + var out bytes.Buffer + configureTestLog(t, "json", &out) + var wg sync.WaitGroup + for range 16 { + wg.Go(func() { + for i := range 100 { + InfoAttrs("query", slog.Int("id", i)) + NewWithPlugin("concurrent").Errorf("error %d", i) + golog.Printf("legacy %d", i) + } + }) + } + wg.Wait() + lines := bytes.Split(bytes.TrimSuffix(out.Bytes(), []byte("\n")), []byte("\n")) + if len(lines) != 4800 { + t.Fatalf("expected 4800 records, got %d", len(lines)) + } + for _, line := range lines { + if !json.Valid(line) { + t.Fatalf("interleaved JSON record: %q", line) + } + } +} + +func TestConfigureTextCompatibility(t *testing.T) { + var out bytes.Buffer + configureTestLog(t, "text", &out) + golog.SetFlags(0) + golog.SetPrefix("prefix: ") + emit := func() { + Info("a", 1) + NewWithPlugin("test").Infof("value %d", 2) + InfoAttrs("attrs", slog.Int("size", 3)) + golog.Print("legacy") + } + want := "prefix: [INFO] a1\nprefix: [INFO] plugin/test: value 2\nprefix: [INFO] attrs\nprefix: legacy\n" + emit() + if out.String() != want { + t.Fatalf("text output changed: %q", out.String()) + } + if err := Configure("json", io.Discard); err != nil { + t.Fatal(err) + } + if err := Configure("text", &out); err != nil { + t.Fatal(err) + } + out.Reset() + emit() + if out.String() != want || IsJSON() { + t.Fatalf("text settings not restored: %q", out.String()) + } + if err := Configure("invalid", io.Discard); err == nil { + t.Fatal("invalid format accepted") + } + if err := Configure("json", nil); err == nil || IsJSON() { + t.Fatal("invalid configuration changed logging mode") + } +} + +func TestJSONFatal(t *testing.T) { + for _, mode := range []string{"global", "globalf", "plugin", "pluginf"} { + t.Run(mode, func(t *testing.T) { + bin, err := os.Executable() + if err != nil { + t.Fatal(err) + } + cmd := exec.Command(bin, "-test.run=^TestJSONFatalHelper$") + cmd.Env = append(os.Environ(), "COREDNS_TEST_JSON_FATAL="+mode, "GORACE=atexit_sleep_ms=0") + out, err := cmd.CombinedOutput() + if exit, ok := err.(*exec.ExitError); !ok || exit.ExitCode() != 1 { + t.Fatalf("expected exit 1, got %v: %s", err, out) + } + var record map[string]any + if err := json.Unmarshal(out, &record); err != nil { + t.Fatalf("invalid fatal log %q: %v", out, err) + } + if record["level"] != "FATAL" || record["msg"] != "fatal\nmessage" { + t.Fatalf("unexpected fatal record: %v", record) + } + if strings.HasPrefix(mode, "plugin") && record["plugin"] != "test" { + t.Fatalf("missing plugin: %v", record) + } + }) + } +} + +func TestJSONFatalHelper(t *testing.T) { + mode := os.Getenv("COREDNS_TEST_JSON_FATAL") + if mode == "" { + return + } + if err := Configure("json", os.Stdout); err != nil { + t.Fatal(err) + } + switch mode { + case "global": + Fatal("fatal\nmessage") + case "globalf": + Fatalf("%s", "fatal\nmessage") + case "plugin": + NewWithPlugin("test").Fatal("fatal\nmessage") + case "pluginf": + NewWithPlugin("test").Fatalf("%s", "fatal\nmessage") + } +} + +func BenchmarkLogFormat(b *testing.B) { + for _, format := range []string{"text", "json"} { + b.Run(format, func(b *testing.B) { + configureTestLog(b, format, io.Discard) + p := NewWithPlugin("test") + b.ReportAllocs() + for b.Loop() { + p.Infof("query %s returned %d", "example.org.", 0) + } + }) + } +} diff --git a/plugin/pkg/log/log.go b/plugin/pkg/log/log.go index 12f7b9861..ee027d2c1 100644 --- a/plugin/pkg/log/log.go +++ b/plugin/pkg/log/log.go @@ -1,7 +1,7 @@ // 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]. Debug logging is available and enabled if the *debug* plugin is -// used. +// used. Configure can opt into structured JSON output instead of text prefixes. // // log.Info("this is some logging"), will log on the Info level. // @@ -41,11 +41,19 @@ func (d *d) Value() bool { // logf calls log.Printf prefixed with level. func logf(level, format string, v ...any) { + if b := jsonBackend.Load(); b != nil { + b.log(level, "", fmt.Sprintf(format, v...)) + return + } golog.Print(level, fmt.Sprintf(format, v...)) } // log calls log.Print prefixed with level. func log(level string, v ...any) { + if b := jsonBackend.Load(); b != nil { + b.log(level, "", fmt.Sprint(v...)) + return + } golog.Print(level, fmt.Sprint(v...)) } @@ -94,7 +102,7 @@ func Fatal(v ...any) { log(fatal, v...); os.Exit(1) } func Fatalf(format string, v ...any) { logf(fatal, format, v...); os.Exit(1) } // Discard sets the log output to /dev/null. -func Discard() { golog.SetOutput(io.Discard) } +func Discard() { SetOutput(io.Discard) } const ( debug = "[DEBUG] " diff --git a/plugin/pkg/log/log_test.go b/plugin/pkg/log/log_test.go index 32c1d39ad..5f8b0870e 100644 --- a/plugin/pkg/log/log_test.go +++ b/plugin/pkg/log/log_test.go @@ -33,6 +33,7 @@ func TestDebug(t *testing.T) { } func TestDebugx(t *testing.T) { + t.Cleanup(D.Clear) var f bytes.Buffer golog.SetOutput(&f) diff --git a/plugin/pkg/log/plugin.go b/plugin/pkg/log/plugin.go index 945d505a0..affb0514b 100644 --- a/plugin/pkg/log/plugin.go +++ b/plugin/pkg/log/plugin.go @@ -8,17 +8,26 @@ import ( // P is a logger that includes the plugin doing the logging. type P struct { plugin string + name string } // NewWithPlugin returns a logger that includes "plugin/name: " in the log message. // I.e [INFO] plugin/: message. -func NewWithPlugin(name string) P { return P{"plugin/" + name + ": "} } +func NewWithPlugin(name string) P { return P{plugin: "plugin/" + name + ": ", name: name} } func (p P) logf(level, format string, v ...any) { + if b := jsonBackend.Load(); b != nil { + b.log(level, p.name, fmt.Sprintf(format, v...)) + return + } log(level, p.plugin, fmt.Sprintf(format, v...)) } func (p P) log(level string, v ...any) { + if b := jsonBackend.Load(); b != nil { + b.log(level, p.name, fmt.Sprint(v...)) + return + } log(level+p.plugin, v...) } diff --git a/test/json_log_test.go b/test/json_log_test.go new file mode 100644 index 000000000..a4698244f --- /dev/null +++ b/test/json_log_test.go @@ -0,0 +1,261 @@ +package test + +import ( + "bytes" + "context" + "encoding/json" + "fmt" + "os" + "os/exec" + "runtime" + "strings" + "sync" + "testing" + "time" + + "github.com/coredns/caddy" + "github.com/coredns/coredns/coremain" + clog "github.com/coredns/coredns/plugin/pkg/log" + + "github.com/miekg/dns" +) + +func TestJSONLoggingProcess(t *testing.T) { + for _, tc := range []struct { + name string + args []string + config string + serve bool + fatal bool + json bool + }{ + {"serve", []string{"-log-format=json", "-conf=stdin"}, jsonLogCorefile, true, false, true}, + {"quiet", []string{"-log-format=json", "-quiet", "-conf=stdin"}, jsonLogCorefile, true, false, true}, + {"signal-shutdown", []string{"-log-format=json", "-conf=stdin"}, jsonLogCorefile, true, false, true}, + {"bad-corefile", []string{"-log-format=json", "-conf=stdin"}, ".:0 {\n invalid-plugin\n}", false, true, true}, + {"missing-corefile", []string{"-log-format=json", "-conf=does-not-exist/Corefile"}, "", false, true, true}, + {"extra-args", []string{"-log-format=json", "unexpected"}, "", false, true, true}, + {"invalid-format", []string{"-log-format=invalid"}, "", false, true, false}, + {"version", []string{"-log-format=json", "-version"}, "", false, false, false}, + {"plugins", []string{"-log-format=json", "-plugins"}, "", false, false, false}, + {"text-default", []string{"-conf=stdin"}, jsonLogCorefile, true, false, false}, + } { + t.Run(tc.name, func(t *testing.T) { + if tc.name == "signal-shutdown" && runtime.GOOS == "windows" { + t.Skip("Windows does not support sending os.Interrupt to a process") + } + bin, err := os.Executable() + if err != nil { + t.Fatal(err) + } + args, err := json.Marshal(tc.args) + if err != nil { + t.Fatal(err) + } + ctx, cancel := context.WithTimeout(t.Context(), 30*time.Second) + defer cancel() + cmd := exec.CommandContext(ctx, bin, "-test.run=^TestJSONLoggingProcessHelper$") + cmd.Env = append(os.Environ(), "COREDNS_TEST_LOG_ARGS="+string(args), + fmt.Sprintf("COREDNS_TEST_LOG_SERVE=%t", tc.serve), + fmt.Sprintf("COREDNS_TEST_LOG_SIGNAL=%t", tc.name == "signal-shutdown"), "GORACE=atexit_sleep_ms=0") + cmd.Stdin = strings.NewReader(tc.config) + var stdout, stderr bytes.Buffer + cmd.Stdout, cmd.Stderr = &stdout, &stderr + err = cmd.Run() + if tc.fatal { + if exit, ok := err.(*exec.ExitError); !ok || exit.ExitCode() != 1 { + t.Fatalf("expected exit 1, got %v\nstdout: %s\nstderr: %s", err, &stdout, &stderr) + } + } else if err != nil { + t.Fatalf("process failed: %v\nstdout: %s\nstderr: %s", err, &stdout, &stderr) + } + if !tc.json { + if tc.serve && !strings.Contains(stdout.String(), "[INFO]") { + t.Fatalf("default text logging changed: %s", &stdout) + } + if stdout.Len()+stderr.Len() == 0 || json.Valid(append(stdout.Bytes(), stderr.Bytes()...)) { + t.Fatal("expected human-readable output") + } + return + } + queries, fatal, startup, afterReload := 0, 0, 0, 0 + shutdown := false + for stream, output := range map[string]*bytes.Buffer{"stdout": &stdout, "stderr": &stderr} { + for line := range bytes.SplitSeq(bytes.TrimSpace(output.Bytes()), []byte("\n")) { + if len(line) == 0 { + continue + } + var record map[string]any + if err := json.Unmarshal(line, &record); err != nil { + t.Fatalf("non-JSON %s: %q: %v", stream, line, err) + } + if record["time"] == nil || record["level"] == nil || record["msg"] == nil { + t.Fatalf("missing common fields: %v", record) + } + if record["level"] == "FATAL" { + fatal++ + if stream != "stderr" { + t.Error("startup fatal log must go to stderr") + } + } + msg, _ := record["msg"].(string) + shutdown = shutdown || strings.Contains(msg, "SIGINT: Shutting down") + if strings.Contains(msg, "CoreDNS-") { + startup++ + } + if tc.name == "quiet" && strings.Contains(msg, ":0 on 127.0.0.1") { + t.Error("quiet mode emitted listener startup output") + } + if record["plugin"] == "log" { + queries++ + if record["rcode"] != "NOERROR" || record["client_ip"] != "127.0.0.1" { + t.Errorf("wrong query result: %v", record) + } + qname := record["qname"].(string) + if !strings.Contains(msg, qname) { + t.Errorf("custom format lost: %v", record) + } + if strings.HasSuffix(qname, ".example.org.") && !strings.Contains(msg, "-special ") { + t.Errorf("server block's custom format lost: %v", record) + } + if strings.HasPrefix(msg, "after-") { + afterReload++ + } + } + } + } + if tc.fatal && fatal != 1 { + t.Errorf("expected one fatal record, got %d", fatal) + } + if tc.serve { + wantQueries := 4 + if runtime.GOOS != "windows" && tc.name != "signal-shutdown" { + wantQueries = 12 + } + if queries != wantQueries { + t.Errorf("expected %d query records, got %d", wantQueries, queries) + } + if runtime.GOOS != "windows" && tc.name != "signal-shutdown" && afterReload != 4 { + t.Errorf("expected four records with the reloaded FORMAT, got %d", afterReload) + } + if tc.name == "quiet" && startup != 0 || tc.name == "serve" && startup != 1 { + t.Errorf("unexpected startup version count: %d", startup) + } + if tc.name == "signal-shutdown" && !shutdown { + t.Error("missing JSON shutdown record") + } + } + }) + } +} + +func TestJSONLoggingProcessHelper(t *testing.T) { + encoded := os.Getenv("COREDNS_TEST_LOG_ARGS") + if encoded == "" { + return + } + var args []string + if err := json.Unmarshal([]byte(encoded), &args); err != nil { + t.Fatal(err) + } + os.Args = append([]string{os.Args[0]}, args...) + done := make(chan error, 1) + if os.Getenv("COREDNS_TEST_LOG_SERVE") == "true" { + var once sync.Once + caddy.RegisterEventHook("json-log-test", func(event caddy.EventName, value any) error { + if event == caddy.InstanceStartupEvent { + once.Do(func() { + go func() { + inst := value.(*caddy.Instance) + if os.Getenv("COREDNS_TEST_LOG_SIGNAL") == "true" { + if err := interruptLogServer(inst); err != nil { + inst.Stop() + inst.ShutdownCallbacks() + done <- err + } + // Let Caddy's signal handler finish shutdown and exit. + return + } + done <- exerciseLogServer(inst) + }() + }) + } + return nil + }) + } + coremain.Run() + if err := <-done; err != nil { + t.Fatal(err) + } + // Avoid the test runner's own PASS line in the server's output stream. + os.Exit(0) +} + +func interruptLogServer(inst *caddy.Instance) error { + if err := queryLogServer(inst); err != nil { + return err + } + p, err := os.FindProcess(os.Getpid()) + if err != nil { + return err + } + defer p.Release() + return p.Signal(os.Interrupt) +} + +func exerciseLogServer(inst *caddy.Instance) error { + defer func() { + inst.Stop() + inst.ShutdownCallbacks() + }() + if err := queryLogServer(inst); err != nil { + return err + } + // Windows cannot inherit Caddy's listener file descriptors on restart. + if runtime.GOOS == "windows" { + return nil + } + if _, err := inst.Restart(NewInput(".:0 {\n invalid-plugin\n}")); err == nil { + return fmt.Errorf("invalid Corefile was accepted on reload") + } + if err := queryLogServer(inst); err != nil { + return err + } + newInst, err := inst.Restart(NewInput(strings.ReplaceAll(jsonLogCorefile, "before", "after"))) + if err != nil { + return err + } + inst = newInst + return queryLogServer(inst) +} + +func queryLogServer(inst *caddy.Instance) error { + udp, tcp := CoreDNSServerPorts(inst, 0) + for protocol, addr := range map[string]string{"udp": udp, "tcp": tcp} { + for _, name := range []string{`a\.b.example.org.`, `a\001b.example.net.`} { + query := new(dns.Msg) + query.SetQuestion(name, dns.TypeA) + client := &dns.Client{Net: protocol, Timeout: 2 * time.Second} + reply, _, err := client.Exchange(query, addr) + if err != nil { + return fmt.Errorf("%s %s: %w", protocol, name, err) + } + if reply.Rcode != dns.RcodeSuccess || len(reply.Extra) != 2 { + return fmt.Errorf("unexpected %s response: %v", protocol, reply) + } + } + } + clog.NewWithPlugin("json-test").Error("multiline error\nwith a stack trace") + return nil +} + +const jsonLogCorefile = `.:0 { + bind 127.0.0.1 + log . "before-default {name}" + whoami +} +example.org.:0 { + bind 127.0.0.1 + log . "before-special {name}" + whoami +}`