Merge pull request #564 from gobuffalo/cleaned-up-logging

cleaned up logging by removing the big giant empty string. pop also now

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,11 @@ 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,
+	}
 	return logrusWrapper{l}
 }

logger_formatter.go

@@ -0,0 +1,154 @@
+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
+)
+
+// textFormatter formats logs into text
+type textFormatter struct {
+	ForceColors bool
+	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)
+	}
+
+	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)
+
+	if isColored {
+		f.printColored(b, entry, keys)
+	} else {
+		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) {
+	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]
+
+	fmt.Fprintf(b, "\x1b[%dm%s\x1b[0m[%s]", levelColor, levelText, entry.Time.Format(defaultTimestampFormat))
+
+	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 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
+	}
+}

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!

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)
 	}