Refactor logger

callbacks.go

@@ -90,9 +90,9 @@ func (p *processor) Execute(db *DB) {
 	}
 
 	if stmt := db.Statement; stmt != nil {
-		db.Logger.RunWith(logger.Info, func() {
-			db.Logger.Info(db.Dialector.Explain(stmt.SQL.String(), stmt.Vars))
-		})
+		db.Logger.Trace(curTime, func() (string, int64) {
+			return db.Dialector.Explain(stmt.SQL.String(), stmt.Vars), db.RowsAffected
+		}, db.Error)
 	}
 }
 

logger/logger.go

@@ -1,14 +1,29 @@
 package logger
 
 import (
-	"fmt"
 	"log"
 	"os"
+	"time"
+
+	"github.com/jinzhu/gorm/utils"
 )
 
-type LogLevel int
+// Colors
+const (
+	Reset      = "\033[0m"
+	Red        = "\033[31m"
+	Green      = "\033[32m"
+	Yellow     = "\033[33m"
+	Blue       = "\033[34m"
+	Magenta    = "\033[35m"
+	Cyan       = "\033[36m"
+	White      = "\033[37m"
+	Redbold    = "\033[31;1m"
+	YellowBold = "\033[33;1m"
+)
 
-var Default Interface = Logger{Writer: log.New(os.Stdout, "\r\n", log.LstdFlags)}
+// LogLevel
+type LogLevel int
 
 const (
 	Error LogLevel = iota + 1
@@ -16,52 +31,101 @@ const (
 	Info
 )
 
+// Writer log writer interface
+type Writer interface {
+	Printf(string, ...interface{})
+}
+
+type Config struct {
+	SlowThreshold time.Duration
+	Colorful      bool
+	LogLevel      LogLevel
+}
+
 // Interface logger interface
 type Interface interface {
 	LogMode(LogLevel) Interface
 	Info(string, ...interface{})
 	Warn(string, ...interface{})
 	Error(string, ...interface{})
-	RunWith(LogLevel, func())
+	Trace(begin time.Time, fc func() (string, int64), err error)
 }
 
-// Writer log writer interface
-type Writer interface {
-	Print(...interface{})
+var Default = New(log.New(os.Stdout, "\r\n", log.LstdFlags), Config{
+	SlowThreshold: 100 * time.Millisecond,
+	Colorful:      true,
+})
+
+func New(writer Writer, config Config) Interface {
+	var (
+		infoPrefix     = "%s\n[info] "
+		warnPrefix     = "%s\n[warn] "
+		errPrefix      = "%s\n[error] "
+		tracePrefix    = "%s\n[%v] [rows:%d] %s"
+		traceErrPrefix = "%s\n[%v] [rows:%d] %s"
+	)
+
+	if config.Colorful {
+		infoPrefix = Green + "%s\n" + Reset + Green + "[info]" + Reset
+		warnPrefix = Blue + "%s\n" + Reset + Magenta + "[warn]" + Reset
+		errPrefix = Magenta + "%s\n" + Reset + Red + "[error]" + Reset
+		tracePrefix = Green + "%s\n" + Reset + YellowBold + "[%.3fms] " + Green + "[rows:%d]" + Reset + " %s"
+		traceErrPrefix = Magenta + "%s\n" + Reset + Redbold + "[%.3fms] " + Yellow + "[rows:%d]" + Reset + " %s"
+	}
+
+	return logger{
+		Writer:         writer,
+		Config:         config,
+		infoPrefix:     infoPrefix,
+		warnPrefix:     warnPrefix,
+		errPrefix:      errPrefix,
+		tracePrefix:    tracePrefix,
+		traceErrPrefix: traceErrPrefix,
+	}
 }
 
-type Logger struct {
+type logger struct {
 	Writer
-	logLevel LogLevel
+	Config
+	infoPrefix, warnPrefix, errPrefix string
+	tracePrefix, traceErrPrefix       string
 }
 
-func (logger Logger) LogMode(level LogLevel) Interface {
-	return Logger{Writer: logger.Writer, logLevel: level}
+// LogMode log mode
+func (l logger) LogMode(level LogLevel) Interface {
+	config := l.Config
+	config.LogLevel = level
+	return logger{Writer: l.Writer, Config: config}
 }
 
 // Info print info
-func (logger Logger) Info(msg string, data ...interface{}) {
-	if logger.logLevel >= Info {
-		logger.Print("[info] " + fmt.Sprintf(msg, data...))
+func (l logger) Info(msg string, data ...interface{}) {
+	if l.LogLevel >= Info {
+		l.Printf(l.infoPrefix+msg, append([]interface{}{utils.FileWithLineNum()}, data...))
 	}
 }
 
 // Warn print warn messages
-func (logger Logger) Warn(msg string, data ...interface{}) {
-	if logger.logLevel >= Warn {
-		logger.Print("[warn] " + fmt.Sprintf(msg, data...))
+func (l logger) Warn(msg string, data ...interface{}) {
+	if l.LogLevel >= Warn {
+		l.Printf(l.warnPrefix+msg, append([]interface{}{utils.FileWithLineNum()}, data...))
 	}
 }
 
 // Error print error messages
-func (logger Logger) Error(msg string, data ...interface{}) {
-	if logger.logLevel >= Error {
-		logger.Print("[error] " + fmt.Sprintf(msg, data...))
+func (l logger) Error(msg string, data ...interface{}) {
+	if l.LogLevel >= Error {
+		l.Printf(l.errPrefix+msg, append([]interface{}{utils.FileWithLineNum()}, data...))
 	}
 }
 
-func (logger Logger) RunWith(logLevel LogLevel, fc func()) {
-	if logger.logLevel >= logLevel {
-		fc()
+// Trace print sql message
+func (l logger) Trace(begin time.Time, fc func() (string, int64), err error) {
+	if elapsed := time.Now().Sub(begin); err != nil || elapsed > l.SlowThreshold {
+		sql, rows := fc()
+		l.Printf(l.traceErrPrefix, utils.FileWithLineNum(), float64(elapsed.Nanoseconds())/1e6, rows, sql)
+	} else if l.LogLevel >= Info {
+		sql, rows := fc()
+		l.Printf(l.tracePrefix, utils.FileWithLineNum(), float64(elapsed.Nanoseconds())/1e6, rows, sql)
 	}
 }

tests/dummy_dialecter.go

@@ -2,6 +2,7 @@ package tests
 
 import (
 	"github.com/jinzhu/gorm"
+	"github.com/jinzhu/gorm/logger"
 	"github.com/jinzhu/gorm/schema"
 )
 
@@ -24,6 +25,10 @@ func (DummyDialector) QuoteChars() [2]byte {
 	return [2]byte{'`', '`'} // `name`
 }
 
+func (DummyDialector) Explain(sql string, vars ...interface{}) string {
+	return logger.ExplainSQL(sql, nil, `"`, vars...)
+}
+
 func (DummyDialector) DataTypeOf(*schema.Field) string {
 	return ""
 }

utils/utils.go

@@ -6,8 +6,8 @@ import (
 	"runtime"
 )
 
-var goSrcRegexp = regexp.MustCompile(`jinzhu/gorm/.*.go`)
-var goTestRegexp = regexp.MustCompile(`jinzhu/gorm/.*test.go`)
+var goSrcRegexp = regexp.MustCompile(`/gorm/.*.go`)
+var goTestRegexp = regexp.MustCompile(`/gorm/.*test.go`)
 
 func FileWithLineNum() string {
 	for i := 2; i < 15; i++ {