From 70953e873a559553e97c985a13db897ab9f573ff Mon Sep 17 00:00:00 2001 From: Francis Lavoie Date: Tue, 16 Apr 2024 18:26:18 -0400 Subject: [PATCH] caddyhttp: Support multiple logger names per host (#6088) * caddyhttp: Support multiple logger names per host * Lint * Add adapt test * Implement "string or array" parsing, keep original `logger_names` * Rewrite adapter test to be more representative of the usecase --- caddyconfig/httpcaddyfile/httptype.go | 12 +- .../import_args_snippet.caddyfiletest | 8 +- .../log_except_catchall_blocks.caddyfiletest | 4 +- .../log_multi_logger_name.caddyfiletest | 117 ++++++++++++++++++ .../log_override_hostname.caddyfiletest | 16 ++- ...og_override_name_multiaccess.caddyfiletest | 4 +- ...rride_name_multiaccess_debug.caddyfiletest | 4 +- .../log_skip_hosts.caddyfiletest | 4 +- modules/caddyhttp/logging.go | 93 ++++++++++---- modules/caddyhttp/server.go | 49 +++++--- 10 files changed, 249 insertions(+), 62 deletions(-) create mode 100644 caddytest/integration/caddyfile_adapt/log_multi_logger_name.caddyfiletest diff --git a/caddyconfig/httpcaddyfile/httptype.go b/caddyconfig/httpcaddyfile/httptype.go index 99411d1c..ab101293 100644 --- a/caddyconfig/httpcaddyfile/httptype.go +++ b/caddyconfig/httpcaddyfile/httptype.go @@ -805,22 +805,22 @@ func (st *ServerType) serversFromPairings( // if the logger overrides the hostnames, map that to the logger name for _, h := range ncl.hostnames { if srv.Logs.LoggerNames == nil { - srv.Logs.LoggerNames = make(map[string]string) + srv.Logs.LoggerNames = make(map[string]caddyhttp.StringArray) } - srv.Logs.LoggerNames[h] = ncl.name + srv.Logs.LoggerNames[h] = append(srv.Logs.LoggerNames[h], ncl.name) } } else { // otherwise, map each host to the logger name for _, h := range sblockLogHosts { - if srv.Logs.LoggerNames == nil { - srv.Logs.LoggerNames = make(map[string]string) - } // strip the port from the host, if any host, _, err := net.SplitHostPort(h) if err != nil { host = h } - srv.Logs.LoggerNames[host] = ncl.name + if srv.Logs.LoggerNames == nil { + srv.Logs.LoggerNames = make(map[string]caddyhttp.StringArray) + } + srv.Logs.LoggerNames[host] = append(srv.Logs.LoggerNames[host], ncl.name) } } } diff --git a/caddytest/integration/caddyfile_adapt/import_args_snippet.caddyfiletest b/caddytest/integration/caddyfile_adapt/import_args_snippet.caddyfiletest index 10d9f4cf..9d5c2535 100644 --- a/caddytest/integration/caddyfile_adapt/import_args_snippet.caddyfiletest +++ b/caddytest/integration/caddyfile_adapt/import_args_snippet.caddyfiletest @@ -72,8 +72,12 @@ b.example.com { ], "logs": { "logger_names": { - "a.example.com": "log0", - "b.example.com": "log1" + "a.example.com": [ + "log0" + ], + "b.example.com": [ + "log1" + ] } } } diff --git a/caddytest/integration/caddyfile_adapt/log_except_catchall_blocks.caddyfiletest b/caddytest/integration/caddyfile_adapt/log_except_catchall_blocks.caddyfiletest index e1362f8f..b2a7f2af 100644 --- a/caddytest/integration/caddyfile_adapt/log_except_catchall_blocks.caddyfiletest +++ b/caddytest/integration/caddyfile_adapt/log_except_catchall_blocks.caddyfiletest @@ -99,7 +99,9 @@ http://localhost:2020 { }, "logs": { "logger_names": { - "localhost": "" + "localhost": [ + "" + ] }, "skip_unmapped_hosts": true } diff --git a/caddytest/integration/caddyfile_adapt/log_multi_logger_name.caddyfiletest b/caddytest/integration/caddyfile_adapt/log_multi_logger_name.caddyfiletest new file mode 100644 index 00000000..be9ec188 --- /dev/null +++ b/caddytest/integration/caddyfile_adapt/log_multi_logger_name.caddyfiletest @@ -0,0 +1,117 @@ +(log-both) { + log {args[0]}-json { + hostnames {args[0]} + output file /var/log/{args[0]}.log + format json + } + log {args[0]}-console { + hostnames {args[0]} + output file /var/log/{args[0]}.json + format console + } +} + +*.example.com { + # Subdomains log to multiple files at once, with + # different output files and formats. + import log-both foo.example.com + import log-both bar.example.com +} +---------- +{ + "logging": { + "logs": { + "bar.example.com-console": { + "writer": { + "filename": "/var/log/bar.example.com.json", + "output": "file" + }, + "encoder": { + "format": "console" + }, + "include": [ + "http.log.access.bar.example.com-console" + ] + }, + "bar.example.com-json": { + "writer": { + "filename": "/var/log/bar.example.com.log", + "output": "file" + }, + "encoder": { + "format": "json" + }, + "include": [ + "http.log.access.bar.example.com-json" + ] + }, + "default": { + "exclude": [ + "http.log.access.bar.example.com-console", + "http.log.access.bar.example.com-json", + "http.log.access.foo.example.com-console", + "http.log.access.foo.example.com-json" + ] + }, + "foo.example.com-console": { + "writer": { + "filename": "/var/log/foo.example.com.json", + "output": "file" + }, + "encoder": { + "format": "console" + }, + "include": [ + "http.log.access.foo.example.com-console" + ] + }, + "foo.example.com-json": { + "writer": { + "filename": "/var/log/foo.example.com.log", + "output": "file" + }, + "encoder": { + "format": "json" + }, + "include": [ + "http.log.access.foo.example.com-json" + ] + } + } + }, + "apps": { + "http": { + "servers": { + "srv0": { + "listen": [ + ":443" + ], + "routes": [ + { + "match": [ + { + "host": [ + "*.example.com" + ] + } + ], + "terminal": true + } + ], + "logs": { + "logger_names": { + "bar.example.com": [ + "bar.example.com-json", + "bar.example.com-console" + ], + "foo.example.com": [ + "foo.example.com-json", + "foo.example.com-console" + ] + } + } + } + } + } + } +} \ No newline at end of file diff --git a/caddytest/integration/caddyfile_adapt/log_override_hostname.caddyfiletest b/caddytest/integration/caddyfile_adapt/log_override_hostname.caddyfiletest index c36ba23f..b9213e65 100644 --- a/caddytest/integration/caddyfile_adapt/log_override_hostname.caddyfiletest +++ b/caddytest/integration/caddyfile_adapt/log_override_hostname.caddyfiletest @@ -75,9 +75,15 @@ example.com:8443 { ], "logs": { "logger_names": { - "bar.example.com": "log0", - "baz.example.com": "log1", - "foo.example.com": "log0" + "bar.example.com": [ + "log0" + ], + "baz.example.com": [ + "log1" + ], + "foo.example.com": [ + "log0" + ] } } }, @@ -99,7 +105,9 @@ example.com:8443 { ], "logs": { "logger_names": { - "example.com": "log2" + "example.com": [ + "log2" + ] } } } diff --git a/caddytest/integration/caddyfile_adapt/log_override_name_multiaccess.caddyfiletest b/caddytest/integration/caddyfile_adapt/log_override_name_multiaccess.caddyfiletest index d48857a2..2708503e 100644 --- a/caddytest/integration/caddyfile_adapt/log_override_name_multiaccess.caddyfiletest +++ b/caddytest/integration/caddyfile_adapt/log_override_name_multiaccess.caddyfiletest @@ -76,7 +76,9 @@ http://localhost:8881 { }, "logs": { "logger_names": { - "localhost": "foo" + "localhost": [ + "foo" + ] } } } diff --git a/caddytest/integration/caddyfile_adapt/log_override_name_multiaccess_debug.caddyfiletest b/caddytest/integration/caddyfile_adapt/log_override_name_multiaccess_debug.caddyfiletest index d024dc38..7ea65978 100644 --- a/caddytest/integration/caddyfile_adapt/log_override_name_multiaccess_debug.caddyfiletest +++ b/caddytest/integration/caddyfile_adapt/log_override_name_multiaccess_debug.caddyfiletest @@ -81,7 +81,9 @@ http://localhost:8881 { }, "logs": { "logger_names": { - "localhost": "foo" + "localhost": [ + "foo" + ] } } } diff --git a/caddytest/integration/caddyfile_adapt/log_skip_hosts.caddyfiletest b/caddytest/integration/caddyfile_adapt/log_skip_hosts.caddyfiletest index 8fdd5715..c10610c2 100644 --- a/caddytest/integration/caddyfile_adapt/log_skip_hosts.caddyfiletest +++ b/caddytest/integration/caddyfile_adapt/log_skip_hosts.caddyfiletest @@ -63,7 +63,9 @@ example.com { ], "logs": { "logger_names": { - "one.example.com": "" + "one.example.com": [ + "" + ] }, "skip_hosts": [ "example.com", diff --git a/modules/caddyhttp/logging.go b/modules/caddyhttp/logging.go index 81b2830f..313f12e1 100644 --- a/modules/caddyhttp/logging.go +++ b/modules/caddyhttp/logging.go @@ -15,6 +15,7 @@ package caddyhttp import ( + "encoding/json" "errors" "net" "net/http" @@ -32,14 +33,17 @@ import ( // customized per-request-host. type ServerLogConfig struct { // The default logger name for all logs emitted by this server for - // hostnames that are not in the LoggerNames (logger_names) map. + // hostnames that are not in the logger_names map. DefaultLoggerName string `json:"default_logger_name,omitempty"` - // LoggerNames maps request hostnames to a custom logger name. - // For example, a mapping of "example.com" to "example" would - // cause access logs from requests with a Host of example.com - // to be emitted by a logger named "http.log.access.example". - LoggerNames map[string]string `json:"logger_names,omitempty"` + // LoggerNames maps request hostnames to one or more custom logger + // names. For example, a mapping of "example.com" to "example" would + // cause access logs from requests with a Host of example.com to be + // emitted by a logger named "http.log.access.example". If there are + // multiple logger names, then the log will be emitted to all of them. + // For backwards compatibility, if the value is a string, it is treated + // as a single-element array. + LoggerNames map[string]StringArray `json:"logger_names,omitempty"` // By default, all requests to this server will be logged if // access logging is enabled. This field lists the request @@ -47,7 +51,7 @@ type ServerLogConfig struct { SkipHosts []string `json:"skip_hosts,omitempty"` // If true, requests to any host not appearing in the - // LoggerNames (logger_names) map will not be logged. + // logger_names map will not be logged. SkipUnmappedHosts bool `json:"skip_unmapped_hosts,omitempty"` // If true, credentials that are otherwise omitted, will be logged. @@ -57,33 +61,39 @@ type ServerLogConfig struct { ShouldLogCredentials bool `json:"should_log_credentials,omitempty"` } -// wrapLogger wraps logger in a logger named according to user preferences for the given host. -func (slc ServerLogConfig) wrapLogger(logger *zap.Logger, host string) *zap.Logger { - if loggerName := slc.getLoggerName(host); loggerName != "" { - return logger.Named(loggerName) +// wrapLogger wraps logger in one or more logger named +// according to user preferences for the given host. +func (slc ServerLogConfig) wrapLogger(logger *zap.Logger, host string) []*zap.Logger { + hosts := slc.getLoggerHosts(host) + loggers := make([]*zap.Logger, 0, len(hosts)) + for _, loggerName := range hosts { + if loggerName == "" { + continue + } + loggers = append(loggers, logger.Named(loggerName)) } - return logger + return loggers } -func (slc ServerLogConfig) getLoggerName(host string) string { - tryHost := func(key string) (string, bool) { +func (slc ServerLogConfig) getLoggerHosts(host string) []string { + tryHost := func(key string) ([]string, bool) { // first try exact match - if loggerName, ok := slc.LoggerNames[key]; ok { - return loggerName, ok + if hosts, ok := slc.LoggerNames[key]; ok { + return hosts, ok } // strip port and try again (i.e. Host header of "example.com:1234" should // match "example.com" if there is no "example.com:1234" in the map) hostOnly, _, err := net.SplitHostPort(key) if err != nil { - return "", false + return []string{}, false } - loggerName, ok := slc.LoggerNames[hostOnly] - return loggerName, ok + hosts, ok := slc.LoggerNames[hostOnly] + return hosts, ok } // try the exact hostname first - if loggerName, ok := tryHost(host); ok { - return loggerName + if hosts, ok := tryHost(host); ok { + return hosts } // try matching wildcard domains if other non-specific loggers exist @@ -94,28 +104,59 @@ func (slc ServerLogConfig) getLoggerName(host string) string { } labels[i] = "*" wildcardHost := strings.Join(labels, ".") - if loggerName, ok := tryHost(wildcardHost); ok { - return loggerName + if hosts, ok := tryHost(wildcardHost); ok { + return hosts } } - return slc.DefaultLoggerName + return []string{slc.DefaultLoggerName} } func (slc *ServerLogConfig) clone() *ServerLogConfig { clone := &ServerLogConfig{ DefaultLoggerName: slc.DefaultLoggerName, - LoggerNames: make(map[string]string), + LoggerNames: make(map[string]StringArray), SkipHosts: append([]string{}, slc.SkipHosts...), SkipUnmappedHosts: slc.SkipUnmappedHosts, ShouldLogCredentials: slc.ShouldLogCredentials, } for k, v := range slc.LoggerNames { - clone.LoggerNames[k] = v + clone.LoggerNames[k] = append([]string{}, v...) } return clone } +// StringArray is a slices of strings, but also accepts +// a single string as a value when JSON unmarshaling, +// converting it to a slice of one string. +type StringArray []string + +// UnmarshalJSON satisfies json.Unmarshaler. +func (sa *StringArray) UnmarshalJSON(b []byte) error { + var jsonObj any + err := json.Unmarshal(b, &jsonObj) + if err != nil { + return err + } + switch obj := jsonObj.(type) { + case string: + *sa = StringArray([]string{obj}) + return nil + case []any: + s := make([]string, 0, len(obj)) + for _, v := range obj { + value, ok := v.(string) + if !ok { + return errors.New("unsupported type") + } + s = append(s, value) + } + *sa = StringArray(s) + return nil + } + return errors.New("unsupported type") +} + // errLogValues inspects err and returns the status code // to use, the error log message, and any extra fields. // If err is a HandlerError, the returned values will diff --git a/modules/caddyhttp/server.go b/modules/caddyhttp/server.go index c7e5a5f6..0e88ef26 100644 --- a/modules/caddyhttp/server.go +++ b/modules/caddyhttp/server.go @@ -361,11 +361,11 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { cloneURL(origReq.URL, r.URL) // prepare the error log - logger := errLog + errLog = errLog.With(zap.Duration("duration", duration)) + errLoggers := []*zap.Logger{errLog} if s.Logs != nil { - logger = s.Logs.wrapLogger(logger, r.Host) + errLoggers = s.Logs.wrapLogger(errLog, r.Host) } - logger = logger.With(zap.Duration("duration", duration)) // get the values that will be used to log the error errStatus, errMsg, errFields := errLogValues(err) @@ -379,7 +379,9 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { if err2 == nil { // user's error route handled the error response // successfully, so now just log the error - logger.Debug(errMsg, errFields...) + for _, logger := range errLoggers { + logger.Debug(errMsg, errFields...) + } } else { // well... this is awkward errFields = append([]zapcore.Field{ @@ -387,7 +389,9 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { zap.Namespace("first_error"), zap.String("msg", errMsg), }, errFields...) - logger.Error("error handling handler error", errFields...) + for _, logger := range errLoggers { + logger.Error("error handling handler error", errFields...) + } if handlerErr, ok := err.(HandlerError); ok { w.WriteHeader(handlerErr.StatusCode) } else { @@ -395,10 +399,12 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) { } } } else { - if errStatus >= 500 { - logger.Error(errMsg, errFields...) - } else { - logger.Debug(errMsg, errFields...) + for _, logger := range errLoggers { + if errStatus >= 500 { + logger.Error(errMsg, errFields...) + } else { + logger.Debug(errMsg, errFields...) + } } w.WriteHeader(errStatus) } @@ -735,16 +741,6 @@ func (s *Server) logRequest( repl.Set("http.response.duration", duration) repl.Set("http.response.duration_ms", duration.Seconds()*1e3) // multiply seconds to preserve decimal (see #4666) - logger := accLog - if s.Logs != nil { - logger = s.Logs.wrapLogger(logger, r.Host) - } - - log := logger.Info - if wrec.Status() >= 400 { - log = logger.Error - } - userID, _ := repl.GetString("http.auth.user.id") reqBodyLength := 0 @@ -768,7 +764,20 @@ func (s *Server) logRequest( })) fields = append(fields, extra.fields...) - log("handled request", fields...) + loggers := []*zap.Logger{accLog} + if s.Logs != nil { + loggers = s.Logs.wrapLogger(accLog, r.Host) + } + + // wrapping may return multiple loggers, so we log to all of them + for _, logger := range loggers { + logAtLevel := logger.Info + if wrec.Status() >= 400 { + logAtLevel = logger.Error + } + + logAtLevel("handled request", fields...) + } } // protocol returns true if the protocol proto is configured/enabled.