// 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" "io/ioutil" "log" "os" "strings" "sync" "time" "go.uber.org/zap" "go.uber.org/zap/zapcore" ) func init() { RegisterModule(StdoutWriter{}) RegisterModule(StderrWriter{}) RegisterModule(DiscardWriter{}) } // Logging facilitates logging within Caddy. type Logging struct { Sink *StandardLibLog `json:"sink,omitempty"` 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 cancelled, 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 == "default" { 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["default"]; 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["default"] = newDefault.CustomLog } // 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) // 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 cancelled. 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 { modName := mod.CaddyModule().Name var cores []zapcore.Core if logging != nil { for _, l := range logging.Logs { if l.matchesModule(modName) { if len(l.Include) == 0 && len(l.Exclude) == 0 { cores = append(cores, l.core) continue } cores = append(cores, &filteringCore{Core: l.core, cl: l}) } } } multiCore := zapcore.NewTee(cores...) return zap.New(multiCore).Named(modName) } // 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 { logging.writerKeys = append(logging.writerKeys, key) } return writer.(io.WriteCloser), !loaded, err } // 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) } type writerDestructor struct { io.WriteCloser } func (wdest writerDestructor) Destruct() error { return wdest.Close() } // StandardLibLog 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. type StandardLibLog struct { WriterRaw json.RawMessage `json:"writer,omitempty"` writer io.WriteCloser } func (sll *StandardLibLog) provision(ctx Context, logging *Logging) error { if sll.WriterRaw != nil { val, err := ctx.LoadModuleInline("output", "caddy.logging.writers", sll.WriterRaw) if err != nil { return fmt.Errorf("loading sink log writer module: %v", err) } wo := val.(WriterOpener) sll.WriterRaw = nil // allow GC to deallocate var isNew bool sll.writer, isNew, err = logging.openWriter(wo) if err != nil { return fmt.Errorf("opening sink log writer %#v: %v", val, err) } if isNew { log.Printf("[INFO] Redirecting sink to: %s", wo) log.SetOutput(sll.writer) log.Printf("[INFO] Redirected sink to here (%s)", wo) } } return nil } // CustomLog represents a custom logger configuration. type CustomLog struct { WriterRaw json.RawMessage `json:"writer,omitempty"` EncoderRaw json.RawMessage `json:"encoder,omitempty"` Level string `json:"level,omitempty"` Sampling *LogSampling `json:"sampling,omitempty"` Include []string `json:"include,omitempty"` Exclude []string `json:"exclude,omitempty"` writerOpener WriterOpener writer io.WriteCloser encoder zapcore.Encoder levelEnabler zapcore.LevelEnabler core zapcore.Core } func (cl *CustomLog) provision(ctx Context, logging *Logging) error { // set up the log level switch cl.Level { case "debug": cl.levelEnabler = zapcore.DebugLevel case "", "info": cl.levelEnabler = zapcore.InfoLevel case "warn": cl.levelEnabler = zapcore.WarnLevel case "error": cl.levelEnabler = zapcore.ErrorLevel case "panic": cl.levelEnabler = zapcore.PanicLevel case "fatal": cl.levelEnabler = zapcore.FatalLevel default: return fmt.Errorf("unrecognized log level: %s", cl.Level) } // 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) } } if cl.EncoderRaw != nil { val, err := ctx.LoadModuleInline("format", "caddy.logging.encoders", cl.EncoderRaw) if err != nil { return fmt.Errorf("loading log encoder module: %v", err) } cl.EncoderRaw = nil // allow GC to deallocate cl.encoder = val.(zapcore.Encoder) } if cl.encoder == nil { cl.encoder = zapcore.NewConsoleEncoder(zap.NewProductionEncoderConfig()) } if cl.WriterRaw != nil { val, err := ctx.LoadModuleInline("output", "caddy.logging.writers", cl.WriterRaw) if err != nil { return fmt.Errorf("loading log writer module: %v", err) } cl.WriterRaw = nil // allow GC to deallocate cl.writerOpener = val.(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) } cl.buildCore() return nil } func (cl *CustomLog) 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.NewSampler(c, cl.Sampling.Interval, cl.Sampling.First, cl.Sampling.Thereafter) } cl.core = c } func (cl *CustomLog) matchesModule(moduleName string) bool { return cl.loggerAllowed(moduleName, 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 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 { Interval time.Duration `json:"interval,omitempty"` First int `json:"first,omitempty"` Thereafter int `json:"thereafter,omitempty"` } type ( // StdoutWriter can write logs to stdout. StdoutWriter struct{} // StderrWriter can write logs to stdout. StderrWriter struct{} // DiscardWriter discards all writes. DiscardWriter struct{} ) // CaddyModule returns the Caddy module information. func (StdoutWriter) CaddyModule() ModuleInfo { return ModuleInfo{ Name: "caddy.logging.writers.stdout", New: func() Module { return new(StdoutWriter) }, } } // CaddyModule returns the Caddy module information. func (StderrWriter) CaddyModule() ModuleInfo { return ModuleInfo{ Name: "caddy.logging.writers.stderr", New: func() Module { return new(StderrWriter) }, } } // CaddyModule returns the Caddy module information. func (DiscardWriter) CaddyModule() ModuleInfo { return ModuleInfo{ Name: "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 ioutil.Discard that can't be closed. func (DiscardWriter) OpenWriter() (io.WriteCloser, error) { return notClosable{ioutil.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 } encCfg := zap.NewProductionEncoderConfig() cl.encoder = zapcore.NewConsoleEncoder(encCfg) cl.levelEnabler = zapcore.InfoLevel cl.buildCore() return &defaultCustomLog{ CustomLog: cl, logger: zap.New(cl.core), }, nil } // 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() // Interface guards var ( _ io.WriteCloser = (*notClosable)(nil) _ WriterOpener = (*StdoutWriter)(nil) _ WriterOpener = (*StderrWriter)(nil) )