// Copyright 2015 Matthew Holt and The Caddy Authors // // Licensed under the Apache License, Version 2.0 (the "License"); // you may not use this file except in compliance with the License. // You may obtain a copy of the License at // // http://www.apache.org/licenses/LICENSE-2.0 // // Unless required by applicable law or agreed to in writing, software // distributed under the License is distributed on an "AS IS" BASIS, // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. // See the License for the specific language governing permissions and // limitations under the License. package caddy import ( "encoding/json" "fmt" "io" "log" "os" "strings" "sync" "time" "go.uber.org/zap" "go.uber.org/zap/zapcore" "golang.org/x/term" ) func init() { RegisterModule(StdoutWriter{}) RegisterModule(StderrWriter{}) RegisterModule(DiscardWriter{}) } // Logging facilitates logging within Caddy. The default log is // called "default" and you can customize it. You can also define // additional logs. // // By default, all logs at INFO level and higher are written to // standard error ("stderr" writer) in a human-readable format // ("console" encoder if stdout is an interactive terminal, "json" // encoder otherwise). // // All defined logs accept all log entries by default, but you // can filter by level and module/logger names. A logger's name // is the same as the module's name, but a module may append to // logger names for more specificity. For example, you can // filter logs emitted only by HTTP handlers using the name // "http.handlers", because all HTTP handler module names have // that prefix. // // Caddy logs (except the sink) are zero-allocation, so they are // very high-performing in terms of memory and CPU time. Enabling // sampling can further increase throughput on extremely high-load // servers. type Logging struct { // Sink is the destination for all unstructured logs emitted // from Go's standard library logger. These logs are common // in dependencies that are not designed specifically for use // in Caddy. Because it is global and unstructured, the sink // lacks most advanced features and customizations. Sink *SinkLog `json:"sink,omitempty"` // Logs are your logs, keyed by an arbitrary name of your // choosing. The default log can be customized by defining // a log called "default". You can further define other logs // and filter what kinds of entries they accept. Logs map[string]*CustomLog `json:"logs,omitempty"` // a list of all keys for open writers; all writers // that are opened to provision this logging config // must have their keys added to this list so they // can be closed when cleaning up writerKeys []string } // openLogs sets up the config and opens all the configured writers. // It closes its logs when ctx is canceled, so it should clean up // after itself. func (logging *Logging) openLogs(ctx Context) error { // make sure to deallocate resources when context is done ctx.OnCancel(func() { err := logging.closeLogs() if err != nil { Log().Error("closing logs", zap.Error(err)) } }) // set up the "sink" log first (std lib's default global logger) if logging.Sink != nil { err := logging.Sink.provision(ctx, logging) if err != nil { return fmt.Errorf("setting up sink log: %v", err) } } // as a special case, set up the default structured Caddy log next if err := logging.setupNewDefault(ctx); err != nil { return err } // then set up any other custom logs for name, l := range logging.Logs { // the default log is already set up if name == DefaultLoggerName { continue } err := l.provision(ctx, logging) if err != nil { return fmt.Errorf("setting up custom log '%s': %v", name, err) } // Any other logs that use the discard writer can be deleted // entirely. This avoids encoding and processing of each // log entry that would just be thrown away anyway. Notably, // we do not reach this point for the default log, which MUST // exist, otherwise core log emissions would panic because // they use the Log() function directly which expects a non-nil // logger. Even if we keep logs with a discard writer, they // have a nop core, and keeping them at all seems unnecessary. if _, ok := l.writerOpener.(*DiscardWriter); ok { delete(logging.Logs, name) continue } } return nil } func (logging *Logging) setupNewDefault(ctx Context) error { if logging.Logs == nil { logging.Logs = make(map[string]*CustomLog) } // extract the user-defined default log, if any newDefault := new(defaultCustomLog) if userDefault, ok := logging.Logs[DefaultLoggerName]; ok { newDefault.CustomLog = userDefault } else { // if none, make one with our own default settings var err error newDefault, err = newDefaultProductionLog() if err != nil { return fmt.Errorf("setting up default Caddy log: %v", err) } logging.Logs[DefaultLoggerName] = newDefault.CustomLog } // options for the default logger options, err := newDefault.CustomLog.buildOptions() if err != nil { return fmt.Errorf("setting up default log: %v", err) } // set up this new log err = newDefault.CustomLog.provision(ctx, logging) if err != nil { return fmt.Errorf("setting up default log: %v", err) } newDefault.logger = zap.New(newDefault.CustomLog.core, options...) // redirect the default caddy logs defaultLoggerMu.Lock() oldDefault := defaultLogger defaultLogger = newDefault defaultLoggerMu.Unlock() // if the new writer is different, indicate it in the logs for convenience var newDefaultLogWriterKey, currentDefaultLogWriterKey string var newDefaultLogWriterStr, currentDefaultLogWriterStr string if newDefault.writerOpener != nil { newDefaultLogWriterKey = newDefault.writerOpener.WriterKey() newDefaultLogWriterStr = newDefault.writerOpener.String() } if oldDefault.writerOpener != nil { currentDefaultLogWriterKey = oldDefault.writerOpener.WriterKey() currentDefaultLogWriterStr = oldDefault.writerOpener.String() } if newDefaultLogWriterKey != currentDefaultLogWriterKey { oldDefault.logger.Info("redirected default logger", zap.String("from", currentDefaultLogWriterStr), zap.String("to", newDefaultLogWriterStr), ) } return nil } // closeLogs cleans up resources allocated during openLogs. // A successful call to openLogs calls this automatically // when the context is canceled. func (logging *Logging) closeLogs() error { for _, key := range logging.writerKeys { _, err := writers.Delete(key) if err != nil { log.Printf("[ERROR] Closing log writer %v: %v", key, err) } } return nil } // Logger returns a logger that is ready for the module to use. func (logging *Logging) Logger(mod Module) *zap.Logger { modID := string(mod.CaddyModule().ID) var cores []zapcore.Core var options []zap.Option if logging != nil { for _, l := range logging.Logs { if l.matchesModule(modID) { if len(l.Include) == 0 && len(l.Exclude) == 0 { cores = append(cores, l.core) continue } if len(options) == 0 { newOptions, err := l.buildOptions() if err != nil { Log().Error("building options for logger", zap.String("module", modID), zap.Error(err)) } options = newOptions } cores = append(cores, &filteringCore{Core: l.core, cl: l}) } } } multiCore := zapcore.NewTee(cores...) return zap.New(multiCore, options...).Named(modID) } // openWriter opens a writer using opener, and returns true if // the writer is new, or false if the writer already exists. func (logging *Logging) openWriter(opener WriterOpener) (io.WriteCloser, bool, error) { key := opener.WriterKey() writer, loaded, err := writers.LoadOrNew(key, func() (Destructor, error) { w, err := opener.OpenWriter() return writerDestructor{w}, err }) if err != nil { return nil, false, err } logging.writerKeys = append(logging.writerKeys, key) return writer.(io.WriteCloser), !loaded, nil } // WriterOpener is a module that can open a log writer. // It can return a human-readable string representation // of itself so that operators can understand where // the logs are going. type WriterOpener interface { fmt.Stringer // WriterKey is a string that uniquely identifies this // writer configuration. It is not shown to humans. WriterKey() string // OpenWriter opens a log for writing. The writer // should be safe for concurrent use but need not // be synchronous. OpenWriter() (io.WriteCloser, error) } // IsWriterStandardStream returns true if the input is a // writer-opener to a standard stream (stdout, stderr). func IsWriterStandardStream(wo WriterOpener) bool { switch wo.(type) { case StdoutWriter, StderrWriter, *StdoutWriter, *StderrWriter: return true } return false } type writerDestructor struct { io.WriteCloser } func (wdest writerDestructor) Destruct() error { return wdest.Close() } // BaseLog contains the common logging parameters for logging. type BaseLog struct { // The module that writes out log entries for the sink. WriterRaw json.RawMessage `json:"writer,omitempty" caddy:"namespace=caddy.logging.writers inline_key=output"` // The encoder is how the log entries are formatted or encoded. EncoderRaw json.RawMessage `json:"encoder,omitempty" caddy:"namespace=caddy.logging.encoders inline_key=format"` // Level is the minimum level to emit, and is inclusive. // Possible levels: DEBUG, INFO, WARN, ERROR, PANIC, and FATAL Level string `json:"level,omitempty"` // Sampling configures log entry sampling. If enabled, // only some log entries will be emitted. This is useful // for improving performance on extremely high-pressure // servers. Sampling *LogSampling `json:"sampling,omitempty"` // If true, the log entry will include the caller's // file name and line number. Default off. WithCaller bool `json:"with_caller,omitempty"` // If non-zero, and `with_caller` is true, this many // stack frames will be skipped when determining the // caller. Default 0. WithCallerSkip int `json:"with_caller_skip,omitempty"` // If not empty, the log entry will include a stack trace // for all logs at the given level or higher. See `level` // for possible values. Default off. WithStacktrace string `json:"with_stacktrace,omitempty"` writerOpener WriterOpener writer io.WriteCloser encoder zapcore.Encoder levelEnabler zapcore.LevelEnabler core zapcore.Core } func (cl *BaseLog) provisionCommon(ctx Context, logging *Logging) error { if cl.WriterRaw != nil { mod, err := ctx.LoadModule(cl, "WriterRaw") if err != nil { return fmt.Errorf("loading log writer module: %v", err) } cl.writerOpener = mod.(WriterOpener) } if cl.writerOpener == nil { cl.writerOpener = StderrWriter{} } var err error cl.writer, _, err = logging.openWriter(cl.writerOpener) if err != nil { return fmt.Errorf("opening log writer using %#v: %v", cl.writerOpener, err) } // set up the log level cl.levelEnabler, err = parseLevel(cl.Level) if err != nil { return err } if cl.EncoderRaw != nil { mod, err := ctx.LoadModule(cl, "EncoderRaw") if err != nil { return fmt.Errorf("loading log encoder module: %v", err) } cl.encoder = mod.(zapcore.Encoder) // if the encoder module needs the writer to determine // the correct default to use for a nested encoder, we // pass it down as a secondary provisioning step if cfd, ok := mod.(ConfiguresFormatterDefault); ok { if err := cfd.ConfigureDefaultFormat(cl.writerOpener); err != nil { return fmt.Errorf("configuring default format for encoder module: %v", err) } } } if cl.encoder == nil { cl.encoder = newDefaultProductionLogEncoder(cl.writerOpener) } cl.buildCore() return nil } func (cl *BaseLog) buildCore() { // logs which only discard their output don't need // to perform encoding or any other processing steps // at all, so just shorcut to a nop core instead if _, ok := cl.writerOpener.(*DiscardWriter); ok { cl.core = zapcore.NewNopCore() return } c := zapcore.NewCore( cl.encoder, zapcore.AddSync(cl.writer), cl.levelEnabler, ) if cl.Sampling != nil { if cl.Sampling.Interval == 0 { cl.Sampling.Interval = 1 * time.Second } if cl.Sampling.First == 0 { cl.Sampling.First = 100 } if cl.Sampling.Thereafter == 0 { cl.Sampling.Thereafter = 100 } c = zapcore.NewSamplerWithOptions(c, cl.Sampling.Interval, cl.Sampling.First, cl.Sampling.Thereafter) } cl.core = c } func (cl *BaseLog) buildOptions() ([]zap.Option, error) { var options []zap.Option if cl.WithCaller { options = append(options, zap.AddCaller()) if cl.WithCallerSkip != 0 { options = append(options, zap.AddCallerSkip(cl.WithCallerSkip)) } } if cl.WithStacktrace != "" { levelEnabler, err := parseLevel(cl.WithStacktrace) if err != nil { return options, fmt.Errorf("setting up default Caddy log: %v", err) } options = append(options, zap.AddStacktrace(levelEnabler)) } return options, nil } // SinkLog configures the default Go standard library // global logger in the log package. This is necessary because // module dependencies which are not built specifically for // Caddy will use the standard logger. This is also known as // the "sink" logger. type SinkLog struct { BaseLog } func (sll *SinkLog) provision(ctx Context, logging *Logging) error { if err := sll.provisionCommon(ctx, logging); err != nil { return err } options, err := sll.buildOptions() if err != nil { return err } logger := zap.New(sll.core, options...) ctx.cleanupFuncs = append(ctx.cleanupFuncs, zap.RedirectStdLog(logger)) return nil } // CustomLog represents a custom logger configuration. // // By default, a log will emit all log entries. Some entries // will be skipped if sampling is enabled. Further, the Include // and Exclude parameters define which loggers (by name) are // allowed or rejected from emitting in this log. If both Include // and Exclude are populated, their values must be mutually // exclusive, and longer namespaces have priority. If neither // are populated, all logs are emitted. type CustomLog struct { BaseLog // Include defines the names of loggers to emit in this // log. For example, to include only logs emitted by the // admin API, you would include "admin.api". Include []string `json:"include,omitempty"` // Exclude defines the names of loggers that should be // skipped by this log. For example, to exclude only // HTTP access logs, you would exclude "http.log.access". Exclude []string `json:"exclude,omitempty"` } func (cl *CustomLog) provision(ctx Context, logging *Logging) error { if err := cl.provisionCommon(ctx, logging); err != nil { return err } // If both Include and Exclude lists are populated, then each item must // be a superspace or subspace of an item in the other list, because // populating both lists means that any given item is either a rule // or an exception to another rule. But if the item is not a super- // or sub-space of any item in the other list, it is neither a rule // nor an exception, and is a contradiction. Ensure, too, that the // sets do not intersect, which is also a contradiction. if len(cl.Include) > 0 && len(cl.Exclude) > 0 { // prevent intersections for _, allow := range cl.Include { for _, deny := range cl.Exclude { if allow == deny { return fmt.Errorf("include and exclude must not intersect, but found %s in both lists", allow) } } } // ensure namespaces are nested outer: for _, allow := range cl.Include { for _, deny := range cl.Exclude { if strings.HasPrefix(allow+".", deny+".") || strings.HasPrefix(deny+".", allow+".") { continue outer } } return fmt.Errorf("when both include and exclude are populated, each element must be a superspace or subspace of one in the other list; check '%s' in include", allow) } } return nil } func (cl *CustomLog) matchesModule(moduleID string) bool { return cl.loggerAllowed(moduleID, true) } // loggerAllowed returns true if name is allowed to emit // to cl. isModule should be true if name is the name of // a module and you want to see if ANY of that module's // logs would be permitted. func (cl *CustomLog) loggerAllowed(name string, isModule bool) bool { // accept all loggers by default if len(cl.Include) == 0 && len(cl.Exclude) == 0 { return true } // append a dot so that partial names don't match // (i.e. we don't want "foo.b" to match "foo.bar"); we // will also have to append a dot when we do HasPrefix // below to compensate for when namespaces are equal if name != "" && name != "*" && name != "." { name += "." } var longestAccept, longestReject int if len(cl.Include) > 0 { for _, namespace := range cl.Include { var hasPrefix bool if isModule { hasPrefix = strings.HasPrefix(namespace+".", name) } else { hasPrefix = strings.HasPrefix(name, namespace+".") } if hasPrefix && len(namespace) > longestAccept { longestAccept = len(namespace) } } // the include list was populated, meaning that // a match in this list is absolutely required // if we are to accept the entry if longestAccept == 0 { return false } } if len(cl.Exclude) > 0 { for _, namespace := range cl.Exclude { // * == all logs emitted by modules // . == all logs emitted by core if (namespace == "*" && name != ".") || (namespace == "." && name == ".") { return false } if strings.HasPrefix(name, namespace+".") && len(namespace) > longestReject { longestReject = len(namespace) } } // the reject list is populated, so we have to // reject this entry if its match is better // than the best from the accept list if longestReject > longestAccept { return false } } return (longestAccept > longestReject) || (len(cl.Include) == 0 && longestReject == 0) } // filteringCore filters log entries based on logger name, // according to the rules of a CustomLog. type filteringCore struct { zapcore.Core cl *CustomLog } // With properly wraps With. func (fc *filteringCore) With(fields []zapcore.Field) zapcore.Core { return &filteringCore{ Core: fc.Core.With(fields), cl: fc.cl, } } // Check only allows the log entry if its logger name // is allowed from the include/exclude rules of fc.cl. func (fc *filteringCore) Check(e zapcore.Entry, ce *zapcore.CheckedEntry) *zapcore.CheckedEntry { if fc.cl.loggerAllowed(e.LoggerName, false) { return fc.Core.Check(e, ce) } return ce } // LogSampling configures log entry sampling. type LogSampling struct { // The window over which to conduct sampling. Interval time.Duration `json:"interval,omitempty"` // Log this many entries within a given level and // message for each interval. First int `json:"first,omitempty"` // If more entries with the same level and message // are seen during the same interval, keep one in // this many entries until the end of the interval. Thereafter int `json:"thereafter,omitempty"` } type ( // StdoutWriter writes logs to standard out. StdoutWriter struct{} // StderrWriter writes logs to standard error. StderrWriter struct{} // DiscardWriter discards all writes. DiscardWriter struct{} ) // CaddyModule returns the Caddy module information. func (StdoutWriter) CaddyModule() ModuleInfo { return ModuleInfo{ ID: "caddy.logging.writers.stdout", New: func() Module { return new(StdoutWriter) }, } } // CaddyModule returns the Caddy module information. func (StderrWriter) CaddyModule() ModuleInfo { return ModuleInfo{ ID: "caddy.logging.writers.stderr", New: func() Module { return new(StderrWriter) }, } } // CaddyModule returns the Caddy module information. func (DiscardWriter) CaddyModule() ModuleInfo { return ModuleInfo{ ID: "caddy.logging.writers.discard", New: func() Module { return new(DiscardWriter) }, } } func (StdoutWriter) String() string { return "stdout" } func (StderrWriter) String() string { return "stderr" } func (DiscardWriter) String() string { return "discard" } // WriterKey returns a unique key representing stdout. func (StdoutWriter) WriterKey() string { return "std:out" } // WriterKey returns a unique key representing stderr. func (StderrWriter) WriterKey() string { return "std:err" } // WriterKey returns a unique key representing discard. func (DiscardWriter) WriterKey() string { return "discard" } // OpenWriter returns os.Stdout that can't be closed. func (StdoutWriter) OpenWriter() (io.WriteCloser, error) { return notClosable{os.Stdout}, nil } // OpenWriter returns os.Stderr that can't be closed. func (StderrWriter) OpenWriter() (io.WriteCloser, error) { return notClosable{os.Stderr}, nil } // OpenWriter returns io.Discard that can't be closed. func (DiscardWriter) OpenWriter() (io.WriteCloser, error) { return notClosable{io.Discard}, nil } // notClosable is an io.WriteCloser that can't be closed. type notClosable struct{ io.Writer } func (fc notClosable) Close() error { return nil } type defaultCustomLog struct { *CustomLog logger *zap.Logger } // newDefaultProductionLog configures a custom log that is // intended for use by default if no other log is specified // in a config. It writes to stderr, uses the console encoder, // and enables INFO-level logs and higher. func newDefaultProductionLog() (*defaultCustomLog, error) { cl := new(CustomLog) cl.writerOpener = StderrWriter{} var err error cl.writer, err = cl.writerOpener.OpenWriter() if err != nil { return nil, err } cl.encoder = newDefaultProductionLogEncoder(cl.writerOpener) cl.levelEnabler = zapcore.InfoLevel cl.buildCore() logger := zap.New(cl.core) // capture logs from other libraries which // may not be using zap logging directly _ = zap.RedirectStdLog(logger) return &defaultCustomLog{ CustomLog: cl, logger: logger, }, nil } func newDefaultProductionLogEncoder(wo WriterOpener) zapcore.Encoder { encCfg := zap.NewProductionEncoderConfig() if IsWriterStandardStream(wo) && term.IsTerminal(int(os.Stderr.Fd())) { // if interactive terminal, make output more human-readable by default encCfg.EncodeTime = func(ts time.Time, encoder zapcore.PrimitiveArrayEncoder) { encoder.AppendString(ts.UTC().Format("2006/01/02 15:04:05.000")) } encCfg.EncodeLevel = zapcore.CapitalColorLevelEncoder return zapcore.NewConsoleEncoder(encCfg) } return zapcore.NewJSONEncoder(encCfg) } func parseLevel(levelInput string) (zapcore.LevelEnabler, error) { repl := NewReplacer() level, err := repl.ReplaceOrErr(levelInput, true, true) if err != nil { return nil, fmt.Errorf("invalid log level: %v", err) } level = strings.ToLower(level) // set up the log level switch level { case "debug": return zapcore.DebugLevel, nil case "", "info": return zapcore.InfoLevel, nil case "warn": return zapcore.WarnLevel, nil case "error": return zapcore.ErrorLevel, nil case "panic": return zapcore.PanicLevel, nil case "fatal": return zapcore.FatalLevel, nil default: return nil, fmt.Errorf("unrecognized log level: %s", level) } } // Log returns the current default logger. func Log() *zap.Logger { defaultLoggerMu.RLock() defer defaultLoggerMu.RUnlock() return defaultLogger.logger } var ( defaultLogger, _ = newDefaultProductionLog() defaultLoggerMu sync.RWMutex ) var writers = NewUsagePool() // ConfiguresFormatterDefault is an optional interface that // encoder modules can implement to configure the default // format of their encoder. This is useful for encoders // which nest an encoder, that needs to know the writer // in order to determine the correct default. type ConfiguresFormatterDefault interface { ConfigureDefaultFormat(WriterOpener) error } const DefaultLoggerName = "default" // Interface guards var ( _ io.WriteCloser = (*notClosable)(nil) _ WriterOpener = (*StdoutWriter)(nil) _ WriterOpener = (*StderrWriter)(nil) )