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

@@ -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)
 					}
 				}
 			}

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"
+							]
 						}
 					}
 				}

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
 					}

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"
+							]
+						}
+					}
+				}
+			}
+		}
+	}
+}

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"
+							]
 						}
 					}
 				}

caddytest/integration/caddyfile_adapt/log_override_name_multiaccess.caddyfiletest

@@ -76,7 +76,9 @@ http://localhost:8881 {
 					},
 					"logs": {
 						"logger_names": {
-							"localhost": "foo"
+							"localhost": [
+								"foo"
+							]
 						}
 					}
 				}

caddytest/integration/caddyfile_adapt/log_override_name_multiaccess_debug.caddyfiletest

@@ -81,7 +81,9 @@ http://localhost:8881 {
 					},
 					"logs": {
 						"logger_names": {
-							"localhost": "foo"
+							"localhost": [
+								"foo"
+							]
 						}
 					}
 				}

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",

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

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.