From 4e276fcc71a652e541dc02387b644ba3fe794269 Mon Sep 17 00:00:00 2001 From: Mark Bates Date: Thu, 27 Jul 2017 13:02:52 -0400 Subject: [PATCH 1/2] cleaned up logging by removing the big giant empty string. pop also now uses the app logger --- logger.go | 11 ++- logger_formatter.go | 203 ++++++++++++++++++++++++++++++++++++++++++++ options.go | 17 ++++ request_logger.go | 2 +- 4 files changed, 230 insertions(+), 3 deletions(-) create mode 100644 logger_formatter.go diff --git a/logger.go b/logger.go index a121b3d4f..b278769b4 100644 --- a/logger.go +++ b/logger.go @@ -1,6 +1,9 @@ package buffalo -import "github.com/sirupsen/logrus" +import ( + "github.com/gobuffalo/envy" + "github.com/sirupsen/logrus" +) // Logger interface is used throughout Buffalo // apps to log a whole manner of things. @@ -42,8 +45,12 @@ func (l logrusWrapper) WithFields(m map[string]interface{}) Logger { Example: time="2016-12-01T21:02:07-05:00" level=info duration=225.283µs human_size="106 B" method=GET path="/" render=199.79µs request_id=2265736089 size=106 status=200 */ func NewLogger(level string) Logger { + dev := envy.Get("GO_ENV", "development") == "development" l := logrus.New() l.Level, _ = logrus.ParseLevel(level) - l.Formatter = &logrus.TextFormatter{} + l.Formatter = &textFormatter{ + ForceColors: dev, + FullTimestamp: true, + } return logrusWrapper{l} } diff --git a/logger_formatter.go b/logger_formatter.go new file mode 100644 index 000000000..e892d1ba8 --- /dev/null +++ b/logger_formatter.go @@ -0,0 +1,203 @@ +package buffalo + +// I really don't want to have this, but until (if) https://github.com/sirupsen/logrus/pull/606 is merged we're stuck with all this code. And yes, this is ALL needed just to remove some blank space in the logs + +import ( + "bytes" + "fmt" + "sort" + "strings" + "sync" + "time" + + "github.com/sirupsen/logrus" +) + +const ( + nocolor = 0 + red = 31 + green = 32 + yellow = 33 + blue = 36 + gray = 37 +) + +var ( + baseTimestamp time.Time +) + +func init() { + baseTimestamp = time.Now() +} + +// textFormatter formats logs into text +type textFormatter struct { + // Set to true to bypass checking for a TTY before outputting colors. + ForceColors bool + + // Force disabling colors. + DisableColors bool + + // Disable timestamp logging. useful when output is redirected to logging + // system that already adds timestamps. + DisableTimestamp bool + + // Enable logging the full timestamp when a TTY is attached instead of just + // the time passed since beginning of execution. + FullTimestamp bool + + // TimestampFormat to use for display when a full timestamp is printed + TimestampFormat string + + // The fields are sorted by default for a consistent output. For applications + // that log extremely frequently and don't use the JSON formatter this may not + // be desired. + DisableSorting bool + + // QuoteEmptyFields will wrap empty fields in quotes if true + QuoteEmptyFields bool + + // Whether the logger's out is to a terminal + isTerminal bool + + sync.Once +} + +func (f *textFormatter) init(entry *logrus.Entry) { + if entry.Logger != nil { + f.isTerminal = logrus.IsTerminal(entry.Logger.Out) + } +} + +const defaultTimestampFormat = time.RFC3339 + +// Format renders a single log entry +func (f *textFormatter) Format(entry *logrus.Entry) ([]byte, error) { + var b *bytes.Buffer + keys := make([]string, 0, len(entry.Data)) + for k := range entry.Data { + keys = append(keys, k) + } + + if !f.DisableSorting { + sort.Strings(keys) + } + if entry.Buffer != nil { + b = entry.Buffer + } else { + b = &bytes.Buffer{} + } + + prefixFieldClashes(entry.Data) + + f.Do(func() { f.init(entry) }) + + isColored := (f.ForceColors || f.isTerminal) && !f.DisableColors + + timestampFormat := f.TimestampFormat + if timestampFormat == "" { + timestampFormat = defaultTimestampFormat + } + if isColored { + f.printColored(b, entry, keys, timestampFormat) + } else { + if !f.DisableTimestamp { + f.appendKeyValue(b, "time", entry.Time.Format(timestampFormat)) + } + f.appendKeyValue(b, "level", entry.Level.String()) + if entry.Message != "" { + f.appendKeyValue(b, "msg", entry.Message) + } + for _, key := range keys { + f.appendKeyValue(b, key, entry.Data[key]) + } + } + + b.WriteByte('\n') + return b.Bytes(), nil +} + +func (f *textFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry, keys []string, timestampFormat string) { + var levelColor int + switch entry.Level { + case logrus.DebugLevel: + levelColor = gray + case logrus.WarnLevel: + levelColor = yellow + case logrus.ErrorLevel, logrus.FatalLevel, logrus.PanicLevel: + levelColor = red + default: + levelColor = blue + } + + levelText := strings.ToUpper(entry.Level.String())[0:4] + + if f.DisableTimestamp { + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m", levelColor, levelText) + } else if !f.FullTimestamp { + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%04d]", levelColor, levelText, int(entry.Time.Sub(baseTimestamp)/time.Second)) + } else { + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s]", levelColor, levelText, entry.Time.Format(timestampFormat)) + } + + if entry.Message != "" { + fmt.Fprintf(b, " %s", entry.Message) + } + + for _, k := range keys { + v := entry.Data[k] + fmt.Fprintf(b, " \x1b[%dm%s\x1b[0m=", levelColor, k) + f.appendValue(b, v) + } +} + +func (f *textFormatter) needsQuoting(text string) bool { + if f.QuoteEmptyFields && len(text) == 0 { + return true + } + for _, ch := range text { + if !((ch >= 'a' && ch <= 'z') || + (ch >= 'A' && ch <= 'Z') || + (ch >= '0' && ch <= '9') || + ch == '-' || ch == '.' || ch == '_' || ch == '/' || ch == '@' || ch == '^' || ch == '+') { + return true + } + } + return false +} + +func (f *textFormatter) appendKeyValue(b *bytes.Buffer, key string, value interface{}) { + if b.Len() > 0 { + b.WriteByte(' ') + } + b.WriteString(key) + b.WriteByte('=') + f.appendValue(b, value) +} + +func (f *textFormatter) appendValue(b *bytes.Buffer, value interface{}) { + stringVal, ok := value.(string) + if !ok { + stringVal = fmt.Sprint(value) + } + + if !f.needsQuoting(stringVal) { + b.WriteString(stringVal) + } else { + b.WriteString(fmt.Sprintf("%q", stringVal)) + } +} + +func prefixFieldClashes(data logrus.Fields) { + if t, ok := data["time"]; ok { + data["fields.time"] = t + } + + if m, ok := data["msg"]; ok { + data["fields.msg"] = m + } + + if l, ok := data["level"]; ok { + data["fields.level"] = l + } +} diff --git a/options.go b/options.go index 3c96cf340..f298553c4 100644 --- a/options.go +++ b/options.go @@ -6,10 +6,12 @@ import ( "log" "net/http" + "github.com/fatih/color" "github.com/gobuffalo/buffalo/worker" "github.com/gobuffalo/envy" "github.com/gorilla/sessions" "github.com/markbates/going/defaults" + "github.com/markbates/pop" ) // Options are used to configure and define how your application should run. @@ -63,6 +65,21 @@ func optionsWithDefaults(opts Options) Options { opts.Logger = NewLogger(opts.LogLevel) } + pop.Log = func(s string, args ...interface{}) { + if pop.Debug { + l := opts.Logger + if len(args) > 0 { + for i, a := range args { + l = l.WithField(fmt.Sprintf("$%d", i+1), a) + } + } + if pop.Color { + s = color.YellowString(s) + } + l.Debug(s) + } + } + if opts.SessionStore == nil { secret := envy.Get("SESSION_SECRET", "") // In production a SESSION_SECRET must be set! diff --git a/request_logger.go b/request_logger.go index 63612aa8b..077a015ca 100644 --- a/request_logger.go +++ b/request_logger.go @@ -44,7 +44,7 @@ func RequestLoggerFunc(h Handler) Handler { "human_size": humanize.Bytes(uint64(ws.Size)), "status": ws.Status, }) - c.Logger().Info() + c.Logger().Info(c.Request().URL.String()) }() return h(c) } From afc01765331effdbda3164a49b7f3c78f09f2f41 Mon Sep 17 00:00:00 2001 From: Mark Bates Date: Thu, 27 Jul 2017 13:08:21 -0400 Subject: [PATCH 2/2] deleted a bunch of the logging code we're not using --- logger.go | 3 +-- logger_formatter.go | 63 +++++---------------------------------------- 2 files changed, 8 insertions(+), 58 deletions(-) diff --git a/logger.go b/logger.go index b278769b4..ea6412cad 100644 --- a/logger.go +++ b/logger.go @@ -49,8 +49,7 @@ func NewLogger(level string) Logger { l := logrus.New() l.Level, _ = logrus.ParseLevel(level) l.Formatter = &textFormatter{ - ForceColors: dev, - FullTimestamp: true, + ForceColors: dev, } return logrusWrapper{l} } diff --git a/logger_formatter.go b/logger_formatter.go index e892d1ba8..62378c19e 100644 --- a/logger_formatter.go +++ b/logger_formatter.go @@ -22,44 +22,10 @@ const ( gray = 37 ) -var ( - baseTimestamp time.Time -) - -func init() { - baseTimestamp = time.Now() -} - // textFormatter formats logs into text type textFormatter struct { - // Set to true to bypass checking for a TTY before outputting colors. ForceColors bool - - // Force disabling colors. - DisableColors bool - - // Disable timestamp logging. useful when output is redirected to logging - // system that already adds timestamps. - DisableTimestamp bool - - // Enable logging the full timestamp when a TTY is attached instead of just - // the time passed since beginning of execution. - FullTimestamp bool - - // TimestampFormat to use for display when a full timestamp is printed - TimestampFormat string - - // The fields are sorted by default for a consistent output. For applications - // that log extremely frequently and don't use the JSON formatter this may not - // be desired. - DisableSorting bool - - // QuoteEmptyFields will wrap empty fields in quotes if true - QuoteEmptyFields bool - - // Whether the logger's out is to a terminal - isTerminal bool - + isTerminal bool sync.Once } @@ -79,9 +45,7 @@ func (f *textFormatter) Format(entry *logrus.Entry) ([]byte, error) { keys = append(keys, k) } - if !f.DisableSorting { - sort.Strings(keys) - } + sort.Strings(keys) if entry.Buffer != nil { b = entry.Buffer } else { @@ -92,18 +56,11 @@ func (f *textFormatter) Format(entry *logrus.Entry) ([]byte, error) { f.Do(func() { f.init(entry) }) - isColored := (f.ForceColors || f.isTerminal) && !f.DisableColors + isColored := (f.ForceColors || f.isTerminal) - timestampFormat := f.TimestampFormat - if timestampFormat == "" { - timestampFormat = defaultTimestampFormat - } if isColored { - f.printColored(b, entry, keys, timestampFormat) + f.printColored(b, entry, keys) } else { - if !f.DisableTimestamp { - f.appendKeyValue(b, "time", entry.Time.Format(timestampFormat)) - } f.appendKeyValue(b, "level", entry.Level.String()) if entry.Message != "" { f.appendKeyValue(b, "msg", entry.Message) @@ -117,7 +74,7 @@ func (f *textFormatter) Format(entry *logrus.Entry) ([]byte, error) { return b.Bytes(), nil } -func (f *textFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry, keys []string, timestampFormat string) { +func (f *textFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry, keys []string) { var levelColor int switch entry.Level { case logrus.DebugLevel: @@ -132,13 +89,7 @@ func (f *textFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry, keys levelText := strings.ToUpper(entry.Level.String())[0:4] - if f.DisableTimestamp { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m", levelColor, levelText) - } else if !f.FullTimestamp { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%04d]", levelColor, levelText, int(entry.Time.Sub(baseTimestamp)/time.Second)) - } else { - fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s]", levelColor, levelText, entry.Time.Format(timestampFormat)) - } + fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s]", levelColor, levelText, entry.Time.Format(defaultTimestampFormat)) if entry.Message != "" { fmt.Fprintf(b, " %s", entry.Message) @@ -152,7 +103,7 @@ func (f *textFormatter) printColored(b *bytes.Buffer, entry *logrus.Entry, keys } func (f *textFormatter) needsQuoting(text string) bool { - if f.QuoteEmptyFields && len(text) == 0 { + if len(text) == 0 { return true } for _, ch := range text {