From 5d97522d18da39cd3f9dd309774a5ad2c51f4c51 Mon Sep 17 00:00:00 2001 From: Matt Holt Date: Tue, 25 Feb 2020 22:00:33 -0700 Subject: [PATCH] v2: 'log' directive for Caddyfile, and debug mode (#3052) * httpcaddyfile: Begin implementing log directive, and debug mode For now, debug mode just sets the log level for all logs to DEBUG (unless a level is specified explicitly). * httpcaddyfile: Finish 'log' directive Also rename StringEncoder -> SingleFieldEncoder * Fix minor bug in replacer (when vals are empty) --- caddyconfig/httpcaddyfile/builtins.go | 110 ++++++++++++++++++ caddyconfig/httpcaddyfile/httptype.go | 67 +++++++++++ go.mod | 2 +- go.sum | 2 + modules/logging/encoders.go | 155 ++++++++++++++++++++++++-- modules/logging/filewriter.go | 76 ++++++++++++- modules/logging/netwriter.go | 23 +++- replacer.go | 9 +- replacer_test.go | 5 + 9 files changed, 428 insertions(+), 21 deletions(-) diff --git a/caddyconfig/httpcaddyfile/builtins.go b/caddyconfig/httpcaddyfile/builtins.go index 8cfca1833..43e184efc 100644 --- a/caddyconfig/httpcaddyfile/builtins.go +++ b/caddyconfig/httpcaddyfile/builtins.go @@ -24,8 +24,10 @@ import ( "github.com/caddyserver/caddy/v2" "github.com/caddyserver/caddy/v2/caddyconfig" + "github.com/caddyserver/caddy/v2/caddyconfig/caddyfile" "github.com/caddyserver/caddy/v2/modules/caddyhttp" "github.com/caddyserver/caddy/v2/modules/caddytls" + "go.uber.org/zap/zapcore" ) func init() { @@ -37,6 +39,7 @@ func init() { RegisterHandlerDirective("route", parseRoute) RegisterHandlerDirective("handle", parseSegmentAsSubroute) RegisterDirective("handle_errors", parseHandleErrors) + RegisterDirective("log", parseLog) } // parseBind parses the bind directive. Syntax: @@ -426,9 +429,116 @@ func parseHandleErrors(h Helper) ([]ConfigValue, error) { }, nil } +// parseLog parses the log directive. Syntax: +// +// log { +// output ... +// format ... +// level +// } +// +func parseLog(h Helper) ([]ConfigValue, error) { + var configValues []ConfigValue + for h.Next() { + cl := new(caddy.CustomLog) + + for h.NextBlock(0) { + switch h.Val() { + case "output": + if !h.NextArg() { + return nil, h.ArgErr() + } + moduleName := h.Val() + + // can't use the usual caddyfile.Unmarshaler flow with the + // standard writers because they are in the caddy package + // (because they are the default) and implementing that + // interface there would unfortunately create circular import + var wo caddy.WriterOpener + switch moduleName { + case "stdout": + wo = caddy.StdoutWriter{} + case "stderr": + wo = caddy.StderrWriter{} + case "discard": + wo = caddy.DiscardWriter{} + default: + mod, err := caddy.GetModule("caddy.logging.writers." + moduleName) + if err != nil { + return nil, h.Errf("getting log writer module named '%s': %v", moduleName, err) + } + unm, ok := mod.New().(caddyfile.Unmarshaler) + if !ok { + return nil, h.Errf("log writer module '%s' is not a Caddyfile unmarshaler", mod) + } + err = unm.UnmarshalCaddyfile(h.NewFromNextSegment()) + if err != nil { + return nil, err + } + wo, ok = unm.(caddy.WriterOpener) + if !ok { + return nil, h.Errf("module %s is not a WriterOpener", mod) + } + } + cl.WriterRaw = caddyconfig.JSONModuleObject(wo, "output", moduleName, h.warnings) + + case "format": + if !h.NextArg() { + return nil, h.ArgErr() + } + moduleName := h.Val() + mod, err := caddy.GetModule("caddy.logging.encoders." + moduleName) + if err != nil { + return nil, h.Errf("getting log encoder module named '%s': %v", moduleName, err) + } + unm, ok := mod.New().(caddyfile.Unmarshaler) + if !ok { + return nil, h.Errf("log encoder module '%s' is not a Caddyfile unmarshaler", mod) + } + err = unm.UnmarshalCaddyfile(h.NewFromNextSegment()) + if err != nil { + return nil, err + } + enc, ok := unm.(zapcore.Encoder) + if !ok { + return nil, h.Errf("module %s is not a zapcore.Encoder", mod) + } + cl.EncoderRaw = caddyconfig.JSONModuleObject(enc, "format", moduleName, h.warnings) + + case "level": + if !h.NextArg() { + return nil, h.ArgErr() + } + cl.Level = h.Val() + if h.NextArg() { + return nil, h.ArgErr() + } + + default: + return nil, h.Errf("unrecognized subdirective: %s", h.Val()) + } + } + + var val namedCustomLog + if !reflect.DeepEqual(cl, new(caddy.CustomLog)) { + cl.Include = []string{"http.log.access"} + val.name = fmt.Sprintf("log%d", logCounter) + val.log = cl + logCounter++ + } + configValues = append(configValues, ConfigValue{ + Class: "custom_log", + Value: val, + }) + } + return configValues, nil +} + // tlsCertTags maps certificate filenames to their tag. // This is used to remember which tag is used for each // certificate files, since we need to avoid loading // the same certificate files more than once, overwriting // previous tags var tlsCertTags = make(map[string]string) + +var logCounter int diff --git a/caddyconfig/httpcaddyfile/httptype.go b/caddyconfig/httpcaddyfile/httptype.go index d4c2bb61e..e3fcdd2ef 100644 --- a/caddyconfig/httpcaddyfile/httptype.go +++ b/caddyconfig/httpcaddyfile/httptype.go @@ -282,6 +282,35 @@ func (st ServerType) Setup(originalServerBlocks []caddyfile.ServerBlock, } } + // extract any custom logs, and enforce configured levels + var customLogs []namedCustomLog + var hasDefaultLog bool + for _, sb := range serverBlocks { + for _, clVal := range sb.pile["custom_log"] { + ncl := clVal.Value.(namedCustomLog) + if ncl.name == "" { + continue + } + if ncl.name == "default" { + hasDefaultLog = true + } + if _, ok := options["debug"]; ok && ncl.log.Level == "" { + ncl.log.Level = "DEBUG" + } + customLogs = append(customLogs, ncl) + } + } + if !hasDefaultLog { + // if the default log was not customized, ensure we + // configure it with any applicable options + if _, ok := options["debug"]; ok { + customLogs = append(customLogs, namedCustomLog{ + name: "default", + log: &caddy.CustomLog{Level: "DEBUG"}, + }) + } + } + // annnd the top-level config, then we're done! cfg := &caddy.Config{AppsRaw: make(caddy.ModuleMap)} if !reflect.DeepEqual(httpApp, caddyhttp.App{}) { @@ -299,6 +328,18 @@ func (st ServerType) Setup(originalServerBlocks []caddyfile.ServerBlock, if adminConfig, ok := options["admin"].(string); ok && adminConfig != "" { cfg.Admin = &caddy.AdminConfig{Listen: adminConfig} } + if len(customLogs) > 0 { + if cfg.Logging == nil { + cfg.Logging = &caddy.Logging{ + Logs: make(map[string]*caddy.CustomLog), + } + } + for _, ncl := range customLogs { + if ncl.name != "" { + cfg.Logging.Logs[ncl.name] = ncl.log + } + } + } return cfg, warnings, nil } @@ -335,6 +376,8 @@ func (ServerType) evaluateGlobalOptionsBlock(serverBlocks []serverBlock, options val, err = parseOptEmail(disp) case "admin": val, err = parseOptAdmin(disp) + case "debug": + options["debug"] = true default: return nil, fmt.Errorf("unrecognized parameter name: %s", dir) } @@ -506,6 +549,25 @@ func (st *ServerType) serversFromPairings( srv.Errors.Routes = appendSubrouteToRouteList(srv.Errors.Routes, sr, matcherSetsEnc, p, warnings) } } + + // add log associations + for _, cval := range sblock.pile["custom_log"] { + ncl := cval.Value.(namedCustomLog) + if srv.Logs == nil { + srv.Logs = &caddyhttp.ServerLogConfig{ + LoggerNames: make(map[string]string), + } + } + hosts, err := st.hostsFromServerBlockKeys(sblock.block) + if err != nil { + return nil, err + } + for _, h := range hosts { + if ncl.name != "" { + srv.Logs.LoggerNames[h] = ncl.name + } + } + } } // a catch-all TLS conn policy is necessary to ensure TLS can @@ -940,6 +1002,11 @@ type matcherSetAndTokens struct { tokens []caddyfile.Token } +type namedCustomLog struct { + name string + log *caddy.CustomLog +} + // sbAddrAssocation is a mapping from a list of // addresses to a list of server blocks that are // served on those addresses. diff --git a/go.mod b/go.mod index b07acdb37..f43a9e7c6 100644 --- a/go.mod +++ b/go.mod @@ -7,7 +7,7 @@ require ( github.com/alecthomas/chroma v0.7.0 github.com/andybalholm/brotli v0.0.0-20190821151343-b60f0d972eeb github.com/cenkalti/backoff/v3 v3.1.1 // indirect - github.com/dustin/go-humanize v1.0.0 + github.com/dustin/go-humanize v1.0.1-0.20200219035652-afde56e7acac github.com/go-acme/lego/v3 v3.3.0 github.com/golang/groupcache v0.0.0-20191002201903-404acd9df4cc github.com/ilibs/json5 v1.0.1 diff --git a/go.sum b/go.sum index 374f9f983..6c4619cba 100644 --- a/go.sum +++ b/go.sum @@ -94,6 +94,8 @@ github.com/dnaeon/go-vcr v0.0.0-20180814043457-aafff18a5cc2/go.mod h1:aBB1+wY4s9 github.com/dnsimple/dnsimple-go v0.30.0/go.mod h1:O5TJ0/U6r7AfT8niYNlmohpLbCSG+c71tQlGr9SeGrg= github.com/dustin/go-humanize v1.0.0 h1:VSnTsYCnlFHaM2/igO1h6X3HA71jcobQuxemgkq4zYo= github.com/dustin/go-humanize v1.0.0/go.mod h1:HtrtbFcZ19U5GC7JDqmcUSB87Iq5E25KnS6fMYU6eOk= +github.com/dustin/go-humanize v1.0.1-0.20200219035652-afde56e7acac h1:opbrjaN/L8gg6Xh5D04Tem+8xVcz6ajZlGCs49mQgyg= +github.com/dustin/go-humanize v1.0.1-0.20200219035652-afde56e7acac/go.mod h1:HtrtbFcZ19U5GC7JDqmcUSB87Iq5E25KnS6fMYU6eOk= github.com/eapache/go-resiliency v1.1.0/go.mod h1:kFI+JgMyC7bLPUVY133qvEBtVayf5mFgVsvEsIPBvNs= github.com/eapache/go-xerial-snappy v0.0.0-20180814174437-776d5712da21/go.mod h1:+020luEh2TKB4/GOp8oxxtq0Daoen/Cii55CzbTV6DU= github.com/eapache/queue v1.1.0/go.mod h1:6eCeP0CKFpHLu8blIFXhExK/dRa7WDZfr6jVFPTqq+I= diff --git a/modules/logging/encoders.go b/modules/logging/encoders.go index 49ad11aa6..bd120d575 100644 --- a/modules/logging/encoders.go +++ b/modules/logging/encoders.go @@ -21,6 +21,7 @@ import ( "time" "github.com/caddyserver/caddy/v2" + "github.com/caddyserver/caddy/v2/caddyconfig/caddyfile" zaplogfmt "github.com/jsternberg/zap-logfmt" "go.uber.org/zap" "go.uber.org/zap/buffer" @@ -31,7 +32,7 @@ func init() { caddy.RegisterModule(ConsoleEncoder{}) caddy.RegisterModule(JSONEncoder{}) caddy.RegisterModule(LogfmtEncoder{}) - caddy.RegisterModule(StringEncoder{}) + caddy.RegisterModule(SingleFieldEncoder{}) } // ConsoleEncoder encodes log entries that are mostly human-readable. @@ -54,6 +55,27 @@ func (ce *ConsoleEncoder) Provision(_ caddy.Context) error { return nil } +// UnmarshalCaddyfile sets up the module from Caddyfile tokens. Syntax: +// +// console { +// +// } +// +// See the godoc on the LogEncoderConfig type for the syntax of +// subdirectives that are common to most/all encoders. +func (ce *ConsoleEncoder) UnmarshalCaddyfile(d *caddyfile.Dispenser) error { + for d.Next() { + if d.NextArg() { + return d.ArgErr() + } + err := ce.LogEncoderConfig.UnmarshalCaddyfile(d) + if err != nil { + return err + } + } + return nil +} + // JSONEncoder encodes entries as JSON. type JSONEncoder struct { zapcore.Encoder `json:"-"` @@ -74,6 +96,27 @@ func (je *JSONEncoder) Provision(_ caddy.Context) error { return nil } +// UnmarshalCaddyfile sets up the module from Caddyfile tokens. Syntax: +// +// json { +// +// } +// +// See the godoc on the LogEncoderConfig type for the syntax of +// subdirectives that are common to most/all encoders. +func (je *JSONEncoder) UnmarshalCaddyfile(d *caddyfile.Dispenser) error { + for d.Next() { + if d.NextArg() { + return d.ArgErr() + } + err := je.LogEncoderConfig.UnmarshalCaddyfile(d) + if err != nil { + return err + } + } + return nil +} + // LogfmtEncoder encodes log entries as logfmt: // https://www.brandur.org/logfmt type LogfmtEncoder struct { @@ -95,26 +138,47 @@ func (lfe *LogfmtEncoder) Provision(_ caddy.Context) error { return nil } -// StringEncoder writes a log entry that consists entirely +// UnmarshalCaddyfile sets up the module from Caddyfile tokens. Syntax: +// +// logfmt { +// +// } +// +// See the godoc on the LogEncoderConfig type for the syntax of +// subdirectives that are common to most/all encoders. +func (lfe *LogfmtEncoder) UnmarshalCaddyfile(d *caddyfile.Dispenser) error { + for d.Next() { + if d.NextArg() { + return d.ArgErr() + } + err := lfe.LogEncoderConfig.UnmarshalCaddyfile(d) + if err != nil { + return err + } + } + return nil +} + +// SingleFieldEncoder writes a log entry that consists entirely // of a single string field in the log entry. This is useful // for custom, self-encoded log entries that consist of a // single field in the structured log entry. -type StringEncoder struct { +type SingleFieldEncoder struct { zapcore.Encoder `json:"-"` FieldName string `json:"field,omitempty"` FallbackRaw json.RawMessage `json:"fallback,omitempty" caddy:"namespace=caddy.logging.encoders inline_key=format"` } // CaddyModule returns the Caddy module information. -func (StringEncoder) CaddyModule() caddy.ModuleInfo { +func (SingleFieldEncoder) CaddyModule() caddy.ModuleInfo { return caddy.ModuleInfo{ - ID: "caddy.logging.encoders.string", - New: func() caddy.Module { return new(StringEncoder) }, + ID: "caddy.logging.encoders.single_field", + New: func() caddy.Module { return new(SingleFieldEncoder) }, } } // Provision sets up the encoder. -func (se *StringEncoder) Provision(ctx caddy.Context) error { +func (se *SingleFieldEncoder) Provision(ctx caddy.Context) error { if se.FallbackRaw != nil { val, err := ctx.LoadModule(se, "FallbackRaw") if err != nil { @@ -132,16 +196,16 @@ func (se *StringEncoder) Provision(ctx caddy.Context) error { // necessary because we implement our own EncodeEntry, // and if we simply let the embedded encoder's Clone // be promoted, it would return a clone of that, and -// we'd lose our StringEncoder's EncodeEntry. -func (se StringEncoder) Clone() zapcore.Encoder { - return StringEncoder{ +// we'd lose our SingleFieldEncoder's EncodeEntry. +func (se SingleFieldEncoder) Clone() zapcore.Encoder { + return SingleFieldEncoder{ Encoder: se.Encoder.Clone(), FieldName: se.FieldName, } } // EncodeEntry partially implements the zapcore.Encoder interface. -func (se StringEncoder) EncodeEntry(ent zapcore.Entry, fields []zapcore.Field) (*buffer.Buffer, error) { +func (se SingleFieldEncoder) EncodeEntry(ent zapcore.Entry, fields []zapcore.Field) (*buffer.Buffer, error) { for _, f := range fields { if f.Key == se.FieldName { buf := bufferpool.Get() @@ -158,6 +222,21 @@ func (se StringEncoder) EncodeEntry(ent zapcore.Entry, fields []zapcore.Field) ( return se.Encoder.EncodeEntry(ent, fields) } +// UnmarshalCaddyfile sets up the module from Caddyfile tokens. Syntax: +// +// single_field +// +func (se *SingleFieldEncoder) UnmarshalCaddyfile(d *caddyfile.Dispenser) error { + for d.Next() { + var fieldName string + if !d.AllArgs(&fieldName) { + return d.ArgErr() + } + se.FieldName = d.Val() + } + return nil +} + // LogEncoderConfig holds configuration common to most encoders. type LogEncoderConfig struct { MessageKey *string `json:"message_key,omitempty"` @@ -172,6 +251,53 @@ type LogEncoderConfig struct { LevelFormat string `json:"level_format,omitempty"` } +// UnmarshalCaddyfile populates the struct from Caddyfile tokens. Syntax: +// +// { +// message_key +// level_key +// time_key +// name_key +// caller_key +// stacktrace_key +// line_ending +// time_format +// level_format +// } +// +func (lec *LogEncoderConfig) UnmarshalCaddyfile(d *caddyfile.Dispenser) error { + for nesting := d.Nesting(); d.NextBlock(nesting); { + subdir := d.Val() + var arg string + if !d.AllArgs(&arg) { + return d.ArgErr() + } + switch subdir { + case "message_key": + lec.MessageKey = &arg + case "level_key": + lec.LevelKey = &arg + case "time_key": + lec.TimeKey = &arg + case "name_key": + lec.NameKey = &arg + case "caller_key": + lec.CallerKey = &arg + case "stacktrace_key": + lec.StacktraceKey = &arg + case "line_ending": + lec.LineEnding = &arg + case "time_format": + lec.TimeFormat = arg + case "level_format": + lec.LevelFormat = arg + default: + return d.Errf("unrecognized subdirective %s", subdir) + } + } + return nil +} + // ZapcoreEncoderConfig returns the equivalent zapcore.EncoderConfig. // If lec is nil, zap.NewProductionEncoderConfig() is returned. func (lec *LogEncoderConfig) ZapcoreEncoderConfig() zapcore.EncoderConfig { @@ -263,5 +389,10 @@ var ( _ zapcore.Encoder = (*ConsoleEncoder)(nil) _ zapcore.Encoder = (*JSONEncoder)(nil) _ zapcore.Encoder = (*LogfmtEncoder)(nil) - _ zapcore.Encoder = (*StringEncoder)(nil) + _ zapcore.Encoder = (*SingleFieldEncoder)(nil) + + _ caddyfile.Unmarshaler = (*ConsoleEncoder)(nil) + _ caddyfile.Unmarshaler = (*JSONEncoder)(nil) + _ caddyfile.Unmarshaler = (*LogfmtEncoder)(nil) + _ caddyfile.Unmarshaler = (*SingleFieldEncoder)(nil) ) diff --git a/modules/logging/filewriter.go b/modules/logging/filewriter.go index f17f9753e..e9c2dd8d0 100644 --- a/modules/logging/filewriter.go +++ b/modules/logging/filewriter.go @@ -19,8 +19,12 @@ import ( "io" "os" "path/filepath" + "strconv" + "time" "github.com/caddyserver/caddy/v2" + "github.com/caddyserver/caddy/v2/caddyconfig/caddyfile" + "github.com/dustin/go-humanize" "gopkg.in/natefinch/lumberjack.v2" ) @@ -125,7 +129,77 @@ func (fw FileWriter) OpenWriter() (io.WriteCloser, error) { return os.OpenFile(fw.Filename, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0666) } +// UnmarshalCaddyfile sets up the module from Caddyfile tokens. Syntax: +// +// file { +// roll_disabled +// roll_size +// roll_keep +// roll_keep_for +// } +// +// The roll_size value will be rounded down to number of megabytes (MiB). +// The roll_keep_for duration will be rounded down to number of days. +func (fw *FileWriter) UnmarshalCaddyfile(d *caddyfile.Dispenser) error { + for d.Next() { + if !d.NextArg() { + return d.ArgErr() + } + fw.Filename = d.Val() + if d.NextArg() { + return d.ArgErr() + } + + for d.NextBlock(0) { + switch d.Val() { + case "roll_disabled": + var f bool + fw.Roll = &f + if d.NextArg() { + return d.ArgErr() + } + + case "roll_size": + var sizeStr string + if !d.AllArgs(&sizeStr) { + return d.ArgErr() + } + size, err := humanize.ParseBytes(sizeStr) + if err != nil { + return d.Errf("parsing size: %v", err) + } + fw.RollSizeMB = int(size) / 1024 / 1024 + + case "roll_keep": + var keepStr string + if !d.AllArgs(&keepStr) { + return d.ArgErr() + } + keep, err := strconv.Atoi(keepStr) + if err != nil { + return d.Errf("parsing roll_keep number: %v", err) + } + fw.RollKeep = keep + + case "roll_keep_for": + var keepForStr string + if !d.AllArgs(&keepForStr) { + return d.ArgErr() + } + keepFor, err := time.ParseDuration(keepForStr) + if err != nil { + return d.Errf("parsing roll_keep_for duration: %v", err) + } + fw.RollKeepDays = int(keepFor.Hours()) / 24 + } + } + } + return nil +} + // Interface guards var ( - _ caddy.Provisioner = (*FileWriter)(nil) + _ caddy.Provisioner = (*FileWriter)(nil) + _ caddy.WriterOpener = (*FileWriter)(nil) + _ caddyfile.Unmarshaler = (*FileWriter)(nil) ) diff --git a/modules/logging/netwriter.go b/modules/logging/netwriter.go index 1df80b65a..7d2dafac3 100644 --- a/modules/logging/netwriter.go +++ b/modules/logging/netwriter.go @@ -20,6 +20,7 @@ import ( "net" "github.com/caddyserver/caddy/v2" + "github.com/caddyserver/caddy/v2/caddyconfig/caddyfile" ) func init() { @@ -75,8 +76,26 @@ func (nw NetWriter) OpenWriter() (io.WriteCloser, error) { return net.Dial(nw.addr.Network, nw.addr.JoinHostPort(0)) } +// UnmarshalCaddyfile sets up the handler from Caddyfile tokens. Syntax: +// +// net
+// +func (nw *NetWriter) UnmarshalCaddyfile(d *caddyfile.Dispenser) error { + for d.Next() { + if !d.NextArg() { + return d.ArgErr() + } + nw.Address = d.Val() + if d.NextArg() { + return d.ArgErr() + } + } + return nil +} + // Interface guards var ( - _ caddy.Provisioner = (*NetWriter)(nil) - _ caddy.WriterOpener = (*NetWriter)(nil) + _ caddy.Provisioner = (*NetWriter)(nil) + _ caddy.WriterOpener = (*NetWriter)(nil) + _ caddyfile.Unmarshaler = (*NetWriter)(nil) ) diff --git a/replacer.go b/replacer.go index 8ed6d2495..aad13e2a2 100644 --- a/replacer.go +++ b/replacer.go @@ -148,11 +148,10 @@ func (r *Replacer) replace(input, empty string, if errOnUnknown { return "", fmt.Errorf("unrecognized placeholder %s%s%s", string(phOpen), key, string(phClose)) - } else if treatUnknownAsEmpty { - if empty != "" { - sb.WriteString(empty) - } - } else { + } else if !treatUnknownAsEmpty { + // if treatUnknownAsEmpty is true, we'll + // handle an empty val later; so only + // continue otherwise lastWriteCursor = i continue } diff --git a/replacer_test.go b/replacer_test.go index 42e9ee1f7..4b5619451 100644 --- a/replacer_test.go +++ b/replacer_test.go @@ -67,6 +67,11 @@ func TestReplacer(t *testing.T) { input: `{{}`, expect: "", }, + { + input: `{unknown}`, + empty: "-", + expect: "-", + }, } { actual := rep.ReplaceAll(tc.input, tc.empty) if actual != tc.expect {