diff --git a/harness/app.go b/harness/app.go index 05cc315..beb11ad 100644 --- a/harness/app.go +++ b/harness/app.go @@ -15,7 +15,6 @@ import ( "github.com/revel/cmd/model" "github.com/revel/cmd/utils" - "log" ) // App contains the configuration for running a Revel app. (Not for the app itself) @@ -89,7 +88,7 @@ func (cmd AppCmd) Start(c *model.CommandConfig) error { // Run the app server inline. Never returns. func (cmd AppCmd) Run() { - log.Println("Exec app:", "path", cmd.Path, "args", cmd.Args) + utils.Logger.Info("Exec app:", "path", cmd.Path, "args", cmd.Args) if err := cmd.Cmd.Run(); err != nil { utils.Logger.Fatal("Error running:", "error", err) } @@ -97,12 +96,44 @@ func (cmd AppCmd) Run() { // Kill terminates the app server if it's running. func (cmd AppCmd) Kill() { + if cmd.Cmd != nil && (cmd.ProcessState == nil || !cmd.ProcessState.Exited()) { + // Send an interrupt signal to allow for a graceful shutdown utils.Logger.Info("Killing revel server pid", "pid", cmd.Process.Pid) - err := cmd.Process.Kill() + err := cmd.Process.Signal(os.Interrupt) if err != nil { utils.Logger.Fatal("Failed to kill revel server:", "error", err) } + + // Wait for the shutdown + ch := make(chan bool, 1) + go func() { + s, err := cmd.Process.Wait() + defer func() { + ch <- true + }() + if err != nil { + utils.Logger.Info("Wait failed for process ", "error", err) + } + if s != nil { + utils.Logger.Info("Revel App exited", "state", s.String()) + } + }() + + // Use a timer to ensure that the process exits + utils.Logger.Info("Waiting to exit") + select { + case <-ch: + return + case <-time.After(60 * time.Second): + // Kill the process + utils.Logger.Error( + "Revel app failed to exit in 60 seconds - killing.", + "processid", cmd.Process.Pid, + "killerror", cmd.Process.Kill()) + } + + utils.Logger.Info("Done Waiting to exit") } } diff --git a/logger/composite_multihandler.go b/logger/composite_multihandler.go new file mode 100644 index 0000000..fb15e8a --- /dev/null +++ b/logger/composite_multihandler.go @@ -0,0 +1,174 @@ +package logger + +import ( + "github.com/mattn/go-colorable" + "gopkg.in/natefinch/lumberjack.v2" + "io" + "os" +) + +type CompositeMultiHandler struct { + DebugHandler LogHandler + InfoHandler LogHandler + WarnHandler LogHandler + ErrorHandler LogHandler + CriticalHandler LogHandler +} + +func NewCompositeMultiHandler() (*CompositeMultiHandler, LogHandler) { + cw := &CompositeMultiHandler{} + return cw, cw +} +func (h *CompositeMultiHandler) Log(r *Record) (err error) { + + var handler LogHandler + + switch r.Level { + case LvlInfo: + handler = h.InfoHandler + case LvlDebug: + handler = h.DebugHandler + case LvlWarn: + handler = h.WarnHandler + case LvlError: + handler = h.ErrorHandler + case LvlCrit: + handler = h.CriticalHandler + } + + // Embed the caller function in the context + if handler != nil { + handler.Log(r) + } + return +} + +func (h *CompositeMultiHandler) SetHandler(handler LogHandler, replace bool, level LogLevel) { + if handler == nil { + // Ignore empty handler + return + } + source := &h.DebugHandler + switch level { + case LvlDebug: + source = &h.DebugHandler + case LvlInfo: + source = &h.InfoHandler + case LvlWarn: + source = &h.WarnHandler + case LvlError: + source = &h.ErrorHandler + case LvlCrit: + source = &h.CriticalHandler + } + + if !replace && *source != nil { + // If we are not replacing the source make sure that the level handler is applied first + if _, isLevel := (*source).(*LevelFilterHandler); !isLevel { + *source = LevelHandler(level, *source) + } + // If this already was a list add a new logger to it + if ll, found := (*source).(*ListLogHandler); found { + ll.Add(handler) + } else { + *source = NewListLogHandler(*source, handler) + } + } else { + *source = handler + } +} + +// For the multi handler set the handler, using the LogOptions defined +func (h *CompositeMultiHandler) SetHandlers(handler LogHandler, options *LogOptions) { + if len(options.Levels) == 0 { + options.Levels = LvlAllList + } + + // Set all levels + for _, lvl := range options.Levels { + h.SetHandler(handler, options.ReplaceExistingHandler, lvl) + } + +} +func (h *CompositeMultiHandler) SetJson(writer io.Writer, options *LogOptions) { + handler := CallerFileHandler(StreamHandler(writer, JsonFormatEx( + options.GetBoolDefault("pretty", false), + options.GetBoolDefault("lineSeparated", true), + ))) + if options.HandlerWrap != nil { + handler = options.HandlerWrap.SetChild(handler) + } + h.SetHandlers(handler, options) +} + +// Use built in rolling function +func (h *CompositeMultiHandler) SetJsonFile(filePath string, options *LogOptions) { + writer := &lumberjack.Logger{ + Filename: filePath, + MaxSize: options.GetIntDefault("maxSizeMB", 1024), // megabytes + MaxAge: options.GetIntDefault("maxAgeDays", 7), //days + MaxBackups: options.GetIntDefault("maxBackups", 7), + Compress: options.GetBoolDefault("compress", true), + } + h.SetJson(writer, options) +} + +func (h *CompositeMultiHandler) SetTerminal(writer io.Writer, options *LogOptions) { + streamHandler := StreamHandler( + writer, + TerminalFormatHandler( + options.GetBoolDefault("noColor", false), + options.GetBoolDefault("smallDate", true))) + + if os.Stdout == writer { + streamHandler = StreamHandler( + colorable.NewColorableStdout(), + TerminalFormatHandler( + options.GetBoolDefault("noColor", false), + options.GetBoolDefault("smallDate", true))) + } else if os.Stderr == writer { + streamHandler = StreamHandler( + colorable.NewColorableStderr(), + TerminalFormatHandler( + options.GetBoolDefault("noColor", false), + options.GetBoolDefault("smallDate", true))) + } + handler := CallerFileHandler(streamHandler) + + if options.HandlerWrap != nil { + handler = options.HandlerWrap.SetChild(handler) + } + h.SetHandlers(handler, options) +} + +// Use built in rolling function +func (h *CompositeMultiHandler) SetTerminalFile(filePath string, options *LogOptions) { + writer := &lumberjack.Logger{ + Filename: filePath, + MaxSize: options.GetIntDefault("maxSizeMB", 1024), // megabytes + MaxAge: options.GetIntDefault("maxAgeDays", 7), //days + MaxBackups: options.GetIntDefault("maxBackups", 7), + Compress: options.GetBoolDefault("compress", true), + } + h.SetTerminal(writer, options) +} + +func (h *CompositeMultiHandler) Disable(levels ...LogLevel) { + if len(levels) == 0 { + levels = LvlAllList + } + for _, level := range levels { + switch level { + case LvlDebug: + h.DebugHandler = nil + case LvlInfo: + h.InfoHandler = nil + case LvlWarn: + h.WarnHandler = nil + case LvlError: + h.ErrorHandler = nil + case LvlCrit: + h.CriticalHandler = nil + } + } +} diff --git a/logger/doc.go b/logger/doc.go index 7cd8296..0f6156a 100644 --- a/logger/doc.go +++ b/logger/doc.go @@ -3,8 +3,13 @@ These facilities all currently use the logging library called log15 at https://github.com/inconshreveable/log15 - Wrappers for the handlers are written here to provide a kind of isolation layer for Revel - in case sometime in the future we would like to switch to another source to implement logging + Defining handlers happens as follows + 1) ALL handlers (log.all.output) replace any existing handlers + 2) Output handlers (log.error.output) replace any existing handlers + 3) Filter handlers (log.xxx.filter, log.xxx.nfilter) append to existing handlers, + note log.all.filter is treated as a filter handler, so it will NOT replace existing ones + + */ package logger diff --git a/logger/handlers.go b/logger/handlers.go index e60a626..dee850e 100644 --- a/logger/handlers.go +++ b/logger/handlers.go @@ -1,82 +1,93 @@ package logger import ( + "fmt" "io" - "os" - - colorable "github.com/mattn/go-colorable" - "github.com/revel/log15" - "gopkg.in/natefinch/lumberjack.v2" ) +type LevelFilterHandler struct { + Level LogLevel + h LogHandler +} + // Filters out records which do not match the level // Uses the `log15.FilterHandler` to perform this task func LevelHandler(lvl LogLevel, h LogHandler) LogHandler { - l15Lvl := log15.Lvl(lvl) - return log15.FilterHandler(func(r *log15.Record) (pass bool) { - return r.Lvl == l15Lvl - }, h) + return &LevelFilterHandler{lvl, h} +} + +// The implementation of the Log +func (h LevelFilterHandler) Log(r *Record) error { + if r.Level == h.Level { + return h.h.Log(r) + } + return nil } // Filters out records which do not match the level // Uses the `log15.FilterHandler` to perform this task func MinLevelHandler(lvl LogLevel, h LogHandler) LogHandler { - l15Lvl := log15.Lvl(lvl) - return log15.FilterHandler(func(r *log15.Record) (pass bool) { - return r.Lvl <= l15Lvl + return FilterHandler(func(r *Record) (pass bool) { + return r.Level <= lvl }, h) } // Filters out records which match the level // Uses the `log15.FilterHandler` to perform this task func NotLevelHandler(lvl LogLevel, h LogHandler) LogHandler { - l15Lvl := log15.Lvl(lvl) - return log15.FilterHandler(func(r *log15.Record) (pass bool) { - return r.Lvl != l15Lvl + return FilterHandler(func(r *Record) (pass bool) { + return r.Level != lvl }, h) } -// Adds in a context called `caller` to the record (contains file name and line number like `foo.go:12`) -// Uses the `log15.CallerFileHandler` to perform this task func CallerFileHandler(h LogHandler) LogHandler { - return log15.CallerFileHandler(h) + return FuncHandler(func(r *Record) error { + r.Context.Add("caller", fmt.Sprint(r.Call)) + return h.Log(r) + }) } // Adds in a context called `caller` to the record (contains file name and line number like `foo.go:12`) // Uses the `log15.CallerFuncHandler` to perform this task func CallerFuncHandler(h LogHandler) LogHandler { - return log15.CallerFuncHandler(h) + return CallerFuncHandler(h) } // Filters out records which match the key value pair // Uses the `log15.MatchFilterHandler` to perform this task func MatchHandler(key string, value interface{}, h LogHandler) LogHandler { - return log15.MatchFilterHandler(key, value, h) + return MatchFilterHandler(key, value, h) +} + +// MatchFilterHandler returns a Handler that only writes records +// to the wrapped Handler if the given key in the logged +// context matches the value. For example, to only log records +// from your ui package: +// +// log.MatchFilterHandler("pkg", "app/ui", log.StdoutHandler) +// +func MatchFilterHandler(key string, value interface{}, h LogHandler) LogHandler { + return FilterHandler(func(r *Record) (pass bool) { + return r.Context[key] == value + }, h) } // If match then A handler is called otherwise B handler is called func MatchAbHandler(key string, value interface{}, a, b LogHandler) LogHandler { - return log15.FuncHandler(func(r *log15.Record) error { - for i := 0; i < len(r.Ctx); i += 2 { - if r.Ctx[i] == key { - if r.Ctx[i+1] == value { - if a != nil { - return a.Log(r) - } - return nil - } - } - } - if b != nil { + return FuncHandler(func(r *Record) error { + if r.Context[key] == value { + return a.Log(r) + } else if b != nil { return b.Log(r) } + return nil }) } // The nil handler is used if logging for a specific request needs to be turned off func NilHandler() LogHandler { - return log15.FuncHandler(func(r *log15.Record) error { + return FuncHandler(func(r *Record) error { return nil }) } @@ -93,80 +104,83 @@ func NotMatchMapHandler(matchMap map[string]interface{}, a LogHandler) LogHandle // Rather then chaining multiple filter handlers, process all here func matchMapHandler(matchMap map[string]interface{}, inverse bool, a LogHandler) LogHandler { - return log15.FuncHandler(func(r *log15.Record) error { - checkMap := map[string]bool{} - // Copy the map to a bool - for i := 0; i < len(r.Ctx); i += 2 { - if value, found := matchMap[r.Ctx[i].(string)]; found && value == r.Ctx[i+1] { - checkMap[r.Ctx[i].(string)] = true + return FuncHandler(func(r *Record) error { + matchCount := 0 + for k, v := range matchMap { + value, found := r.Context[k] + if !found { + return nil + } + // Test for two failure cases + if value == v && inverse || value != v && !inverse { + return nil + } else { + matchCount++ } } - if len(checkMap) == len(matchMap) { - if !inverse { - return a.Log(r) - } - } else if inverse { - return a.Log(r) + if matchCount != len(matchMap) { + return nil } - return nil + return a.Log(r) }) } // Filters out records which do not match the key value pair // Uses the `log15.FilterHandler` to perform this task func NotMatchHandler(key string, value interface{}, h LogHandler) LogHandler { - return log15.FilterHandler(func(r *log15.Record) (pass bool) { - switch key { - case r.KeyNames.Lvl: - return r.Lvl != value - case r.KeyNames.Time: - return r.Time != value - case r.KeyNames.Msg: - return r.Msg != value - } - - for i := 0; i < len(r.Ctx); i += 2 { - if r.Ctx[i] == key { - return r.Ctx[i+1] == value - } - } - return true + return FilterHandler(func(r *Record) (pass bool) { + return r.Context[key] != value }, h) } func MultiHandler(hs ...LogHandler) LogHandler { - // Convert the log handlers to log15.Handlers - handlers := []log15.Handler{} - for _, h := range hs { - if h != nil { - handlers = append(handlers, h) + return FuncHandler(func(r *Record) error { + for _, h := range hs { + // what to do about failures? + h.Log(r) } - } - - return log15.MultiHandler(handlers...) + return nil + }) } -// Outputs the records to the passed in stream -// Uses the `log15.StreamHandler` to perform this task +// StreamHandler writes log records to an io.Writer +// with the given format. StreamHandler can be used +// to easily begin writing log records to other +// outputs. +// +// StreamHandler wraps itself with LazyHandler and SyncHandler +// to evaluate Lazy objects and perform safe concurrent writes. func StreamHandler(wr io.Writer, fmtr LogFormat) LogHandler { - return log15.StreamHandler(wr, fmtr) + h := FuncHandler(func(r *Record) error { + _, err := wr.Write(fmtr.Format(r)) + return err + }) + return LazyHandler(SyncHandler(h)) } -// Filter handler, this is the only -// Uses the `log15.FilterHandler` to perform this task -func FilterHandler(fn func(r *log15.Record) bool, h LogHandler) LogHandler { - return log15.FilterHandler(fn, h) +// Filter handler +func FilterHandler(fn func(r *Record) bool, h LogHandler) LogHandler { + return FuncHandler(func(r *Record) error { + if fn(r) { + return h.Log(r) + } + return nil + }) } +// List log handler handles a list of LogHandlers type ListLogHandler struct { handlers []LogHandler } +// Create a new list of log handlers func NewListLogHandler(h1, h2 LogHandler) *ListLogHandler { ll := &ListLogHandler{handlers: []LogHandler{h1, h2}} return ll } -func (ll *ListLogHandler) Log(r *log15.Record) (err error) { + +// Log the record +func (ll *ListLogHandler) Log(r *Record) (err error) { for _, handler := range ll.handlers { if err == nil { err = handler.Log(r) @@ -176,11 +190,15 @@ func (ll *ListLogHandler) Log(r *log15.Record) (err error) { } return } + +// Add another log handler func (ll *ListLogHandler) Add(h LogHandler) { if h != nil { ll.handlers = append(ll.handlers, h) } } + +// Remove a log handler func (ll *ListLogHandler) Del(h LogHandler) { if h != nil { for i, handler := range ll.handlers { @@ -190,161 +208,3 @@ func (ll *ListLogHandler) Del(h LogHandler) { } } } - -type CompositeMultiHandler struct { - DebugHandler LogHandler - InfoHandler LogHandler - WarnHandler LogHandler - ErrorHandler LogHandler - CriticalHandler LogHandler -} - -func NewCompositeMultiHandler() (*CompositeMultiHandler, LogHandler) { - cw := &CompositeMultiHandler{} - return cw, cw -} -func (h *CompositeMultiHandler) Log(r *log15.Record) (err error) { - - var handler LogHandler - switch r.Lvl { - case log15.LvlInfo: - handler = h.InfoHandler - case log15.LvlDebug: - handler = h.DebugHandler - case log15.LvlWarn: - handler = h.WarnHandler - case log15.LvlError: - handler = h.ErrorHandler - case log15.LvlCrit: - handler = h.CriticalHandler - } - - // Embed the caller function in the context - if handler != nil { - handler.Log(r) - } - return -} -func (h *CompositeMultiHandler) SetHandler(handler LogHandler, replace bool, level LogLevel) { - if handler == nil { - // Ignore empty handler - return - } - source := &h.DebugHandler - switch level { - case LvlDebug: - source = &h.DebugHandler - case LvlInfo: - source = &h.InfoHandler - case LvlWarn: - source = &h.WarnHandler - case LvlError: - source = &h.ErrorHandler - case LvlCrit: - source = &h.CriticalHandler - } - - if !replace && *source != nil { - // If this already was a list add a new logger to it - if ll, found := (*source).(*ListLogHandler); found { - ll.Add(handler) - } else { - *source = NewListLogHandler(*source, handler) - } - } else { - *source = handler - } -} - -func (h *CompositeMultiHandler) SetHandlers(handler LogHandler, options *LogOptions) { - if len(options.Levels) == 0 { - options.Levels = LvlAllList - } - // Set all levels - for _, lvl := range options.Levels { - h.SetHandler(handler, options.ReplaceExistingHandler, lvl) - } - -} -func (h *CompositeMultiHandler) SetJson(writer io.Writer, options *LogOptions) { - handler := CallerFileHandler(StreamHandler(writer, log15.JsonFormatEx( - options.GetBoolDefault("pretty", false), - options.GetBoolDefault("lineSeparated", true), - ))) - if options.HandlerWrap != nil { - handler = options.HandlerWrap.SetChild(handler) - } - h.SetHandlers(handler, options) -} - -// Use built in rolling function -func (h *CompositeMultiHandler) SetJsonFile(filePath string, options *LogOptions) { - writer := &lumberjack.Logger{ - Filename: filePath, - MaxSize: options.GetIntDefault("maxSizeMB", 1024), // megabytes - MaxAge: options.GetIntDefault("maxAgeDays", 7), //days - MaxBackups: options.GetIntDefault("maxBackups", 7), - Compress: options.GetBoolDefault("compress", true), - } - h.SetJson(writer, options) -} - -func (h *CompositeMultiHandler) SetTerminal(writer io.Writer, options *LogOptions) { - streamHandler := StreamHandler( - writer, - TerminalFormatHandler( - options.GetBoolDefault("noColor", false), - options.GetBoolDefault("smallDate", true))) - - if os.Stdout == writer { - streamHandler = StreamHandler( - colorable.NewColorableStdout(), - TerminalFormatHandler( - options.GetBoolDefault("noColor", false), - options.GetBoolDefault("smallDate", true))) - } else if os.Stderr == writer { - streamHandler = StreamHandler( - colorable.NewColorableStderr(), - TerminalFormatHandler( - options.GetBoolDefault("noColor", false), - options.GetBoolDefault("smallDate", true))) - } - - handler := CallerFileHandler(streamHandler) - if options.HandlerWrap != nil { - handler = options.HandlerWrap.SetChild(handler) - } - h.SetHandlers(handler, options) -} - -// Use built in rolling function -func (h *CompositeMultiHandler) SetTerminalFile(filePath string, options *LogOptions) { - writer := &lumberjack.Logger{ - Filename: filePath, - MaxSize: options.GetIntDefault("maxSizeMB", 1024), // megabytes - MaxAge: options.GetIntDefault("maxAgeDays", 7), //days - MaxBackups: options.GetIntDefault("maxBackups", 7), - Compress: options.GetBoolDefault("compress", true), - } - h.SetTerminal(writer, options) -} - -func (h *CompositeMultiHandler) Disable(levels ...LogLevel) { - if len(levels) == 0 { - levels = LvlAllList - } - for _, level := range levels { - switch level { - case LvlDebug: - h.DebugHandler = nil - case LvlInfo: - h.InfoHandler = nil - case LvlWarn: - h.WarnHandler = nil - case LvlError: - h.ErrorHandler = nil - case LvlCrit: - h.CriticalHandler = nil - } - } -} diff --git a/logger/init.go b/logger/init.go new file mode 100644 index 0000000..6a02cf8 --- /dev/null +++ b/logger/init.go @@ -0,0 +1,189 @@ +package logger + +// Get all handlers based on the Config (if available) +import ( + "fmt" + "github.com/revel/config" + "log" + "os" + "path/filepath" + "strings" +) + +func InitializeFromConfig(basePath string, config *config.Context) (c *CompositeMultiHandler) { + // If running in test mode suppress anything that is not an error + if config != nil && config.BoolDefault(TEST_MODE_FLAG, false) { + // Preconfigure all the options + config.SetOption("log.info.output", "none") + config.SetOption("log.debug.output", "none") + config.SetOption("log.warn.output", "none") + config.SetOption("log.error.output", "stderr") + config.SetOption("log.crit.output", "stderr") + } + + // If the configuration has an all option we can skip some + c, _ = NewCompositeMultiHandler() + + // Filters are assigned first, non filtered items override filters + if config != nil && !config.BoolDefault(TEST_MODE_FLAG, false) { + initAllLog(c, basePath, config) + } + initLogLevels(c, basePath, config) + if c.CriticalHandler == nil && c.ErrorHandler != nil { + c.CriticalHandler = c.ErrorHandler + } + if config != nil && !config.BoolDefault(TEST_MODE_FLAG, false) { + initFilterLog(c, basePath, config) + if c.CriticalHandler == nil && c.ErrorHandler != nil { + c.CriticalHandler = c.ErrorHandler + } + initRequestLog(c, basePath, config) + } + + return c +} + +// Init the log.all configuration options +func initAllLog(c *CompositeMultiHandler, basePath string, config *config.Context) { + if config != nil { + extraLogFlag := config.BoolDefault(SPECIAL_USE_FLAG, false) + if output, found := config.String("log.all.output"); found { + // Set all output for the specified handler + if extraLogFlag { + log.Printf("Adding standard handler for levels to >%s< ", output) + } + initHandlerFor(c, output, basePath, NewLogOptions(config, true, nil, LvlAllList...)) + } + } +} + +// Init the filter options +// log.all.filter .... +// log.error.filter .... +func initFilterLog(c *CompositeMultiHandler, basePath string, config *config.Context) { + + if config != nil { + extraLogFlag := config.BoolDefault(SPECIAL_USE_FLAG, false) + + for _, logFilter := range logFilterList { + // Init for all filters + for _, name := range []string{"all", "debug", "info", "warn", "error", "crit", + "trace", // TODO trace is deprecated + } { + optionList := config.Options(logFilter.LogPrefix + name + logFilter.LogSuffix) + for _, option := range optionList { + splitOptions := strings.Split(option, ".") + keyMap := map[string]interface{}{} + for x := 3; x < len(splitOptions); x += 2 { + keyMap[splitOptions[x]] = splitOptions[x+1] + } + phandler := logFilter.parentHandler(keyMap) + if extraLogFlag { + log.Printf("Adding key map handler %s %s output %s", option, name, config.StringDefault(option, "")) + fmt.Printf("Adding key map handler %s %s output %s matching %#v\n", option, name, config.StringDefault(option, ""), keyMap) + } + + if name == "all" { + initHandlerFor(c, config.StringDefault(option, ""), basePath, NewLogOptions(config, false, phandler)) + } else { + initHandlerFor(c, config.StringDefault(option, ""), basePath, NewLogOptions(config, false, phandler, toLevel[name])) + } + } + } + } + } +} + +// Init the log.error, log.warn etc configuration options +func initLogLevels(c *CompositeMultiHandler, basePath string, config *config.Context) { + for _, name := range []string{"debug", "info", "warn", "error", "crit", + "trace", // TODO trace is deprecated + } { + if config != nil { + extraLogFlag := config.BoolDefault(SPECIAL_USE_FLAG, false) + output, found := config.String("log." + name + ".output") + if found { + if extraLogFlag { + log.Printf("Adding standard handler %s output %s", name, output) + } + initHandlerFor(c, output, basePath, NewLogOptions(config, true, nil, toLevel[name])) + } + // Gets the list of options with said prefix + } else { + initHandlerFor(c, "stderr", basePath, NewLogOptions(config, true, nil, toLevel[name])) + } + } +} + +// Init the request log options +func initRequestLog(c *CompositeMultiHandler, basePath string, config *config.Context) { + // Request logging to a separate output handler + // This takes the InfoHandlers and adds a MatchAbHandler handler to it to direct + // context with the word "section=requestlog" to that handler. + // Note if request logging is not enabled the MatchAbHandler will not be added and the + // request log messages will be sent out the INFO handler + outputRequest := "stdout" + if config != nil { + outputRequest = config.StringDefault("log.request.output", "") + } + oldInfo := c.InfoHandler + c.InfoHandler = nil + if outputRequest != "" { + initHandlerFor(c, outputRequest, basePath, NewLogOptions(config, false, nil, LvlInfo)) + } + if c.InfoHandler != nil || oldInfo != nil { + if c.InfoHandler == nil { + c.InfoHandler = oldInfo + } else { + c.InfoHandler = MatchAbHandler("section", "requestlog", c.InfoHandler, oldInfo) + } + } +} + +// Returns a handler for the level using the output string +// Accept formats for output string are +// LogFunctionMap[value] callback function +// `stdout` `stderr` `full/file/path/to/location/app.log` `full/file/path/to/location/app.json` +func initHandlerFor(c *CompositeMultiHandler, output, basePath string, options *LogOptions) { + if options.Ctx != nil { + options.SetExtendedOptions( + "noColor", !options.Ctx.BoolDefault("log.colorize", true), + "smallDate", options.Ctx.BoolDefault("log.smallDate", true), + "maxSize", options.Ctx.IntDefault("log.maxsize", 1024*10), + "maxAge", options.Ctx.IntDefault("log.maxage", 14), + "maxBackups", options.Ctx.IntDefault("log.maxbackups", 14), + "compressBackups", !options.Ctx.BoolDefault("log.compressBackups", true), + ) + } + + output = strings.TrimSpace(output) + if funcHandler, found := LogFunctionMap[output]; found { + funcHandler(c, options) + } else { + switch output { + case "": + fallthrough + case "off": + // No handler, discard data + default: + // Write to file specified + if !filepath.IsAbs(output) { + output = filepath.Join(basePath, output) + } + + if err := os.MkdirAll(filepath.Dir(output), 0755); err != nil { + log.Panic(err) + } + + if strings.HasSuffix(output, "json") { + c.SetJsonFile(output, options) + } else { + // Override defaults for a terminal file + options.SetExtendedOptions("noColor", true) + options.SetExtendedOptions("smallDate", false) + c.SetTerminalFile(output, options) + } + } + } + return +} diff --git a/logger/init_test.go b/logger/init_test.go new file mode 100644 index 0000000..50fcd61 --- /dev/null +++ b/logger/init_test.go @@ -0,0 +1,273 @@ +// Copyright (c) 2012-2018 The Revel Framework Authors, All rights reserved. +// Revel Framework source code and usage is governed by a MIT style +// license that can be found in the LICENSE file. + +package logger_test + +import ( + "github.com/revel/config" + "github.com/revel/revel/logger" + "github.com/stretchr/testify/assert" + "os" + "strings" + "testing" +) + +type ( + // A counter for the tester + testCounter struct { + debug, info, warn, error, critical int + } + // The data to tes + testData struct { + config []string + result testResult + tc *testCounter + } + // The test result + testResult struct { + debug, info, warn, error, critical int + } +) + +// Single test cases +var singleCases = []testData{ + {config: []string{"log.crit.output"}, + result: testResult{0, 0, 0, 0, 1}}, + {config: []string{"log.error.output"}, + result: testResult{0, 0, 0, 1, 1}}, + {config: []string{"log.warn.output"}, + result: testResult{0, 0, 1, 0, 0}}, + {config: []string{"log.info.output"}, + result: testResult{0, 1, 0, 0, 0}}, + {config: []string{"log.debug.output"}, + result: testResult{1, 0, 0, 0, 0}}, +} + +// Test singles +func TestSingleCases(t *testing.T) { + rootLog := logger.New() + for _, testCase := range singleCases { + testCase.logTest(rootLog, t) + testCase.validate(t) + } +} + +// Filter test cases +var filterCases = []testData{ + {config: []string{"log.crit.filter.module.app"}, + result: testResult{0, 0, 0, 0, 1}}, + {config: []string{"log.crit.filter.module.appa"}, + result: testResult{0, 0, 0, 0, 0}}, + {config: []string{"log.error.filter.module.app"}, + result: testResult{0, 0, 0, 1, 1}}, + {config: []string{"log.error.filter.module.appa"}, + result: testResult{0, 0, 0, 0, 0}}, + {config: []string{"log.warn.filter.module.app"}, + result: testResult{0, 0, 1, 0, 0}}, + {config: []string{"log.warn.filter.module.appa"}, + result: testResult{0, 0, 0, 0, 0}}, + {config: []string{"log.info.filter.module.app"}, + result: testResult{0, 1, 0, 0, 0}}, + {config: []string{"log.info.filter.module.appa"}, + result: testResult{0, 0, 0, 0, 0}}, + {config: []string{"log.debug.filter.module.app"}, + result: testResult{1, 0, 0, 0, 0}}, + {config: []string{"log.debug.filter.module.appa"}, + result: testResult{0, 0, 0, 0, 0}}, +} + +// Filter test +func TestFilterCases(t *testing.T) { + rootLog := logger.New("module", "app") + for _, testCase := range filterCases { + testCase.logTest(rootLog, t) + testCase.validate(t) + } +} + +// Inverse test cases +var nfilterCases = []testData{ + {config: []string{"log.crit.nfilter.module.appa"}, + result: testResult{0, 0, 0, 0, 1}}, + {config: []string{"log.crit.nfilter.modules.appa"}, + result: testResult{0, 0, 0, 0, 0}}, + {config: []string{"log.crit.nfilter.module.app"}, + result: testResult{0, 0, 0, 0, 0}}, + {config: []string{"log.error.nfilter.module.appa"}, // Special case, when error is not nill critical inherits from error + result: testResult{0, 0, 0, 1, 1}}, + {config: []string{"log.error.nfilter.module.app"}, + result: testResult{0, 0, 0, 0, 0}}, + {config: []string{"log.warn.nfilter.module.appa"}, + result: testResult{0, 0, 1, 0, 0}}, + {config: []string{"log.warn.nfilter.module.app"}, + result: testResult{0, 0, 0, 0, 0}}, + {config: []string{"log.info.nfilter.module.appa"}, + result: testResult{0, 1, 0, 0, 0}}, + {config: []string{"log.info.nfilter.module.app"}, + result: testResult{0, 0, 0, 0, 0}}, + {config: []string{"log.debug.nfilter.module.appa"}, + result: testResult{1, 0, 0, 0, 0}}, + {config: []string{"log.debug.nfilter.module.app"}, + result: testResult{0, 0, 0, 0, 0}}, +} + +// Inverse test +func TestNotFilterCases(t *testing.T) { + rootLog := logger.New("module", "app") + for _, testCase := range nfilterCases { + testCase.logTest(rootLog, t) + testCase.validate(t) + } +} + +// off test cases +var offCases = []testData{ + {config: []string{"log.all.output", "log.error.output=off"}, + result: testResult{1, 1, 1, 0, 1}}, +} + +// Off test +func TestOffCases(t *testing.T) { + rootLog := logger.New("module", "app") + for _, testCase := range offCases { + testCase.logTest(rootLog, t) + testCase.validate(t) + } +} + +// Duplicate test cases +var duplicateCases = []testData{ + {config: []string{"log.all.output", "log.error.output", "log.error.filter.module.app"}, + result: testResult{1, 1, 1, 2, 1}}, +} + +// test duplicate cases +func TestDuplicateCases(t *testing.T) { + rootLog := logger.New("module", "app") + for _, testCase := range duplicateCases { + testCase.logTest(rootLog, t) + testCase.validate(t) + } +} + +// Contradicting cases +var contradictCases = []testData{ + {config: []string{"log.all.output", "log.error.output=off", "log.all.output"}, + result: testResult{1, 1, 1, 0, 1}}, + {config: []string{"log.all.output", "log.error.output=off", "log.debug.filter.module.app"}, + result: testResult{2, 1, 1, 0, 1}}, + {config: []string{"log.all.filter.module.app", "log.info.output=off", "log.info.filter.module.app"}, + result: testResult{1, 2, 1, 1, 1}}, + {config: []string{"log.all.output", "log.info.output=off", "log.info.filter.module.app"}, + result: testResult{1, 1, 1, 1, 1}}, +} + +// Contradiction test +func TestContradictCases(t *testing.T) { + rootLog := logger.New("module", "app") + for _, testCase := range contradictCases { + testCase.logTest(rootLog, t) + testCase.validate(t) + } +} + +// All test cases +var allCases = []testData{ + {config: []string{"log.all.filter.module.app"}, + result: testResult{1, 1, 1, 1, 1}}, + {config: []string{"log.all.output"}, + result: testResult{2, 2, 2, 2, 2}}, +} + +// All tests +func TestAllCases(t *testing.T) { + rootLog := logger.New("module", "app") + for i, testCase := range allCases { + testCase.logTest(rootLog, t) + allCases[i] = testCase + } + rootLog = logger.New() + for i, testCase := range allCases { + testCase.logTest(rootLog, t) + allCases[i] = testCase + } + for _, testCase := range allCases { + testCase.validate(t) + } + +} + +func (c *testCounter) Log(r *logger.Record) error { + switch r.Level { + case logger.LvlDebug: + c.debug++ + case logger.LvlInfo: + c.info++ + case logger.LvlWarn: + c.warn++ + case logger.LvlError: + c.error++ + case logger.LvlCrit: + c.critical++ + default: + panic("Unknown log level") + } + return nil +} +func (td *testData) logTest(rootLog logger.MultiLogger, t *testing.T) { + if td.tc == nil { + td.tc = &testCounter{} + counterInit(td.tc) + } + newContext := config.NewContext() + for _, i := range td.config { + iout := strings.Split(i, "=") + if len(iout) > 1 { + newContext.SetOption(iout[0], iout[1]) + } else { + newContext.SetOption(i, "test") + } + } + + newContext.SetOption("specialUseFlag", "true") + + handler := logger.InitializeFromConfig("test", newContext) + + rootLog.SetHandler(handler) + + td.runLogTest(rootLog) +} + +func (td *testData) runLogTest(log logger.MultiLogger) { + log.Debug("test") + log.Info("test") + log.Warn("test") + log.Error("test") + log.Crit("test") +} + +func (td *testData) validate(t *testing.T) { + t.Logf("Test %#v expected %#v", td.tc, td.result) + assert.Equal(t, td.result.debug, td.tc.debug, "Debug failed "+strings.Join(td.config, " ")) + assert.Equal(t, td.result.info, td.tc.info, "Info failed "+strings.Join(td.config, " ")) + assert.Equal(t, td.result.warn, td.tc.warn, "Warn failed "+strings.Join(td.config, " ")) + assert.Equal(t, td.result.error, td.tc.error, "Error failed "+strings.Join(td.config, " ")) + assert.Equal(t, td.result.critical, td.tc.critical, "Critical failed "+strings.Join(td.config, " ")) +} + +// Add test to the function map +func counterInit(tc *testCounter) { + logger.LogFunctionMap["test"] = func(c *logger.CompositeMultiHandler, logOptions *logger.LogOptions) { + // Output to the test log and the stdout + outHandler := logger.LogHandler( + logger.NewListLogHandler(tc, + logger.StreamHandler(os.Stdout, logger.TerminalFormatHandler(false, true))), + ) + if logOptions.HandlerWrap != nil { + outHandler = logOptions.HandlerWrap.SetChild(outHandler) + } + + c.SetHandlers(outHandler, logOptions) + } +} diff --git a/logger/log.go.old b/logger/log.go.old deleted file mode 100644 index 3a65852..0000000 --- a/logger/log.go.old +++ /dev/null @@ -1,656 +0,0 @@ -package logger - - -// LoggedError is wrapper to differentiate logged panics from unexpected ones. -import ( - "os" - "fmt" - "strings" - "go.uber.org/zap" - "go.uber.org/zap/zapcore" - "sync" - "go.uber.org/zap/buffer" - "time" - "encoding/base64" - "unicode/utf8" - "encoding/json" - "math" - - "io" -) - -type ( - MultiLogger interface { - //log15.Logger - //// New returns a new Logger that has this logger's context plus the given context - New(ctx ...interface{}) MultiLogger - // - // The encoders job is to encode the - SetHandler(h LogHandler) - SetStackDepth(int) MultiLogger - // - //// Log a message at the given level with context key/value pairs - Debug(msg string, ctx ...interface{}) - Debugf(msg string, params ...interface{}) - Info(msg string, ctx ...interface{}) - Infof(msg string, params ...interface{}) - Warn(msg string, ctx ...interface{}) - Warnf(msg string, params ...interface{}) - Error(msg string, ctx ...interface{}) - Errorf(msg string, params ...interface{}) - Crit(msg string, ctx ...interface{}) - Critf(msg string, params ...interface{}) - - //// Logs a message as an Crit and exits - Fatal(msg string, ctx ...interface{}) - Fatalf(msg string, params ...interface{}) - //// Logs a message as an Crit and panics - Panic(msg string, ctx ...interface{}) - Panicf(msg string, params ...interface{}) - } - - // The log han - LogHandler interface { - Encode(Record) ([]byte, error) - GetLevel() Level - GetWriter() io.Writer - } - - // The Record - Record struct { - Level Level - Time time.Time - LoggerName string - Message string - Caller EntryCaller - Stack string - Context []Field -} - - // The fields passed in - Field interface { - GetKey() string - GetValueAsString() string - GetValue() interface{} - } - - EntryCaller interface { - IsDefined() bool - GetPC() uintptr - GetFile() string - GetLine() int - } - - // Called only if the logger needs - ResolveLaterLogger func() interface{} - - FieldType int - Level int -) - -type ( - zapLogger struct { - logger *zap.SugaredLogger - coreList []*zapcore.Core - } - zapField struct { - Key string - Type FieldType - Integer int64 - String string - Interface interface{} - } - zapEntryCaller struct { - Defined bool - PC uintptr - File string - Line int - } - zapEncoder struct { - lh LogHandler - } -) - -func newLogger(addCaller bool) MultiLogger { - logger := zap.New(nil).WithOptions(zap.AddCaller()) - l := &zapLogger{logger:logger.Sugar()} - - return l -} - -// It is up to the handler to determine the synchronization to the output -// streams -func (z *zapLogger) SetHandler(lh LogHandler) { - // Swap out the logger when a new handler is attached - encoder := &zapEncoder{lh} - levelHandler := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool { - return lvl >= zapcore.Level(lh.GetLevel()) - }) - logger := zap.New(zapcore.NewCore(encoder, nil, levelHandler)).WithOptions(zap.AddCaller()) - Logger.With("foo","bar").Desugar().Core() -} - -var Logger *zap.SugaredLogger - -func InitLogger(logLevel zapcore.Level) { - config :=zap.NewDevelopmentEncoderConfig() - config.EncodeLevel = zapcore.CapitalColorLevelEncoder - - consoleEncoder := NewConsoleEncoder(config) - lowPriority := zap.LevelEnablerFunc(func(lvl zapcore.Level) bool { - return lvl >= logLevel - }) - - consoleDebugging := zapcore.Lock(os.Stdout) - core := zapcore.NewTee( - zapcore.NewCore(consoleEncoder, consoleDebugging, lowPriority), - ) - logger := zap.New(core).WithOptions(zap.AddCaller()) - Logger = logger.Sugar() -} -type LoggedError struct{ error } - -func NewLoggedError(err error) *LoggedError { - return &LoggedError{err} -} - -func Errorf(format string, args ...interface{}) { - // Ensure the user's command prompt starts on the next line. - if !strings.HasSuffix(format, "\n") { - format += "\n" - } - fmt.Fprintf(os.Stderr, format, args...) - panic(format) // Panic instead of os.Exit so that deferred will run. -} - - - -// This is all for the Console logger - a little wordy but it works - -var _sliceEncoderPool = sync.Pool{ - New: func() interface{} { - return &sliceArrayEncoder{elems: make([]interface{}, 0, 2)} - }, -} - -func getSliceEncoder() *sliceArrayEncoder { - return _sliceEncoderPool.Get().(*sliceArrayEncoder) -} - -func putSliceEncoder(e *sliceArrayEncoder) { - e.elems = e.elems[:0] - _sliceEncoderPool.Put(e) -} - -type consoleEncoder struct { - *zapcore.EncoderConfig - openNamespaces int - buf *buffer.Buffer - reflectBuf *buffer.Buffer - reflectEnc *json.Encoder -} - -var ( - _pool = buffer.NewPool() - // Get retrieves a buffer from the pool, creating one if necessary. - Get = _pool.Get -) - - -// NewConsoleEncoder creates an encoder whose output is designed for human - -// rather than machine - consumption. It serializes the core log entry data -// (message, level, timestamp, etc.) in a plain-text format and leaves the -// structured context as JSON. -// -// Note that although the console encoder doesn't use the keys specified in the -// encoder configuration, it will omit any element whose key is set to the empty -// string. -func NewConsoleEncoder(cfg zapcore.EncoderConfig) zapcore.Encoder { - ec := &consoleEncoder{buf : Get(), reflectBuf: Get()} - ec.EncoderConfig = &cfg - return ec -} - -func (c consoleEncoder) Clone() zapcore.Encoder { - return &consoleEncoder{buf : Get(), reflectBuf: Get()} -} - -func (c consoleEncoder) EncodeEntry(ent zapcore.Entry, fields []zapcore.Field) (*buffer.Buffer, error) { - line := Get() - - var color = 0 - switch ent.Level { - case zap.PanicLevel: - // Magenta - color = 35 - case zap.ErrorLevel: - // Red - color = 31 - case zap.WarnLevel: - // Yellow - color = 33 - case zap.InfoLevel: - // Green - color = 32 - case zap.DebugLevel: - // Cyan - color = 36 - } - - // We don't want the entry's metadata to be quoted and escaped (if it's - // encoded as strings), which means that we can't use the JSON encoder. The - // simplest option is to use the memory encoder and fmt.Fprint. - // - // If this ever becomes a performance bottleneck, we can implement - // ArrayEncoder for our plain-text format. - arr := getSliceEncoder() - if c.LevelKey != "" && c.EncodeLevel != nil { - arr.AppendString(fmt.Sprintf("\x1b[%dm%-5s\x1b[0m",color,ent.Level.CapitalString())) - } - if ent.LoggerName != "" && c.NameKey != "" { - nameEncoder := c.EncodeName - - if nameEncoder == nil { - // Fall back to FullNameEncoder for backward compatibility. - nameEncoder = zapcore.FullNameEncoder - } - - nameEncoder(ent.LoggerName, arr) - } - if c.TimeKey != "" && c.EncodeTime != nil { - arr.AppendString(ent.Time.Format("15:04:05")) - } - - if ent.Caller.Defined && c.CallerKey != "" && c.EncodeCaller != nil { - c.EncodeCaller(ent.Caller, arr) - } - for i := range arr.elems { - if i > 0 { - line.AppendByte(' ') - } - fmt.Fprint(line, arr.elems[i]) - } - putSliceEncoder(arr) - - // Add the message itself. - if c.MessageKey != "" { - c.addTabIfNecessary(line) - line.AppendString(ent.Message) - } - - // Add any structured context. - c.writeContext(line, fields) - - // If there's no stacktrace key, honor that; this allows users to force - // single-line output. - if ent.Stack != "" && c.StacktraceKey != "" { - line.AppendByte('\n') - line.AppendString(ent.Stack) - } - - if c.LineEnding != "" { - line.AppendString(c.LineEnding) - } else { - line.AppendString(zapcore.DefaultLineEnding) - } - return line, nil -} - -func (c consoleEncoder) writeContext(line *buffer.Buffer, extra []zapcore.Field) { - context := c.Clone().(*consoleEncoder) - defer context.buf.Free() - // - addFields(context, extra) - context.closeOpenNamespaces() - if context.buf.Len() == 0 { - return - } - // - line.Write(context.buf.Bytes()) -} -func addFields(enc zapcore.ObjectEncoder, fields []zapcore.Field) { - for i := range fields { - fields[i].AddTo(enc) - } -} - - -func (c consoleEncoder) addTabIfNecessary(line *buffer.Buffer) { - if line.Len() > 0 { - line.AppendByte('\t') - } -} - - -func (enc *consoleEncoder) AddArray(key string, arr zapcore.ArrayMarshaler) error { - enc.addKey(key) - return enc.AppendArray(arr) -} - -func (enc *consoleEncoder) AddObject(key string, obj zapcore.ObjectMarshaler) error { - enc.addKey(key) - return enc.AppendObject(obj) -} - -func (enc *consoleEncoder) AddBinary(key string, val []byte) { - enc.AddString(key, base64.StdEncoding.EncodeToString(val)) -} - -func (enc *consoleEncoder) AddByteString(key string, val []byte) { - enc.addKey(key) - enc.AppendByteString(val) -} - -func (enc *consoleEncoder) AddBool(key string, val bool) { - enc.addKey(key) - enc.AppendBool(val) -} - -func (enc *consoleEncoder) AddComplex128(key string, val complex128) { - enc.addKey(key) - enc.AppendComplex128(val) -} - -func (enc *consoleEncoder) AddDuration(key string, val time.Duration) { - enc.addKey(key) - enc.AppendDuration(val) -} - -func (enc *consoleEncoder) AddFloat64(key string, val float64) { - enc.addKey(key) - enc.AppendFloat64(val) -} - -func (enc *consoleEncoder) AddInt64(key string, val int64) { - enc.addKey(key) - enc.AppendInt64(val) -} - -func (enc *consoleEncoder) AddReflected(key string, obj interface{}) error { - enc.resetReflectBuf() - err := enc.reflectEnc.Encode(obj) - if err != nil { - return err - } - enc.reflectBuf.TrimNewline() - enc.addKey(key) - _, err = enc.buf.Write(enc.reflectBuf.Bytes()) - return err -} - -func (enc *consoleEncoder) OpenNamespace(key string) { - enc.addKey(key) - enc.buf.AppendByte('{') - enc.openNamespaces++ -} - -func (enc *consoleEncoder) AddString(key, val string) { - enc.addKey(key) - enc.AppendString(val) -} - -func (enc *consoleEncoder) AddTime(key string, val time.Time) { - enc.addKey(key) - enc.AppendTime(val) -} - -func (enc *consoleEncoder) AddUint64(key string, val uint64) { - enc.addKey(key) - enc.AppendUint64(val) -} - -func (enc *consoleEncoder) addKey(key string) { - // Print key in different color - enc.buf.AppendString(fmt.Sprintf(" \x1b[%dm%s\x1b[0m",36,key)) - - enc.buf.AppendByte('=') -} - -func (enc *consoleEncoder) AppendArray(arr zapcore.ArrayMarshaler) error { - enc.buf.AppendByte('[') - err := arr.MarshalLogArray(enc) - enc.buf.AppendByte(']') - return err -} - -func (enc *consoleEncoder) AppendObject(obj zapcore.ObjectMarshaler) error { - enc.buf.AppendByte('{') - err := obj.MarshalLogObject(enc) - enc.buf.AppendByte('}') - return err -} - -func (enc *consoleEncoder) AppendBool(val bool) { - enc.buf.AppendBool(val) -} - -func (enc *consoleEncoder) AppendByteString(val []byte) { - enc.buf.AppendByte('"') - enc.safeAddByteString(val) - enc.buf.AppendByte('"') -} - -func (enc *consoleEncoder) AppendComplex128(val complex128) { - // Cast to a platform-independent, fixed-size type. - r, i := float64(real(val)), float64(imag(val)) - enc.buf.AppendByte('"') - // Because we're always in a quoted string, we can use strconv without - // special-casing NaN and +/-Inf. - enc.buf.AppendFloat(r, 64) - enc.buf.AppendByte('+') - enc.buf.AppendFloat(i, 64) - enc.buf.AppendByte('i') - enc.buf.AppendByte('"') -} - -func (enc *consoleEncoder) AppendDuration(val time.Duration) { - cur := enc.buf.Len() - enc.EncodeDuration(val, enc) - if cur == enc.buf.Len() { - // User-supplied EncodeDuration is a no-op. Fall back to nanoseconds to keep - // JSON valid. - enc.AppendInt64(int64(val)) - } -} - -func (enc *consoleEncoder) AppendInt64(val int64) { - enc.buf.AppendInt(val) -} -func (enc *consoleEncoder) resetReflectBuf() { - if enc.reflectBuf == nil { - enc.reflectBuf = Get() - enc.reflectEnc = json.NewEncoder(enc.reflectBuf) - } else { - enc.reflectBuf.Reset() - } -} -func (enc *consoleEncoder) AppendReflected(val interface{}) error { - enc.resetReflectBuf() - err := enc.reflectEnc.Encode(val) - if err != nil { - return err - } - enc.reflectBuf.TrimNewline() - _, err = enc.buf.Write(enc.reflectBuf.Bytes()) - return err -} - -func (enc *consoleEncoder) AppendString(val string) { - enc.safeAddString(val) -} - -func (enc *consoleEncoder) AppendTime(val time.Time) { - cur := enc.buf.Len() - enc.EncodeTime(val, enc) - if cur == enc.buf.Len() { - // User-supplied EncodeTime is a no-op. Fall back to nanos since epoch to keep - // output JSON valid. - enc.AppendInt64(val.UnixNano()) - } -} - -func (enc *consoleEncoder) AppendUint64(val uint64) { - enc.buf.AppendUint(val) -} -func (enc *consoleEncoder) appendFloat(val float64, bitSize int) { - switch { - case math.IsNaN(val): - enc.buf.AppendString(`"NaN"`) - case math.IsInf(val, 1): - enc.buf.AppendString(`"+Inf"`) - case math.IsInf(val, -1): - enc.buf.AppendString(`"-Inf"`) - default: - enc.buf.AppendFloat(val, bitSize) - } -} - -// safeAddString JSON-escapes a string and appends it to the internal buffer. -// Unlike the standard library's encoder, it doesn't attempt to protect the -// user from browser vulnerabilities or JSONP-related problems. -func (enc *consoleEncoder) safeAddString(s string) { - for i := 0; i < len(s); { - if enc.tryAddRuneSelf(s[i]) { - i++ - continue - } - r, size := utf8.DecodeRuneInString(s[i:]) - if enc.tryAddRuneError(r, size) { - i++ - continue - } - enc.buf.AppendString(s[i : i+size]) - i += size - } -} - -// safeAddByteString is no-alloc equivalent of safeAddString(string(s)) for s []byte. -func (enc *consoleEncoder) safeAddByteString(s []byte) { - for i := 0; i < len(s); { - if enc.tryAddRuneSelf(s[i]) { - i++ - continue - } - r, size := utf8.DecodeRune(s[i:]) - if enc.tryAddRuneError(r, size) { - i++ - continue - } - enc.buf.Write(s[i : i+size]) - i += size - } -} - -// tryAddRuneSelf appends b if it is valid UTF-8 character represented in a single byte. -func (enc *consoleEncoder) tryAddRuneSelf(b byte) bool { - if b >= utf8.RuneSelf { - return false - } - if 0x20 <= b && b != '\\' && b != '"' { - enc.buf.AppendByte(b) - return true - } - switch b { - case '\\', '"': - enc.buf.AppendByte('\\') - enc.buf.AppendByte(b) - case '\n': - enc.buf.AppendByte('\\') - enc.buf.AppendByte('n') - case '\r': - enc.buf.AppendByte('\\') - enc.buf.AppendByte('r') - case '\t': - enc.buf.AppendByte('\\') - enc.buf.AppendByte('t') - default: - // Encode bytes < 0x20, except for the escape sequences above. - enc.buf.AppendString(`\u00`) - enc.buf.AppendByte(_hex[b>>4]) - enc.buf.AppendByte(_hex[b&0xF]) - } - return true -} -func (enc *consoleEncoder) closeOpenNamespaces() { - for i := 0; i < enc.openNamespaces; i++ { - enc.buf.AppendByte('}') - } -} - - -func (enc *consoleEncoder) tryAddRuneError(r rune, size int) bool { - if r == utf8.RuneError && size == 1 { - enc.buf.AppendString(`\ufffd`) - return true - } - return false -} -func (enc *consoleEncoder) AddComplex64(k string, v complex64) { enc.AddComplex128(k, complex128(v)) } -func (enc *consoleEncoder) AddFloat32(k string, v float32) { enc.AddFloat64(k, float64(v)) } -func (enc *consoleEncoder) AddInt(k string, v int) { enc.AddInt64(k, int64(v)) } -func (enc *consoleEncoder) AddInt32(k string, v int32) { enc.AddInt64(k, int64(v)) } -func (enc *consoleEncoder) AddInt16(k string, v int16) { enc.AddInt64(k, int64(v)) } -func (enc *consoleEncoder) AddInt8(k string, v int8) { enc.AddInt64(k, int64(v)) } -func (enc *consoleEncoder) AddUint(k string, v uint) { enc.AddUint64(k, uint64(v)) } -func (enc *consoleEncoder) AddUint32(k string, v uint32) { enc.AddUint64(k, uint64(v)) } -func (enc *consoleEncoder) AddUint16(k string, v uint16) { enc.AddUint64(k, uint64(v)) } -func (enc *consoleEncoder) AddUint8(k string, v uint8) { enc.AddUint64(k, uint64(v)) } -func (enc *consoleEncoder) AddUintptr(k string, v uintptr) { enc.AddUint64(k, uint64(v)) } -func (enc *consoleEncoder) AppendComplex64(v complex64) { enc.AppendComplex128(complex128(v)) } -func (enc *consoleEncoder) AppendFloat64(v float64) { enc.appendFloat(v, 64) } -func (enc *consoleEncoder) AppendFloat32(v float32) { enc.appendFloat(float64(v), 32) } -func (enc *consoleEncoder) AppendInt(v int) { enc.AppendInt64(int64(v)) } -func (enc *consoleEncoder) AppendInt32(v int32) { enc.AppendInt64(int64(v)) } -func (enc *consoleEncoder) AppendInt16(v int16) { enc.AppendInt64(int64(v)) } -func (enc *consoleEncoder) AppendInt8(v int8) { enc.AppendInt64(int64(v)) } -func (enc *consoleEncoder) AppendUint(v uint) { enc.AppendUint64(uint64(v)) } -func (enc *consoleEncoder) AppendUint32(v uint32) { enc.AppendUint64(uint64(v)) } -func (enc *consoleEncoder) AppendUint16(v uint16) { enc.AppendUint64(uint64(v)) } -func (enc *consoleEncoder) AppendUint8(v uint8) { enc.AppendUint64(uint64(v)) } -func (enc *consoleEncoder) AppendUintptr(v uintptr) { enc.AppendUint64(uint64(v)) } - -const _hex = "0123456789abcdef" - -type sliceArrayEncoder struct { - elems []interface{} -} - -func (s *sliceArrayEncoder) AppendArray(v zapcore.ArrayMarshaler) error { - enc := &sliceArrayEncoder{} - err := v.MarshalLogArray(enc) - s.elems = append(s.elems, enc.elems) - return err -} - -func (s *sliceArrayEncoder) AppendObject(v zapcore.ObjectMarshaler) error { - m := zapcore.NewMapObjectEncoder() - err := v.MarshalLogObject(m) - s.elems = append(s.elems, m.Fields) - return err -} - -func (s *sliceArrayEncoder) AppendReflected(v interface{}) error { - s.elems = append(s.elems, v) - return nil -} - -func (s *sliceArrayEncoder) AppendBool(v bool) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendByteString(v []byte) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendComplex128(v complex128) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendComplex64(v complex64) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendDuration(v time.Duration) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendFloat64(v float64) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendFloat32(v float32) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendInt(v int) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendInt64(v int64) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendInt32(v int32) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendInt16(v int16) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendInt8(v int8) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendString(v string) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendTime(v time.Time) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendUint(v uint) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendUint64(v uint64) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendUint32(v uint32) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendUint16(v uint16) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendUint8(v uint8) { s.elems = append(s.elems, v) } -func (s *sliceArrayEncoder) AppendUintptr(v uintptr) { s.elems = append(s.elems, v) } diff --git a/logger/log_function_map.go b/logger/log_function_map.go new file mode 100644 index 0000000..ebbc76d --- /dev/null +++ b/logger/log_function_map.go @@ -0,0 +1,37 @@ +package logger + +import ( + "os" +) + +// The log function map can be added to, so that you can specify your own logging mechanism +// it has defaults for off, stdout, stderr +var LogFunctionMap = map[string]func(*CompositeMultiHandler, *LogOptions){ + // Do nothing - set the logger off + "off": func(c *CompositeMultiHandler, logOptions *LogOptions) { + // Only drop the results if there is a parent handler defined + if logOptions.HandlerWrap != nil { + for _, l := range logOptions.Levels { + c.SetHandler(logOptions.HandlerWrap.SetChild(NilHandler()), logOptions.ReplaceExistingHandler, l) + } + } else { + // Clear existing handler + c.SetHandlers(NilHandler(), logOptions) + } + }, + // Do nothing - set the logger off + "": func(*CompositeMultiHandler, *LogOptions) {}, + // Set the levels to stdout, replace existing + "stdout": func(c *CompositeMultiHandler, logOptions *LogOptions) { + if logOptions.Ctx != nil { + logOptions.SetExtendedOptions( + "noColor", !logOptions.Ctx.BoolDefault("log.colorize", true), + "smallDate", logOptions.Ctx.BoolDefault("log.smallDate", true)) + } + c.SetTerminal(os.Stdout, logOptions) + }, + // Set the levels to stderr output to terminal + "stderr": func(c *CompositeMultiHandler, logOptions *LogOptions) { + c.SetTerminal(os.Stderr, logOptions) + }, +} diff --git a/logger/logger.go b/logger/logger.go index 8474d00..b9abdaf 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -3,9 +3,7 @@ package logger import ( "fmt" "github.com/revel/config" - "github.com/revel/log15" - "log" - "os" + "time" ) // The LogHandler defines the interface to handle the log records @@ -13,51 +11,82 @@ type ( // The Multilogger reduces the number of exposed defined logging variables, // and allows the output to be easily refined MultiLogger interface { - //log15.Logger - //// New returns a new Logger that has this logger's context plus the given context + // New returns a new Logger that has this logger's context plus the given context New(ctx ...interface{}) MultiLogger - // - //// SetHandler updates the logger to write records to the specified handler. + + // SetHandler updates the logger to write records to the specified handler. SetHandler(h LogHandler) + + // Set the stack depth for the logger SetStackDepth(int) MultiLogger - // - //// Log a message at the given level with context key/value pairs + + // Log a message at the given level with context key/value pairs Debug(msg string, ctx ...interface{}) + + // Log a message at the given level formatting message with the parameters Debugf(msg string, params ...interface{}) + + // Log a message at the given level with context key/value pairs Info(msg string, ctx ...interface{}) + + // Log a message at the given level formatting message with the parameters Infof(msg string, params ...interface{}) + + // Log a message at the given level with context key/value pairs Warn(msg string, ctx ...interface{}) + + // Log a message at the given level formatting message with the parameters Warnf(msg string, params ...interface{}) + + // Log a message at the given level with context key/value pairs Error(msg string, ctx ...interface{}) + + // Log a message at the given level formatting message with the parameters Errorf(msg string, params ...interface{}) + + // Log a message at the given level with context key/value pairs Crit(msg string, ctx ...interface{}) + + // Log a message at the given level formatting message with the parameters Critf(msg string, params ...interface{}) - //// Logs a message as an Crit and exits + // Log a message at the given level with context key/value pairs and exits Fatal(msg string, ctx ...interface{}) + + // Log a message at the given level formatting message with the parameters and exits Fatalf(msg string, params ...interface{}) - //// Logs a message as an Crit and panics + + // Log a message at the given level with context key/value pairs and panics Panic(msg string, ctx ...interface{}) + + // Log a message at the given level formatting message with the parameters and panics Panicf(msg string, params ...interface{}) } + + // The log handler interface LogHandler interface { - log15.Handler + Log(*Record) error + //log15.Handler } + + // The log stack handler interface LogStackHandler interface { LogHandler GetStack() int } + + // The log handler interface which has child logs ParentLogHandler interface { SetChild(handler LogHandler) LogHandler } + + // The log format interface LogFormat interface { - log15.Format + Format(r *Record) []byte } - LogLevel log15.Lvl - RevelLogger struct { - log15.Logger - } + // The log level type + LogLevel int // Used for the callback to LogFunctionMap LogOptions struct { @@ -67,125 +96,65 @@ type ( Levels []LogLevel ExtendedOptions map[string]interface{} } + + // The log record + Record struct { + Message string // The message + Time time.Time // The time + Level LogLevel //The level + Call CallStack // The call stack if built + Context ContextMap // The context + } + + // The lazy structure to implement a function to be invoked only if needed + Lazy struct { + Fn interface{} // the function + } + + // Currently the only requirement for the callstack is to support the Formatter method + // which stack.Call does so we use that + CallStack interface { + fmt.Formatter // Requirement + } ) +// FormatFunc returns a new Format object which uses +// the given function to perform record formatting. +func FormatFunc(f func(*Record) []byte) LogFormat { + return formatFunc(f) +} + +type formatFunc func(*Record) []byte + +func (f formatFunc) Format(r *Record) []byte { + return f(r) +} +func NewRecord(message string, level LogLevel) *Record { + return &Record{Message: message, Context: ContextMap{}, Level: level} +} + const ( - LvlDebug = LogLevel(log15.LvlDebug) - LvlInfo = LogLevel(log15.LvlInfo) - LvlWarn = LogLevel(log15.LvlWarn) - LvlError = LogLevel(log15.LvlError) - LvlCrit = LogLevel(log15.LvlCrit) + LvlCrit LogLevel = iota // Critical + LvlError // Error + LvlWarn // Warning + LvlInfo // Information + LvlDebug // Debug ) // A list of all the log levels var LvlAllList = []LogLevel{LvlDebug, LvlInfo, LvlWarn, LvlError, LvlCrit} -// The log function map can be added to, so that you can specify your own logging mechanism -var LogFunctionMap = map[string]func(*CompositeMultiHandler, *LogOptions){ - // Do nothing - set the logger off - "off": func(c *CompositeMultiHandler, logOptions *LogOptions) { - // Only drop the results if there is a parent handler defined - if logOptions.HandlerWrap != nil { - for _, l := range logOptions.Levels { - c.SetHandler(logOptions.HandlerWrap.SetChild(NilHandler()), logOptions.ReplaceExistingHandler, l) - } - } - }, - // Do nothing - set the logger off - "": func(*CompositeMultiHandler, *LogOptions) {}, - // Set the levels to stdout, replace existing - "stdout": func(c *CompositeMultiHandler, logOptions *LogOptions) { - if logOptions.Ctx != nil { - logOptions.SetExtendedOptions( - "noColor", !logOptions.Ctx.BoolDefault("log.colorize", true), - "smallDate", logOptions.Ctx.BoolDefault("log.smallDate", true)) - } - - c.SetTerminal(os.Stdout, logOptions) - }, - // Set the levels to stderr output to terminal - "stderr": func(c *CompositeMultiHandler, logOptions *LogOptions) { - c.SetTerminal(os.Stderr, logOptions) - }, -} - -// Set the systems default logger -// Default logs will be captured and handled by revel at level info -func SetDefaultLog(fromLog MultiLogger) { - log.SetOutput(loggerRewrite{Logger: fromLog, Level: log15.LvlInfo, hideDeprecated: true}) - // No need to show date and time, that will be logged with revel - log.SetFlags(0) -} - -// Formatted debug call -func (rl *RevelLogger) Debugf(msg string, param ...interface{}) { - rl.Debug(fmt.Sprintf(msg, param...)) -} - -// Formatted info call -func (rl *RevelLogger) Infof(msg string, param ...interface{}) { - rl.Info(fmt.Sprintf(msg, param...)) -} -func (rl *RevelLogger) Warnf(msg string, param ...interface{}) { - rl.Warn(fmt.Sprintf(msg, param...)) -} -func (rl *RevelLogger) Errorf(msg string, param ...interface{}) { - rl.Error(fmt.Sprintf(msg, param...)) -} -func (rl *RevelLogger) Critf(msg string, param ...interface{}) { - rl.Crit(fmt.Sprintf(msg, param...)) -} -func (rl *RevelLogger) Fatalf(msg string, param ...interface{}) { - rl.Crit(fmt.Sprintf(msg, param...)) - os.Exit(1) -} -func (rl *RevelLogger) Panicf(msg string, param ...interface{}) { - rl.Crit(fmt.Sprintf(msg, param...)) - panic(msg) -} - -func (rl *RevelLogger) Fatal(msg string, ctx ...interface{}) { - rl.Crit(msg, ctx...) - os.Exit(1) -} - -func (rl *RevelLogger) Panic(msg string, ctx ...interface{}) { - rl.Crit(msg, ctx...) - panic(msg) -} - -// Override log15 method -func (rl *RevelLogger) New(ctx ...interface{}) MultiLogger { - old := &RevelLogger{Logger: rl.Logger.New(ctx...)} - return old -} - -// Set the stack level to check for the caller -func (rl *RevelLogger) SetStackDepth(amount int) MultiLogger { - rl.Logger.SetStackDepth(amount) // Ignore the logger returned - return rl -} - -// Create a new logger -func New(ctx ...interface{}) MultiLogger { - r := &RevelLogger{Logger: log15.New(ctx...)} - r.SetStackDepth(1) - return r -} - -// Set the handler in the Logger -func (rl *RevelLogger) SetHandler(h LogHandler) { - rl.Logger.SetHandler(h) -} - +// Implements the ParentLogHandler type parentLogHandler struct { setChild func(handler LogHandler) LogHandler } +// Create a new parent log handler func NewParentLogHandler(callBack func(child LogHandler) LogHandler) ParentLogHandler { return &parentLogHandler{callBack} } +// Sets the child of the log handler func (p *parentLogHandler) SetChild(child LogHandler) LogHandler { return p.setChild(child) } @@ -208,18 +177,24 @@ func (l *LogOptions) SetExtendedOptions(options ...interface{}) { l.ExtendedOptions[options[x].(string)] = options[x+1] } } + +// Gets a string option with default func (l *LogOptions) GetStringDefault(option, value string) string { if v, found := l.ExtendedOptions[option]; found { return v.(string) } return value } + +// Gets an int option with default func (l *LogOptions) GetIntDefault(option string, value int) int { if v, found := l.ExtendedOptions[option]; found { return v.(int) } return value } + +// Gets a boolean option with default func (l *LogOptions) GetBoolDefault(option string, value bool) bool { if v, found := l.ExtendedOptions[option]; found { return v.(bool) diff --git a/logger/revel_logger.go b/logger/revel_logger.go new file mode 100644 index 0000000..b3a6f86 --- /dev/null +++ b/logger/revel_logger.go @@ -0,0 +1,142 @@ +package logger + +import ( + "fmt" + "github.com/revel/log15" + "log" + "os" +) + +// This type implements the MultiLogger +type RevelLogger struct { + log15.Logger +} + +// Set the systems default logger +// Default logs will be captured and handled by revel at level info +func SetDefaultLog(fromLog MultiLogger) { + log.SetOutput(loggerRewrite{Logger: fromLog, Level: log15.LvlInfo, hideDeprecated: true}) + // No need to show date and time, that will be logged with revel + log.SetFlags(0) +} + +func (rl *RevelLogger) Debugf(msg string, param ...interface{}) { + rl.Debug(fmt.Sprintf(msg, param...)) +} + +// Print a formatted info message +func (rl *RevelLogger) Infof(msg string, param ...interface{}) { + rl.Info(fmt.Sprintf(msg, param...)) +} + +// Print a formatted warn message +func (rl *RevelLogger) Warnf(msg string, param ...interface{}) { + rl.Warn(fmt.Sprintf(msg, param...)) +} + +// Print a formatted error message +func (rl *RevelLogger) Errorf(msg string, param ...interface{}) { + rl.Error(fmt.Sprintf(msg, param...)) +} + +// Print a formatted critical message +func (rl *RevelLogger) Critf(msg string, param ...interface{}) { + rl.Crit(fmt.Sprintf(msg, param...)) +} + +// Print a formatted fatal message +func (rl *RevelLogger) Fatalf(msg string, param ...interface{}) { + rl.Fatal(fmt.Sprintf(msg, param...)) +} + +// Print a formatted panic message +func (rl *RevelLogger) Panicf(msg string, param ...interface{}) { + rl.Panic(fmt.Sprintf(msg, param...)) +} + +// Print a critical message and call os.Exit(1) +func (rl *RevelLogger) Fatal(msg string, ctx ...interface{}) { + rl.Crit(msg, ctx...) + os.Exit(1) +} + +// Print a critical message and panic +func (rl *RevelLogger) Panic(msg string, ctx ...interface{}) { + rl.Crit(msg, ctx...) + panic(msg) +} + +// Override log15 method +func (rl *RevelLogger) New(ctx ...interface{}) MultiLogger { + old := &RevelLogger{Logger: rl.Logger.New(ctx...)} + return old +} + +// Set the stack level to check for the caller +func (rl *RevelLogger) SetStackDepth(amount int) MultiLogger { + rl.Logger.SetStackDepth(amount) // Ignore the logger returned + return rl +} + +// Create a new logger +func New(ctx ...interface{}) MultiLogger { + r := &RevelLogger{Logger: log15.New(ctx...)} + r.SetStackDepth(1) + return r +} + +// Set the handler in the Logger +func (rl *RevelLogger) SetHandler(h LogHandler) { + rl.Logger.SetHandler(callHandler(h.Log)) +} + +// The function wrapper to implement the callback +type callHandler func(r *Record) error + +// Log implementation, reads the record and extracts the details from the log record +// Hiding the implementation. +func (c callHandler) Log(log *log15.Record) error { + ctx := log.Ctx + var ctxMap ContextMap + if len(ctx) > 0 { + ctxMap = make(ContextMap, len(ctx)/2) + + for i := 0; i < len(ctx); i += 2 { + v := ctx[i] + key, ok := v.(string) + if !ok { + key = fmt.Sprintf("LOGGER_INVALID_KEY %v", v) + } + var value interface{} + if len(ctx) > i+1 { + value = ctx[i+1] + } else { + value = "LOGGER_VALUE_MISSING" + } + ctxMap[key] = value + } + } else { + ctxMap = make(ContextMap, 0) + } + r := &Record{Message: log.Msg, Context: ctxMap, Time: log.Time, Level: LogLevel(log.Lvl), Call: CallStack(log.Call)} + return c(r) +} + +// Internally used contextMap, allows conversion of map to map[string]string +type ContextMap map[string]interface{} + +// Convert the context map to be string only values, any non string values are ignored +func (m ContextMap) StringMap() (newMap map[string]string) { + if m != nil { + newMap = map[string]string{} + for key, value := range m { + if svalue, isstring := value.(string); isstring { + newMap[key] = svalue + } + } + } + return +} +func (m ContextMap) Add(key string, value interface{}) { + m[key] = value +} diff --git a/logger/format.go b/logger/terminal_format.go similarity index 64% rename from logger/format.go rename to logger/terminal_format.go index e5276f1..ca2cd15 100644 --- a/logger/format.go +++ b/logger/terminal_format.go @@ -2,8 +2,8 @@ package logger import ( "bytes" + "encoding/json" "fmt" - "github.com/revel/log15" "reflect" "strconv" "sync" @@ -19,9 +19,8 @@ const ( ) var ( - // Name the log level - toRevel = map[log15.Lvl]string{log15.LvlDebug: "DEBUG", - log15.LvlInfo: "INFO", log15.LvlWarn: "WARN", log15.LvlError: "ERROR", log15.LvlCrit: "CRIT"} + levelString = map[LogLevel]string{LvlDebug: "DEBUG", + LvlInfo: "INFO", LvlWarn: "WARN", LvlError: "ERROR", LvlCrit: "CRIT"} ) // Outputs to the terminal in a format like below @@ -31,53 +30,51 @@ func TerminalFormatHandler(noColor bool, smallDate bool) LogFormat { if smallDate { dateFormat = termSmallTimeFormat } - return log15.FormatFunc(func(r *log15.Record) []byte { + return FormatFunc(func(r *Record) []byte { // Bash coloring http://misc.flogisoft.com/bash/tip_colors_and_formatting var color = 0 - switch r.Lvl { - case log15.LvlCrit: + switch r.Level { + case LvlCrit: // Magenta color = 35 - case log15.LvlError: + case LvlError: // Red color = 31 - case log15.LvlWarn: + case LvlWarn: // Yellow color = 33 - case log15.LvlInfo: + case LvlInfo: // Green color = 32 - case log15.LvlDebug: + case LvlDebug: // Cyan color = 36 } b := &bytes.Buffer{} - caller := findInContext("caller", r.Ctx) - module := findInContext("module", r.Ctx) + caller, _ := r.Context["caller"].(string) + module, _ := r.Context["module"].(string) if noColor == false && color > 0 { if len(module) > 0 { - fmt.Fprintf(b, "\x1b[%dm%-5s\x1b[0m %s %6s %13s: %-40s ", color, toRevel[r.Lvl], r.Time.Format(dateFormat), module, caller, r.Msg) + fmt.Fprintf(b, "\x1b[%dm%-5s\x1b[0m %s %6s %13s: %-40s ", color, levelString[r.Level], r.Time.Format(dateFormat), module, caller, r.Message) } else { - fmt.Fprintf(b, "\x1b[%dm%-5s\x1b[0m %s %13s: %-40s ", color, toRevel[r.Lvl], r.Time.Format(dateFormat), caller, r.Msg) + fmt.Fprintf(b, "\x1b[%dm%-5s\x1b[0m %s %13s: %-40s ", color, levelString[r.Level], r.Time.Format(dateFormat), caller, r.Message) } } else { - fmt.Fprintf(b, "%-5s %s %6s %13s: %-40s", toRevel[r.Lvl], r.Time.Format(dateFormat), module, caller, r.Msg) + fmt.Fprintf(b, "%-5s %s %6s %13s: %-40s", levelString[r.Level], r.Time.Format(dateFormat), module, caller, r.Message) } - for i := 0; i < len(r.Ctx); i += 2 { + i := 0 + for k, v := range r.Context { if i != 0 { b.WriteByte(' ') } - - k, ok := r.Ctx[i].(string) - if k == "caller" || k == "fn" || k == "module" { + i++ + if k == "module" || k == "caller" { continue } - v := formatLogfmtValue(r.Ctx[i+1]) - if !ok { - k, v = errorKey, formatLogfmtValue(k) - } + + v := formatLogfmtValue(v) // TODO: we should probably check that all of your key bytes aren't invalid if noColor == false && color > 0 { @@ -94,15 +91,6 @@ func TerminalFormatHandler(noColor bool, smallDate bool) LogFormat { return b.Bytes() }) } -func findInContext(key string, ctx []interface{}) string { - for i := 0; i < len(ctx); i += 2 { - k := ctx[i].(string) - if key == k { - return formatLogfmtValue(ctx[i+1]) - } - } - return "" -} // formatValue formats a value for serialization func formatLogfmtValue(value interface{}) string { @@ -132,6 +120,8 @@ func formatLogfmtValue(value interface{}) string { return escapeString(fmt.Sprintf("%+v", value)) } } + +// Format the value in json format func formatShared(value interface{}) (result interface{}) { defer func() { if err := recover(); err != nil { @@ -158,10 +148,12 @@ func formatShared(value interface{}) (result interface{}) { } } +// A reusuable buffer for outputting data var stringBufPool = sync.Pool{ New: func() interface{} { return new(bytes.Buffer) }, } +// Escape the string when needed func escapeString(s string) string { needsQuotes := false needsEscape := false @@ -204,3 +196,50 @@ func escapeString(s string) string { stringBufPool.Put(e) return ret } + +// JsonFormatEx formats log records as JSON objects. If pretty is true, +// records will be pretty-printed. If lineSeparated is true, records +// will be logged with a new line between each record. +func JsonFormatEx(pretty, lineSeparated bool) LogFormat { + jsonMarshal := json.Marshal + if pretty { + jsonMarshal = func(v interface{}) ([]byte, error) { + return json.MarshalIndent(v, "", " ") + } + } + + return FormatFunc(func(r *Record) []byte { + props := make(map[string]interface{}) + + props["t"] = r.Time + props["lvl"] = levelString[r.Level] + props["msg"] = r.Message + for k, v := range r.Context { + props[k] = formatJsonValue(v) + } + + b, err := jsonMarshal(props) + if err != nil { + b, _ = jsonMarshal(map[string]string{ + errorKey: err.Error(), + }) + return b + } + + if lineSeparated { + b = append(b, '\n') + } + + return b + }) +} + +func formatJsonValue(value interface{}) interface{} { + value = formatShared(value) + switch value.(type) { + case int, int8, int16, int32, int64, float32, float64, uint, uint8, uint16, uint32, uint64, string: + return value + default: + return fmt.Sprintf("%+v", value) + } +} diff --git a/logger/utils.go b/logger/utils.go index 6d5dc87..3918cc1 100644 --- a/logger/utils.go +++ b/logger/utils.go @@ -1,13 +1,9 @@ package logger import ( - "github.com/revel/config" "github.com/revel/log15" "gopkg.in/stack.v0" "log" - "os" - "path/filepath" - "strings" ) // Utility package to make existing logging backwards compatible @@ -20,6 +16,14 @@ var ( } ) +const ( + // The test mode flag overrides the default log level and shows only errors + TEST_MODE_FLAG = "testModeFlag" + // The special use flag enables showing messages when the logger is setup + SPECIAL_USE_FLAG = "specialUseFlag" +) + +// Returns the logger for the name func GetLogger(name string, logger MultiLogger) (l *log.Logger) { switch name { case "trace": // TODO trace is deprecated, replaced by debug @@ -40,198 +44,26 @@ func GetLogger(name string, logger MultiLogger) (l *log.Logger) { } -// Get all handlers based on the Config (if available) -func InitializeFromConfig(basePath string, config *config.Context) (c *CompositeMultiHandler) { - // If running in test mode suppress anything that is not an error - if config != nil && config.BoolDefault("testModeFlag", false) { - config.SetOption("log.info.output", "off") - config.SetOption("log.debug.output", "off") - config.SetOption("log.warn.output", "off") - config.SetOption("log.error.output", "stderr") - config.SetOption("log.crit.output", "stderr") - } +// Used by the initFilterLog to handle the filters +var logFilterList = []struct { + LogPrefix, LogSuffix string + parentHandler func(map[string]interface{}) ParentLogHandler +}{{ + "log.", ".filter", + func(keyMap map[string]interface{}) ParentLogHandler { + return NewParentLogHandler(func(child LogHandler) LogHandler { + return MatchMapHandler(keyMap, child) + }) - // If the configuration has an all option we can skip some - c, _ = NewCompositeMultiHandler() - - // Filters are assigned first, non filtered items override filters - initAllLog(c, basePath, config) - initLogLevels(c, basePath, config) - if c.CriticalHandler == nil && c.ErrorHandler != nil { - c.CriticalHandler = c.ErrorHandler - } - initFilterLog(c, basePath, config) - if c.CriticalHandler == nil && c.ErrorHandler != nil { - c.CriticalHandler = c.ErrorHandler - } - initRequestLog(c, basePath, config) - - return c -} - -// Init the log.all configuration options -func initAllLog(c *CompositeMultiHandler, basePath string, config *config.Context) { - if config != nil { - extraLogFlag := config.BoolDefault("specialUseFlag", false) - if output, found := config.String("log.all.output"); found { - // Set all output for the specified handler - if extraLogFlag { - log.Printf("Adding standard handler for levels to >%s< ", output) - } - initHandlerFor(c, output, basePath, NewLogOptions(config, true, nil, LvlAllList...)) - } - } -} - -// Init the filter options -// log.all.filter .... -// log.error.filter .... -func initFilterLog(c *CompositeMultiHandler, basePath string, config *config.Context) { - if config != nil { - extraLogFlag := config.BoolDefault("specialUseFlag", false) - - // The commands to use - logFilterList := []struct { - LogPrefix, LogSuffix string - parentHandler func(map[string]interface{}) ParentLogHandler - }{{ - "log.", ".filter", - func(keyMap map[string]interface{}) ParentLogHandler { - return NewParentLogHandler(func(child LogHandler) LogHandler { - return MatchMapHandler(keyMap, child) - }) - - }, - }, { - "log.", ".nfilter", - func(keyMap map[string]interface{}) ParentLogHandler { - return NewParentLogHandler(func(child LogHandler) LogHandler { - return NotMatchMapHandler(keyMap, child) - }) - }, - }} - - for _, logFilter := range logFilterList { - // Init for all filters - for _, name := range []string{"all", "debug", "info", "warn", "error", "crit", - "trace", // TODO trace is deprecated - } { - optionList := config.Options(logFilter.LogPrefix + name + logFilter.LogSuffix) - for _, option := range optionList { - splitOptions := strings.Split(option, ".") - keyMap := map[string]interface{}{} - for x := 3; x < len(splitOptions); x += 2 { - keyMap[splitOptions[x]] = splitOptions[x+1] - } - phandler := logFilter.parentHandler(keyMap) - if extraLogFlag { - log.Printf("Adding key map handler %s %s output %s", option, name, config.StringDefault(option, "")) - } - - if name == "all" { - initHandlerFor(c, config.StringDefault(option, ""), basePath, NewLogOptions(config, false, phandler)) - } else { - initHandlerFor(c, config.StringDefault(option, ""), basePath, NewLogOptions(config, false, phandler, toLevel[name])) - } - } - } - } - } -} - -// Init the log.error, log.warn etc configuration options -func initLogLevels(c *CompositeMultiHandler, basePath string, config *config.Context) { - for _, name := range []string{"debug", "info", "warn", "error", "crit", - "trace", // TODO trace is deprecated - } { - if config != nil { - extraLogFlag := config.BoolDefault("specialUseFlag", false) - output, found := config.String("log." + name + ".output") - if found { - if extraLogFlag { - log.Printf("Adding standard handler %s output %s", name, output) - } - initHandlerFor(c, output, basePath, NewLogOptions(config, true, nil, toLevel[name])) - } - // Gets the list of options with said prefix - } else { - initHandlerFor(c, "stderr", basePath, NewLogOptions(config, true, nil, toLevel[name])) - } - } -} - -// Init the request log options -func initRequestLog(c *CompositeMultiHandler, basePath string, config *config.Context) { - // Request logging to a separate output handler - // This takes the InfoHandlers and adds a MatchAbHandler handler to it to direct - // context with the word "section=requestlog" to that handler. - // Note if request logging is not enabled the MatchAbHandler will not be added and the - // request log messages will be sent out the INFO handler - outputRequest := "stdout" - if config != nil { - outputRequest = config.StringDefault("log.request.output", "") - } - oldInfo := c.InfoHandler - c.InfoHandler = nil - if outputRequest != "" { - initHandlerFor(c, outputRequest, basePath, NewLogOptions(config, false, nil, LvlInfo)) - } - if c.InfoHandler != nil || oldInfo != nil { - if c.InfoHandler == nil { - c.InfoHandler = oldInfo - } else { - c.InfoHandler = MatchAbHandler("section", "requestlog", c.InfoHandler, oldInfo) - } - } -} - -// Returns a handler for the level using the output string -// Accept formats for output string are -// LogFunctionMap[value] callback function -// `stdout` `stderr` `full/file/path/to/location/app.log` `full/file/path/to/location/app.json` -func initHandlerFor(c *CompositeMultiHandler, output, basePath string, options *LogOptions) { - if options.Ctx != nil { - options.SetExtendedOptions( - "noColor", !options.Ctx.BoolDefault("log.colorize", true), - "smallDate", options.Ctx.BoolDefault("log.smallDate", true), - "maxSize", options.Ctx.IntDefault("log.maxsize", 1024*10), - "maxAge", options.Ctx.IntDefault("log.maxage", 14), - "maxBackups", options.Ctx.IntDefault("log.maxbackups", 14), - "compressBackups", !options.Ctx.BoolDefault("log.compressBackups", true), - ) - } - - output = strings.TrimSpace(output) - if funcHandler, found := LogFunctionMap[output]; found { - funcHandler(c, options) - } else { - switch output { - case "": - fallthrough - case "off": - // No handler, discard data - default: - // Write to file specified - if !filepath.IsAbs(output) { - output = filepath.Join(basePath, output) - } - - if err := os.MkdirAll(filepath.Dir(output), 0755); err != nil { - log.Panic(err) - } - - if strings.HasSuffix(output, "json") { - c.SetJsonFile(output, options) - } else { - // Override defaults for a terminal file - options.SetExtendedOptions("noColor", true) - options.SetExtendedOptions("smallDate", false) - c.SetTerminalFile(output, options) - } - } - } - return -} + }, +}, { + "log.", ".nfilter", + func(keyMap map[string]interface{}) ParentLogHandler { + return NewParentLogHandler(func(child LogHandler) LogHandler { + return NotMatchMapHandler(keyMap, child) + }) + }, +}} // This structure and method will handle the old output format and log it to the new format type loggerRewrite struct { @@ -240,8 +72,10 @@ type loggerRewrite struct { hideDeprecated bool } +// The message indicating that a logger is using a deprecated log mechanism var log_deprecated = []byte("* LOG DEPRECATED * ") +// Implements the Write of the logger func (lr loggerRewrite) Write(p []byte) (n int, err error) { if !lr.hideDeprecated { p = append(log_deprecated, p...) @@ -270,7 +104,7 @@ func (lr loggerRewrite) Write(p []byte) (n int, err error) { // For logging purposes the call stack can be used to record the stack trace of a bad error // simply pass it as a context field in your log statement like -// `controller.Log.Critc("This should not occur","stack",revel.NewCallStack())` +// `controller.Log.Crit("This should not occur","stack",revel.NewCallStack())` func NewCallStack() interface{} { return stack.Trace() } diff --git a/logger/wrap_handlers.go b/logger/wrap_handlers.go new file mode 100644 index 0000000..3d68e75 --- /dev/null +++ b/logger/wrap_handlers.go @@ -0,0 +1,98 @@ +package logger + +// FuncHandler returns a Handler that logs records with the given +// function. +import ( + "fmt" + "reflect" + "sync" + "time" +) + +// Function handler wraps the declared function and returns the handler for it +func FuncHandler(fn func(r *Record) error) LogHandler { + return funcHandler(fn) +} + +// The type decleration for the function +type funcHandler func(r *Record) error + +// The implementation of the Log +func (h funcHandler) Log(r *Record) error { + return h(r) +} + +// This function allows you to do a full declaration for the log, +// it is recommended you use FuncHandler instead +func HandlerFunc(log func(message string, time time.Time, level LogLevel, call CallStack, context ContextMap) error) LogHandler { + return remoteHandler(log) +} + +// The type used for the HandlerFunc +type remoteHandler func(message string, time time.Time, level LogLevel, call CallStack, context ContextMap) error + +// The Log implementation +func (c remoteHandler) Log(record *Record) error { + return c(record.Message, record.Time, record.Level, record.Call, record.Context) +} + +// SyncHandler can be wrapped around a handler to guarantee that +// only a single Log operation can proceed at a time. It's necessary +// for thread-safe concurrent writes. +func SyncHandler(h LogHandler) LogHandler { + var mu sync.Mutex + return FuncHandler(func(r *Record) error { + defer mu.Unlock() + mu.Lock() + return h.Log(r) + }) +} + +// LazyHandler writes all values to the wrapped handler after evaluating +// any lazy functions in the record's context. It is already wrapped +// around StreamHandler and SyslogHandler in this library, you'll only need +// it if you write your own Handler. +func LazyHandler(h LogHandler) LogHandler { + return FuncHandler(func(r *Record) error { + for k, v := range r.Context { + if lz, ok := v.(Lazy); ok { + value, err := evaluateLazy(lz) + if err != nil { + r.Context[errorKey] = "bad lazy " + k + } else { + v = value + } + } + } + + return h.Log(r) + }) +} + +func evaluateLazy(lz Lazy) (interface{}, error) { + t := reflect.TypeOf(lz.Fn) + + if t.Kind() != reflect.Func { + return nil, fmt.Errorf("INVALID_LAZY, not func: %+v", lz.Fn) + } + + if t.NumIn() > 0 { + return nil, fmt.Errorf("INVALID_LAZY, func takes args: %+v", lz.Fn) + } + + if t.NumOut() == 0 { + return nil, fmt.Errorf("INVALID_LAZY, no func return val: %+v", lz.Fn) + } + + value := reflect.ValueOf(lz.Fn) + results := value.Call([]reflect.Value{}) + if len(results) == 1 { + return results[0].Interface(), nil + } else { + values := make([]interface{}, len(results)) + for i, v := range results { + values[i] = v.Interface() + } + return values, nil + } +} diff --git a/revel/new.go b/revel/new.go index 97cc43b..b2d557f 100644 --- a/revel/new.go +++ b/revel/new.go @@ -245,7 +245,7 @@ func newLoadFromGit(c *model.CommandConfig, sp *url.URL) (err error) { utils.Logger.Info("Exec:", "args", getCmd.Args) getOutput, err := getCmd.CombinedOutput() if err != nil { - utils.Logger.Fatalf("Abort: could not clone the Skeleton source code: \n%s\n%s\n", getOutput, c.New.SkeletonPath) + utils.Logger.Fatal("Abort: could not clone the Skeleton source code: ","output", getOutput, "path", c.New.SkeletonPath) } outputPath := targetPath if len(pathpart) > 1 { diff --git a/utils/command.go b/utils/command.go index 5871ebb..7468fc1 100644 --- a/utils/command.go +++ b/utils/command.go @@ -11,24 +11,13 @@ import ( func CmdInit(c *exec.Cmd, basePath string) { c.Dir = basePath // Go 1.8 fails if we do not include the GOROOT - c.Env = []string{"GOPATH=" + build.Default.GOPATH, "PATH=" + GetEnv("PATH"), "GOROOT="+ GetEnv("GOROOT")} + c.Env = []string{"GOPATH=" + build.Default.GOPATH, "GOROOT="+ os.Getenv("GOROOT")} // Fetch the rest of the env variables for _, e := range os.Environ() { pair := strings.Split(e, "=") - if pair[0]=="GOPATH" { + if pair[0]=="GOPATH" || pair[0]=="GOROOT" { continue } c.Env = append(c.Env,e) } -} - -// Returns an environment variable -func GetEnv(name string) string { - for _, v := range os.Environ() { - split := strings.Split(v, "=") - if split[0] == name { - return strings.Join(split[1:], "") - } - } - return "" -} +} \ No newline at end of file diff --git a/utils/file.go b/utils/file.go index 0cbfbe5..cb714ee 100644 --- a/utils/file.go +++ b/utils/file.go @@ -151,7 +151,7 @@ func MustChmod(filename string, mode os.FileMode) { // Called if panic func PanicOnError(err error, msg string) { if revErr, ok := err.(*Error); (ok && revErr != nil) || (!ok && err != nil) { - Logger.Panicf("Abort: %s: %s %s\n", msg, revErr, err) + Logger.Panicf("Abort: %s: %s %s", msg, revErr, err) } }