Browse Source

feat(logging): a lot of progress on moving to new logging lib, #4590

Torkel Ödegaard 9 years ago
parent
commit
22778e6efd

+ 1 - 1
conf/defaults.ini

@@ -273,7 +273,7 @@ log_rotate = true
 max_lines = 1000000
 
 # Max size shift of single file, default is 28 means 1 << 28, 256MB
-max_lines_shift = 28
+max_size_shift = 28
 
 # Segment log daily, default is true
 daily_rotate = true

+ 1 - 1
conf/sample.ini

@@ -253,7 +253,7 @@ check_for_updates = true
 ;max_lines = 1000000
 
 # Max size shift of single file, default is 28 means 1 << 28, 256MB
-;max_lines_shift = 28
+;max_size_shift = 28
 
 # Segment log daily, default is true
 ;daily_rotate = true

+ 1 - 0
pkg/api/dashboard.go

@@ -31,6 +31,7 @@ func isDashboardStarredByUser(c *middleware.Context, dashId int64) (bool, error)
 }
 
 func GetDashboard(c *middleware.Context) {
+	log.New("test", "asd").Error("muppets")
 	slug := strings.ToLower(c.Params(":slug"))
 
 	query := m.GetDashboardQuery{Slug: slug, OrgId: c.OrgId}

+ 6 - 1
pkg/cmd/grafana-server/main.go

@@ -39,7 +39,6 @@ func init() {
 }
 
 func main() {
-
 	v := flag.Bool("v", false, "prints current version and exits")
 	flag.Parse()
 	if *v {
@@ -48,11 +47,17 @@ func main() {
 	}
 
 	buildstampInt64, _ := strconv.ParseInt(buildstamp, 10, 64)
+	if buildstampInt64 == 0 {
+		buildstampInt64 = time.Now().Unix()
+	}
 
 	setting.BuildVersion = version
 	setting.BuildCommit = commit
 	setting.BuildStamp = buildstampInt64
 
+	logger := log.New("main")
+	logger.Info("Starting Grafana", "version", version, "commit", commit, "compiled", time.Unix(buildstampInt64, 0))
+
 	go listenToSystemSignels()
 
 	flag.Parse()

+ 9 - 3
pkg/cmd/grafana-server/web.go

@@ -6,6 +6,7 @@ package main
 import (
 	"fmt"
 	"net/http"
+	"os"
 	"path"
 
 	"gopkg.in/macaron.v1"
@@ -18,6 +19,8 @@ import (
 	"github.com/grafana/grafana/pkg/setting"
 )
 
+var logger log.Logger
+
 func newMacaron() *macaron.Macaron {
 	macaron.Env = setting.Env
 	m := macaron.New()
@@ -76,23 +79,26 @@ func mapStatic(m *macaron.Macaron, rootDir string, dir string, prefix string) {
 }
 
 func StartServer() {
+	logger = log.New("server")
 
 	var err error
 	m := newMacaron()
 	api.Register(m)
 
 	listenAddr := fmt.Sprintf("%s:%s", setting.HttpAddr, setting.HttpPort)
-	log.Info("Listen: %v://%s%s", setting.Protocol, listenAddr, setting.AppSubUrl)
+	logger.Info("Server Listening", "address", listenAddr, "protocol", setting.Protocol, "subUrl", setting.AppSubUrl)
 	switch setting.Protocol {
 	case setting.HTTP:
 		err = http.ListenAndServe(listenAddr, m)
 	case setting.HTTPS:
 		err = http.ListenAndServeTLS(listenAddr, setting.CertFile, setting.KeyFile, m)
 	default:
-		log.Fatal(4, "Invalid protocol: %s", setting.Protocol)
+		logger.Error("Invalid protocol", "protocol", setting.Protocol)
+		os.Exit(1)
 	}
 
 	if err != nil {
-		log.Fatal(4, "Fail to start server: %v", err)
+		logger.Error("Fail to start server", "error", err)
+		os.Exit(1)
 	}
 }

+ 0 - 157
pkg/log/console.go

@@ -1,157 +0,0 @@
-// Copyright 2014 The Gogs Authors. All rights reserved.
-// Use of this source code is governed by a MIT-style
-// license that can be found in the LICENSE file.
-
-package log
-
-import (
-	"encoding/json"
-	"fmt"
-	"log"
-	"os"
-	"runtime"
-)
-
-type Brush func(string) string
-
-func NewBrush(color string) Brush {
-	pre := "\033["
-	reset := "\033[0m"
-	return func(text string) string {
-		return pre + color + "m" + text + reset
-	}
-}
-
-var (
-	Red    = NewBrush("1;31")
-	Purple = NewBrush("1;35")
-	Yellow = NewBrush("1;33")
-	Green  = NewBrush("1;32")
-	Blue   = NewBrush("1;34")
-	Cyan   = NewBrush("1;36")
-
-	colors = []Brush{
-		Cyan,   // Trace      cyan
-		Blue,   // Debug      blue
-		Green,  // Info       green
-		Yellow, // Warn       yellow
-		Red,    // Error      red
-		Purple, // Critical   purple
-		Red,    // Fatal      red
-	}
-	consoleWriter = &ConsoleWriter{lg: log.New(os.Stdout, "", 0),
-		Level: TRACE}
-)
-
-// ConsoleWriter implements LoggerInterface and writes messages to terminal.
-type ConsoleWriter struct {
-	lg         *log.Logger
-	Level      LogLevel `json:"level"`
-	Formatting bool     `json:"formatting"`
-}
-
-// create ConsoleWriter returning as LoggerInterface.
-func NewConsole() LoggerInterface {
-	return &ConsoleWriter{
-		lg:         log.New(os.Stderr, "", log.Ldate|log.Ltime),
-		Level:      TRACE,
-		Formatting: true,
-	}
-}
-
-func (cw *ConsoleWriter) Init(config string) error {
-	return json.Unmarshal([]byte(config), cw)
-}
-
-func (cw *ConsoleWriter) WriteMsg(msg string, skip int, level LogLevel) error {
-	if cw.Level > level {
-		return nil
-	}
-	if runtime.GOOS == "windows" || !cw.Formatting {
-		cw.lg.Println(msg)
-	} else {
-		cw.lg.Println(colors[level](msg))
-	}
-	return nil
-}
-
-func (_ *ConsoleWriter) Flush() {
-
-}
-
-func (_ *ConsoleWriter) Destroy() {
-}
-
-func printConsole(level LogLevel, msg string) {
-	consoleWriter.WriteMsg(msg, 0, level)
-}
-
-func printfConsole(level LogLevel, format string, v ...interface{}) {
-	consoleWriter.WriteMsg(fmt.Sprintf(format, v...), 0, level)
-}
-
-// ConsoleTrace prints to stdout using TRACE colors
-func ConsoleTrace(s string) {
-	printConsole(TRACE, s)
-}
-
-// ConsoleTracef prints a formatted string to stdout using TRACE colors
-func ConsoleTracef(format string, v ...interface{}) {
-	printfConsole(TRACE, format, v...)
-}
-
-// ConsoleDebug prints to stdout using DEBUG colors
-func ConsoleDebug(s string) {
-	printConsole(DEBUG, s)
-}
-
-// ConsoleDebugf prints a formatted string to stdout using DEBUG colors
-func ConsoleDebugf(format string, v ...interface{}) {
-	printfConsole(DEBUG, format, v...)
-}
-
-// ConsoleInfo prints to stdout using INFO colors
-func ConsoleInfo(s string) {
-	printConsole(INFO, s)
-}
-
-// ConsoleInfof prints a formatted string to stdout using INFO colors
-func ConsoleInfof(format string, v ...interface{}) {
-	printfConsole(INFO, format, v...)
-}
-
-// ConsoleWarn prints to stdout using WARN colors
-func ConsoleWarn(s string) {
-	printConsole(WARN, s)
-}
-
-// ConsoleWarnf prints a formatted string to stdout using WARN colors
-func ConsoleWarnf(format string, v ...interface{}) {
-	printfConsole(WARN, format, v...)
-}
-
-// ConsoleError prints to stdout using ERROR colors
-func ConsoleError(s string) {
-	printConsole(ERROR, s)
-}
-
-// ConsoleErrorf prints a formatted string to stdout using ERROR colors
-func ConsoleErrorf(format string, v ...interface{}) {
-	printfConsole(ERROR, format, v...)
-}
-
-// ConsoleFatal prints to stdout using FATAL colors
-func ConsoleFatal(s string) {
-	printConsole(FATAL, s)
-	os.Exit(1)
-}
-
-// ConsoleFatalf prints a formatted string to stdout using FATAL colors
-func ConsoleFatalf(format string, v ...interface{}) {
-	printfConsole(FATAL, format, v...)
-	os.Exit(1)
-}
-
-func init() {
-	Register("console", NewConsole)
-}

+ 21 - 48
pkg/log/file.go

@@ -5,43 +5,39 @@
 package log
 
 import (
-	"encoding/json"
 	"errors"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"os"
 	"path/filepath"
 	"strings"
 	"sync"
 	"time"
+
+	"github.com/inconshreveable/log15"
 )
 
 // FileLogWriter implements LoggerInterface.
 // It writes messages by lines limit, file size limit, or time frequency.
 type FileLogWriter struct {
-	*log.Logger
 	mw *MuxWriter
-	// The opened file
-	Filename string `json:"filename"`
 
-	Maxlines          int `json:"maxlines"`
+	Format            log15.Format
+	Filename          string
+	Maxlines          int
 	maxlines_curlines int
 
 	// Rotate at size
-	Maxsize         int `json:"maxsize"`
+	Maxsize         int
 	maxsize_cursize int
 
 	// Rotate daily
-	Daily          bool  `json:"daily"`
-	Maxdays        int64 `json:"maxdays"`
+	Daily          bool
+	Maxdays        int64
 	daily_opendate int
 
-	Rotate bool `json:"rotate"`
-
-	startLock sync.Mutex // Only one log can write to the file
-
-	Level LogLevel `json:"level"`
+	Rotate    bool
+	startLock sync.Mutex
 }
 
 // an *os.File writer with locker.
@@ -66,37 +62,29 @@ func (l *MuxWriter) SetFd(fd *os.File) {
 }
 
 // create a FileLogWriter returning as LoggerInterface.
-func NewFileWriter() LoggerInterface {
+func NewFileWriter() *FileLogWriter {
 	w := &FileLogWriter{
 		Filename: "",
+		Format:   log15.LogfmtFormat(),
 		Maxlines: 1000000,
 		Maxsize:  1 << 28, //256 MB
 		Daily:    true,
 		Maxdays:  7,
 		Rotate:   true,
-		Level:    TRACE,
 	}
 	// use MuxWriter instead direct use os.File for lock write when rotate
 	w.mw = new(MuxWriter)
-	// set MuxWriter as Logger's io.Writer
-	w.Logger = log.New(w.mw, "", log.Ldate|log.Ltime)
 	return w
 }
 
-// Init file logger with json config.
-// config like:
-//	{
-//	"filename":"log/gogs.log",
-//	"maxlines":10000,
-//	"maxsize":1<<30,
-//	"daily":true,
-//	"maxdays":15,
-//	"rotate":true
-//	}
-func (w *FileLogWriter) Init(config string) error {
-	if err := json.Unmarshal([]byte(config), w); err != nil {
-		return err
-	}
+func (w *FileLogWriter) Log(r *log15.Record) error {
+	data := w.Format.Format(r)
+	w.docheck(len(data))
+	_, err := w.mw.Write(data)
+	return err
+}
+
+func (w *FileLogWriter) Init() error {
 	if len(w.Filename) == 0 {
 		return errors.New("config must have filename")
 	}
@@ -131,17 +119,6 @@ func (w *FileLogWriter) docheck(size int) {
 	w.maxsize_cursize += size
 }
 
-// write logger message into file.
-func (w *FileLogWriter) WriteMsg(msg string, skip int, level LogLevel) error {
-	if level < w.Level {
-		return nil
-	}
-	n := 24 + len(msg) // 24 stand for the length "2013/06/23 21:00:22 [T] "
-	w.docheck(n)
-	w.Logger.Println(msg)
-	return nil
-}
-
 func (w *FileLogWriter) createLogFile() (*os.File, error) {
 	// Open the log file
 	return os.OpenFile(w.Filename, os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0644)
@@ -227,7 +204,7 @@ func (w *FileLogWriter) deleteOldLog() {
 }
 
 // destroy file logger, close file writer.
-func (w *FileLogWriter) Destroy() {
+func (w *FileLogWriter) Close() {
 	w.mw.fd.Close()
 }
 
@@ -237,7 +214,3 @@ func (w *FileLogWriter) Destroy() {
 func (w *FileLogWriter) Flush() {
 	w.mw.fd.Sync()
 }
-
-func init() {
-	Register("file", NewFileWriter)
-}

+ 5 - 0
pkg/log/handlers.go

@@ -0,0 +1,5 @@
+package log
+
+type DisposableHandler interface {
+	Close()
+}

+ 31 - 0
pkg/log/interface.go

@@ -0,0 +1,31 @@
+package log
+
+import "github.com/inconshreveable/log15"
+
+type Lvl int
+
+const (
+	LvlCrit Lvl = iota
+	LvlError
+	LvlWarn
+	LvlInfo
+	LvlDebug
+)
+
+type Logger interface {
+	// New returns a new Logger that has this logger's context plus the given context
+	New(ctx ...interface{}) log15.Logger
+
+	// GetHandler gets the handler associated with the logger.
+	GetHandler() log15.Handler
+
+	// SetHandler updates the logger to write records to the specified handler.
+	SetHandler(h log15.Handler)
+
+	// Log a message at the given level with context key/value pairs
+	Debug(msg string, ctx ...interface{})
+	Info(msg string, ctx ...interface{})
+	Warn(msg string, ctx ...interface{})
+	Error(msg string, ctx ...interface{})
+	Crit(msg string, ctx ...interface{})
+}

+ 114 - 271
pkg/log/log.go

@@ -8,324 +8,167 @@ import (
 	"fmt"
 	"os"
 	"path/filepath"
-	"runtime"
 	"strings"
-	"sync"
-)
 
-var (
-	loggers []*Logger
+	"gopkg.in/ini.v1"
+
+	"github.com/inconshreveable/log15"
 )
 
-func NewLogger(bufLen int64, mode, config string) {
-	logger := newLogger(bufLen)
+var rootLogger log15.Logger
+var loggersToClose []DisposableHandler
 
-	isExist := false
-	for _, l := range loggers {
-		if l.adapter == mode {
-			isExist = true
-			l = logger
-		}
-	}
-	if !isExist {
-		loggers = append(loggers, logger)
-	}
-	if err := logger.SetLogger(mode, config); err != nil {
-		Fatal(1, "Fail to set logger(%s): %v", mode, err)
-	}
+func init() {
+	loggersToClose = make([]DisposableHandler, 0)
+	rootLogger = log15.Root()
 }
 
-// this helps you work around the performance annoyance mentioned in
-// https://github.com/grafana/grafana/issues/4055
-// until we refactor this library completely
-func Level(level LogLevel) {
-	for i := range loggers {
-		loggers[i].level = level
-	}
+func New(logger string, ctx ...interface{}) Logger {
+	params := append([]interface{}{"logger", logger}, ctx...)
+	return rootLogger.New(params...)
 }
 
 func Trace(format string, v ...interface{}) {
-	for _, logger := range loggers {
-		logger.Trace(format, v...)
-	}
+	rootLogger.Debug(fmt.Sprintf(format, v))
 }
 
 func Debug(format string, v ...interface{}) {
-	for _, logger := range loggers {
-		logger.Debug(format, v...)
-	}
+	rootLogger.Debug(fmt.Sprintf(format, v))
 }
 
-func Info(format string, v ...interface{}) {
-	for _, logger := range loggers {
-		logger.Info(format, v...)
-	}
+func Debug2(message string, v ...interface{}) {
+	rootLogger.Debug(message, v...)
 }
 
-func Warn(format string, v ...interface{}) {
-	for _, logger := range loggers {
-		logger.Warn(format, v...)
-	}
+func Info(format string, v ...interface{}) {
+	rootLogger.Info(fmt.Sprintf(format, v))
 }
 
-func Error(skip int, format string, v ...interface{}) {
-	for _, logger := range loggers {
-		logger.Error(skip, format, v...)
-	}
+func Info2(message string, v ...interface{}) {
+	rootLogger.Info(message, v...)
 }
 
-func Critical(skip int, format string, v ...interface{}) {
-	for _, logger := range loggers {
-		logger.Critical(skip, format, v...)
-	}
-}
-
-func Fatal(skip int, format string, v ...interface{}) {
-	Error(skip, format, v...)
-	for _, l := range loggers {
-		l.Close()
-	}
-	os.Exit(1)
+func Warn(format string, v ...interface{}) {
+	rootLogger.Warn(fmt.Sprintf(format, v))
 }
 
-func Close() {
-	for _, l := range loggers {
-		l.Close()
-		// delete the logger.
-		l = nil
-	}
-	// clear the loggers slice.
-	loggers = nil
+func Warn2(message string, v ...interface{}) {
+	rootLogger.Warn(message, v...)
 }
 
-// .___        __                 _____
-// |   | _____/  |_  ____________/ ____\____    ____  ____
-// |   |/    \   __\/ __ \_  __ \   __\\__  \ _/ ___\/ __ \
-// |   |   |  \  | \  ___/|  | \/|  |   / __ \\  \__\  ___/
-// |___|___|  /__|  \___  >__|   |__|  (____  /\___  >___  >
-//          \/          \/                  \/     \/    \/
-
-type LogLevel int
-
-const (
-	TRACE LogLevel = iota
-	DEBUG
-	INFO
-	WARN
-	ERROR
-	CRITICAL
-	FATAL
-)
-
-// LoggerInterface represents behaviors of a logger provider.
-type LoggerInterface interface {
-	Init(config string) error
-	WriteMsg(msg string, skip int, level LogLevel) error
-	Destroy()
-	Flush()
+func Error(skip int, format string, v ...interface{}) {
+	rootLogger.Error(fmt.Sprintf(format, v))
 }
 
-type loggerType func() LoggerInterface
-
-var adapters = make(map[string]loggerType)
-
-// Register registers given logger provider to adapters.
-func Register(name string, log loggerType) {
-	if log == nil {
-		panic("log: register provider is nil")
-	}
-	if _, dup := adapters[name]; dup {
-		panic("log: register called twice for provider \"" + name + "\"")
-	}
-	adapters[name] = log
+func Error2(message string, v ...interface{}) {
+	rootLogger.Error(message, v...)
 }
 
-type logMsg struct {
-	skip  int
-	level LogLevel
-	msg   string
+func Critical(skip int, format string, v ...interface{}) {
+	rootLogger.Crit(fmt.Sprintf(format, v))
 }
 
-// Logger is default logger in beego application.
-// it can contain several providers and log message into all providers.
-type Logger struct {
-	adapter string
-	lock    sync.Mutex
-	level   LogLevel
-	msg     chan *logMsg
-	outputs map[string]LoggerInterface
-	quit    chan bool
+func Fatal(skip int, format string, v ...interface{}) {
+	rootLogger.Crit(fmt.Sprintf(format, v))
+	Close()
+	os.Exit(1)
 }
 
-// newLogger initializes and returns a new logger.
-func newLogger(buffer int64) *Logger {
-	l := &Logger{
-		msg:     make(chan *logMsg, buffer),
-		outputs: make(map[string]LoggerInterface),
-		quit:    make(chan bool),
+func Close() {
+	for _, logger := range loggersToClose {
+		logger.Close()
 	}
-	go l.StartLogger()
-	return l
+	loggersToClose = make([]DisposableHandler, 0)
 }
 
-// SetLogger sets new logger instanse with given logger adapter and config.
-func (l *Logger) SetLogger(adapter string, config string) error {
-	l.lock.Lock()
-	defer l.lock.Unlock()
-	if log, ok := adapters[adapter]; ok {
-		lg := log()
-		if err := lg.Init(config); err != nil {
-			return err
-		}
-		l.outputs[adapter] = lg
-		l.adapter = adapter
-	} else {
-		panic("log: unknown adapter \"" + adapter + "\" (forgotten register?)")
-	}
-	return nil
+var logLevels = map[string]log15.Lvl{
+	"Trace":    log15.LvlDebug,
+	"Debug":    log15.LvlDebug,
+	"Info":     log15.LvlInfo,
+	"Warn":     log15.LvlWarn,
+	"Error":    log15.LvlError,
+	"Critical": log15.LvlCrit,
 }
 
-// DelLogger removes a logger adapter instance.
-func (l *Logger) DelLogger(adapter string) error {
-	l.lock.Lock()
-	defer l.lock.Unlock()
-	if lg, ok := l.outputs[adapter]; ok {
-		lg.Destroy()
-		delete(l.outputs, adapter)
-	} else {
-		panic("log: unknown adapter \"" + adapter + "\" (forgotten register?)")
-	}
-	return nil
-}
+func getLogLevel(key string, defaultName string, cfg *ini.File) (string, log15.Lvl) {
+	levelName := cfg.Section(key).Key("level").In(defaultName, []string{"Trace", "Debug", "Info", "Warn", "Error", "Critical"})
 
-func (l *Logger) writerMsg(skip int, level LogLevel, msg string) error {
-	lm := &logMsg{
-		skip:  skip,
-		level: level,
+	level, ok := logLevels[levelName]
+	if !ok {
+		rootLogger.Error("Unknown log level", "level", levelName)
 	}
 
-	// Only error information needs locate position for debugging.
-	if lm.level >= ERROR {
-		pc, file, line, ok := runtime.Caller(skip)
-		if ok {
-			// Get caller function name.
-			fn := runtime.FuncForPC(pc)
-			var fnName string
-			if fn == nil {
-				fnName = "?()"
-			} else {
-				fnName = strings.TrimLeft(filepath.Ext(fn.Name()), ".") + "()"
-			}
-
-			lm.msg = fmt.Sprintf("[%s:%d %s] %s", filepath.Base(file), line, fnName, msg)
-		} else {
-			lm.msg = msg
-		}
-	} else {
-		lm.msg = msg
-	}
-	l.msg <- lm
-	return nil
+	return levelName, level
 }
 
-// StartLogger starts logger chan reading.
-func (l *Logger) StartLogger() {
-	for {
-		select {
-		case bm := <-l.msg:
-			for _, l := range l.outputs {
-				if err := l.WriteMsg(bm.msg, bm.skip, bm.level); err != nil {
-					fmt.Println("ERROR, unable to WriteMsg:", err)
-				}
-			}
-		case <-l.quit:
-			return
-		}
-	}
-}
+func ReadLoggingConfig(modes []string, logsPath string, cfg *ini.File) {
+	Close()
 
-// Flush flushs all chan data.
-func (l *Logger) Flush() {
-	for _, l := range l.outputs {
-		l.Flush()
-	}
-}
+	defaultLevelName, _ := getLogLevel("log", "Info", cfg)
+	handlers := make([]log15.Handler, 0)
 
-// Close closes logger, flush all chan data and destroy all adapter instances.
-func (l *Logger) Close() {
-	l.quit <- true
-	for {
-		if len(l.msg) > 0 {
-			bm := <-l.msg
-			for _, l := range l.outputs {
-				if err := l.WriteMsg(bm.msg, bm.skip, bm.level); err != nil {
-					fmt.Println("ERROR, unable to WriteMsg:", err)
-				}
-			}
-		} else {
-			break
+	for _, mode := range modes {
+		mode = strings.TrimSpace(mode)
+		sec, err := cfg.GetSection("log." + mode)
+		if err != nil {
+			rootLogger.Error("Unknown log mode", "mode", mode)
 		}
-	}
-	for _, l := range l.outputs {
-		l.Flush()
-		l.Destroy()
-	}
-}
-
-func (l *Logger) Trace(format string, v ...interface{}) {
-	if l.level > TRACE {
-		return
-	}
-	msg := fmt.Sprintf("[T] "+format, v...)
-	l.writerMsg(0, TRACE, msg)
-}
-
-func (l *Logger) Debug(format string, v ...interface{}) {
-	if l.level > DEBUG {
-		return
-	}
-	msg := fmt.Sprintf("[D] "+format, v...)
-	l.writerMsg(0, DEBUG, msg)
-}
-
-func (l *Logger) Info(format string, v ...interface{}) {
-	if l.level > INFO {
-		return
-	}
-	msg := fmt.Sprintf("[I] "+format, v...)
-	l.writerMsg(0, INFO, msg)
-}
-
-func (l *Logger) Warn(format string, v ...interface{}) {
-	if l.level > WARN {
-		return
-	}
-	msg := fmt.Sprintf("[W] "+format, v...)
-	l.writerMsg(0, WARN, msg)
-}
-
-func (l *Logger) Error(skip int, format string, v ...interface{}) {
-	if l.level > ERROR {
-		return
-	}
-	msg := fmt.Sprintf("[E] "+format, v...)
-	l.writerMsg(skip, ERROR, msg)
-}
 
-func (l *Logger) Critical(skip int, format string, v ...interface{}) {
-	if l.level > CRITICAL {
-		return
+		// Log level.
+		_, level := getLogLevel("log."+mode, defaultLevelName, cfg)
+
+		// Generate log configuration.
+		switch mode {
+		case "console":
+			handlers = append(handlers, log15.LvlFilterHandler(level, log15.StdoutHandler))
+		case "file":
+			fileName := sec.Key("file_name").MustString(filepath.Join(logsPath, "grafana.log"))
+			os.MkdirAll(filepath.Dir(fileName), os.ModePerm)
+			fileHandler := NewFileWriter()
+			fileHandler.Filename = fileName
+			fileHandler.Rotate = sec.Key("log_rotate").MustBool(true)
+			fileHandler.Maxlines = sec.Key("max_lines").MustInt(1000000)
+			fileHandler.Maxsize = 1 << uint(sec.Key("max_size_shift").MustInt(28))
+			fileHandler.Daily = sec.Key("daily_rotate").MustBool(true)
+			fileHandler.Maxdays = sec.Key("max_days").MustInt64(7)
+			fileHandler.Init()
+
+			loggersToClose = append(loggersToClose, fileHandler)
+			handlers = append(handlers, log15.LazyHandler(fileHandler))
+
+			// case "conn":
+			// 	LogConfigs[i] = util.DynMap{
+			// 		"level":          level,
+			// 		"reconnectOnMsg": sec.Key("reconnect_on_msg").MustBool(),
+			// 		"reconnect":      sec.Key("reconnect").MustBool(),
+			// 		"net":            sec.Key("protocol").In("tcp", []string{"tcp", "unix", "udp"}),
+			// 		"addr":           sec.Key("addr").MustString(":7020"),
+			// 	}
+			// case "smtp":
+			// 	LogConfigs[i] = util.DynMap{
+			// 		"level":     level,
+			// 		"user":      sec.Key("user").MustString("example@example.com"),
+			// 		"passwd":    sec.Key("passwd").MustString("******"),
+			// 		"host":      sec.Key("host").MustString("127.0.0.1:25"),
+			// 		"receivers": sec.Key("receivers").MustString("[]"),
+			// 		"subject":   sec.Key("subject").MustString("Diagnostic message from serve"),
+			// 	}
+			// case "database":
+			// 	LogConfigs[i] = util.DynMap{
+			// 		"level":  level,
+			// 		"driver": sec.Key("driver").String(),
+			// 		"conn":   sec.Key("conn").String(),
+			// 	}
+			// case "syslog":
+			// 	LogConfigs[i] = util.DynMap{
+			// 		"level":    level,
+			// 		"network":  sec.Key("network").MustString(""),
+			// 		"address":  sec.Key("address").MustString(""),
+			// 		"facility": sec.Key("facility").MustString("local7"),
+			// 		"tag":      sec.Key("tag").MustString(""),
+			// 	}
+		}
 	}
-	msg := fmt.Sprintf("[C] "+format, v...)
-	l.writerMsg(skip, CRITICAL, msg)
-}
 
-func (l *Logger) Fatal(skip int, format string, v ...interface{}) {
-	if l.level > FATAL {
-		return
-	}
-	msg := fmt.Sprintf("[F] "+format, v...)
-	l.writerMsg(skip, FATAL, msg)
-	l.Close()
-	os.Exit(1)
+	rootLogger.SetHandler(log15.MultiHandler(handlers...))
 }

+ 92 - 91
pkg/log/syslog.go

@@ -2,94 +2,95 @@
 
 package log
 
-import (
-	"encoding/json"
-	"errors"
-	"log/syslog"
-)
-
-type SyslogWriter struct {
-	syslog   *syslog.Writer
-	Network  string `json:"network"`
-	Address  string `json:"address"`
-	Facility string `json:"facility"`
-	Tag      string `json:"tag"`
-}
-
-func NewSyslog() LoggerInterface {
-	return new(SyslogWriter)
-}
-
-func (sw *SyslogWriter) Init(config string) error {
-	if err := json.Unmarshal([]byte(config), sw); err != nil {
-		return err
-	}
-
-	prio, err := parseFacility(sw.Facility)
-	if err != nil {
-		return err
-	}
-
-	w, err := syslog.Dial(sw.Network, sw.Address, prio, sw.Tag)
-	if err != nil {
-		return err
-	}
-
-	sw.syslog = w
-	return nil
-}
-
-func (sw *SyslogWriter) WriteMsg(msg string, skip int, level LogLevel) error {
-	var err error
-
-	switch level {
-	case TRACE, DEBUG:
-		err = sw.syslog.Debug(msg)
-	case INFO:
-		err = sw.syslog.Info(msg)
-	case WARN:
-		err = sw.syslog.Warning(msg)
-	case ERROR:
-		err = sw.syslog.Err(msg)
-	case CRITICAL:
-		err = sw.syslog.Crit(msg)
-	case FATAL:
-		err = sw.syslog.Alert(msg)
-	default:
-		err = errors.New("invalid syslog level")
-	}
-
-	return err
-}
-
-func (sw *SyslogWriter) Destroy() {
-	sw.syslog.Close()
-}
-
-func (sw *SyslogWriter) Flush() {}
-
-var facilities = map[string]syslog.Priority{
-	"user":   syslog.LOG_USER,
-	"daemon": syslog.LOG_DAEMON,
-	"local0": syslog.LOG_LOCAL0,
-	"local1": syslog.LOG_LOCAL1,
-	"local2": syslog.LOG_LOCAL2,
-	"local3": syslog.LOG_LOCAL3,
-	"local4": syslog.LOG_LOCAL4,
-	"local5": syslog.LOG_LOCAL5,
-	"local6": syslog.LOG_LOCAL6,
-	"local7": syslog.LOG_LOCAL7,
-}
-
-func parseFacility(facility string) (syslog.Priority, error) {
-	prio, ok := facilities[facility]
-	if !ok {
-		return syslog.LOG_LOCAL0, errors.New("invalid syslog facility")
-	}
-
-	return prio, nil
-}
-
-func init() {
-	Register("syslog", NewSyslog)
-}
+//
+// import (
+// 	"encoding/json"
+// 	"errors"
+// 	"log/syslog"
+// )
+//
+// type SyslogWriter struct {
+// 	syslog   *syslog.Writer
+// 	Network  string `json:"network"`
+// 	Address  string `json:"address"`
+// 	Facility string `json:"facility"`
+// 	Tag      string `json:"tag"`
+// }
+//
+// func NewSyslog() LoggerInterface {
+// 	return new(SyslogWriter)
+// }
+//
+// func (sw *SyslogWriter) Init(config string) error {
+// 	if err := json.Unmarshal([]byte(config), sw); err != nil {
+// 		return err
+// 	}
+//
+// 	prio, err := parseFacility(sw.Facility)
+// 	if err != nil {
+// 		return err
+// 	}
+//
+// 	w, err := syslog.Dial(sw.Network, sw.Address, prio, sw.Tag)
+// 	if err != nil {
+// 		return err
+// 	}
+//
+// 	sw.syslog = w
+// 	return nil
+// }
+//
+// func (sw *SyslogWriter) WriteMsg(msg string, skip int, level LogLevel) error {
+// 	var err error
+//
+// 	switch level {
+// 	case TRACE, DEBUG:
+// 		err = sw.syslog.Debug(msg)
+// 	case INFO:
+// 		err = sw.syslog.Info(msg)
+// 	case WARN:
+// 		err = sw.syslog.Warning(msg)
+// 	case ERROR:
+// 		err = sw.syslog.Err(msg)
+// 	case CRITICAL:
+// 		err = sw.syslog.Crit(msg)
+// 	case FATAL:
+// 		err = sw.syslog.Alert(msg)
+// 	default:
+// 		err = errors.New("invalid syslog level")
+// 	}
+//
+// 	return err
+// }
+//
+// func (sw *SyslogWriter) Destroy() {
+// 	sw.syslog.Close()
+// }
+//
+// func (sw *SyslogWriter) Flush() {}
+//
+// var facilities = map[string]syslog.Priority{
+// 	"user":   syslog.LOG_USER,
+// 	"daemon": syslog.LOG_DAEMON,
+// 	"local0": syslog.LOG_LOCAL0,
+// 	"local1": syslog.LOG_LOCAL1,
+// 	"local2": syslog.LOG_LOCAL2,
+// 	"local3": syslog.LOG_LOCAL3,
+// 	"local4": syslog.LOG_LOCAL4,
+// 	"local5": syslog.LOG_LOCAL5,
+// 	"local6": syslog.LOG_LOCAL6,
+// 	"local7": syslog.LOG_LOCAL7,
+// }
+//
+// func parseFacility(facility string) (syslog.Priority, error) {
+// 	prio, ok := facilities[facility]
+// 	if !ok {
+// 		return syslog.LOG_LOCAL0, errors.New("invalid syslog facility")
+// 	}
+//
+// 	return prio, nil
+// }
+//
+// func init() {
+// 	Register("syslog", NewSyslog)
+// }

+ 5 - 11
pkg/middleware/logger.go

@@ -16,11 +16,9 @@
 package middleware
 
 import (
-	"fmt"
 	"net/http"
 	"time"
 
-	"github.com/grafana/grafana/pkg/log"
 	"github.com/grafana/grafana/pkg/metrics"
 	"github.com/grafana/grafana/pkg/setting"
 	"gopkg.in/macaron.v1"
@@ -40,25 +38,21 @@ func Logger() macaron.Handler {
 		c.Next()
 
 		timeTakenMs := time.Since(start) / time.Millisecond
-		content := fmt.Sprintf("Completed %s %s \"%s %s %s\" %v %s %d bytes in %dms", c.RemoteAddr(), uname, req.Method, req.URL.Path, req.Proto, rw.Status(), http.StatusText(rw.Status()), rw.Size(), timeTakenMs)
 
 		if timer, ok := c.Data["perfmon.timer"]; ok {
 			timerTyped := timer.(metrics.Timer)
 			timerTyped.Update(timeTakenMs)
 		}
 
-		switch rw.Status() {
-		case 200, 304:
-			content = fmt.Sprintf("%s", content)
+		status := rw.Status()
+		if status == 200 || status == 304 {
 			if !setting.RouterLogging {
 				return
 			}
-		case 404:
-			content = fmt.Sprintf("%s", content)
-		case 500:
-			content = fmt.Sprintf("%s", content)
 		}
 
-		log.Info(content)
+		if ctx, ok := c.Data["ctx"]; ok {
+			ctx.(*Context).Logger.Info("Request Completed", "method", req.Method, "path", req.URL.Path, "status", status, "remote_addr", c.RemoteAddr(), "uname", uname, "time_ms", timeTakenMs, "size", rw.Size())
+		}
 	}
 }

+ 8 - 0
pkg/middleware/middleware.go

@@ -1,6 +1,7 @@
 package middleware
 
 import (
+	"fmt"
 	"strconv"
 	"strings"
 
@@ -23,6 +24,7 @@ type Context struct {
 
 	IsSignedIn     bool
 	AllowAnonymous bool
+	Logger         log.Logger
 }
 
 func GetContextHandler() macaron.Handler {
@@ -33,6 +35,7 @@ func GetContextHandler() macaron.Handler {
 			Session:        GetSession(),
 			IsSignedIn:     false,
 			AllowAnonymous: false,
+			Logger:         log.New("context"),
 		}
 
 		// the order in which these are tested are important
@@ -48,6 +51,11 @@ func GetContextHandler() macaron.Handler {
 			initContextWithAnonymousUser(ctx) {
 		}
 
+		ctx.Logger = log.New("context", "user", ctx.UserId, "orgId", ctx.OrgId)
+		// set ctx in data array on the original context
+		c.Data["ctx"] = ctx
+		fmt.Printf("c: %v\n", c)
+
 		c.Map(ctx)
 	}
 }

+ 1 - 2
pkg/plugins/models.go

@@ -6,7 +6,6 @@ import (
 	"fmt"
 	"strings"
 
-	"github.com/grafana/grafana/pkg/log"
 	m "github.com/grafana/grafana/pkg/models"
 	"github.com/grafana/grafana/pkg/setting"
 )
@@ -58,7 +57,7 @@ func (pb *PluginBase) registerPlugin(pluginDir string) error {
 	}
 
 	if !strings.HasPrefix(pluginDir, setting.StaticRootPath) {
-		log.Info("Plugins: Registering plugin %v", pb.Name)
+		plog.Info("Registering plugin", "name", pb.Name)
 	}
 
 	if len(pb.Dependencies.Plugins) == 0 {

+ 7 - 4
pkg/plugins/plugins.go

@@ -25,6 +25,7 @@ var (
 
 	GrafanaLatestVersion string
 	GrafanaHasUpdate     bool
+	plog                 log.Logger
 )
 
 type PluginScanner struct {
@@ -33,6 +34,8 @@ type PluginScanner struct {
 }
 
 func Init() error {
+	plog = log.New("plugins")
+
 	DataSources = make(map[string]*DataSourcePlugin)
 	StaticRoutes = make([]*PluginStaticRoute, 0)
 	Panels = make(map[string]*PanelPlugin)
@@ -44,16 +47,16 @@ func Init() error {
 		"app":        AppPlugin{},
 	}
 
-	log.Info("Plugins: Scan starting")
+	plog.Info("Starting plugin search")
 	scan(path.Join(setting.StaticRootPath, "app/plugins"))
 
 	// check if plugins dir exists
 	if _, err := os.Stat(setting.PluginsPath); os.IsNotExist(err) {
-		log.Warn("Plugins: Plugin dir %v does not exist", setting.PluginsPath)
+		plog.Warn("Plugin dir does not exist", "dir", setting.PluginsPath)
 		if err = os.MkdirAll(setting.PluginsPath, os.ModePerm); err != nil {
-			log.Warn("Plugins: Failed to create plugin dir: %v, error: %v", setting.PluginsPath, err)
+			plog.Warn("Failed to create plugin dir", "dir", setting.PluginsPath, "error", err)
 		} else {
-			log.Info("Plugins: Plugin dir %v created", setting.PluginsPath)
+			plog.Info("Plugin dir created", "dir", setting.PluginsPath)
 			scan(setting.PluginsPath)
 		}
 	} else {

+ 9 - 18
pkg/services/sqlstore/migrator/migrator.go

@@ -11,11 +11,10 @@ import (
 )
 
 type Migrator struct {
-	LogLevel log.LogLevel
-
 	x          *xorm.Engine
 	dialect    Dialect
 	migrations []Migration
+	Logger     log.Logger
 }
 
 type MigrationLog struct {
@@ -30,7 +29,7 @@ type MigrationLog struct {
 func NewMigrator(engine *xorm.Engine) *Migrator {
 	mg := &Migrator{}
 	mg.x = engine
-	mg.LogLevel = log.WARN
+	mg.Logger = log.New("Migrator")
 	mg.migrations = make([]Migration, 0)
 	mg.dialect = NewDialect(mg.x.DriverName())
 	return mg
@@ -69,9 +68,7 @@ func (mg *Migrator) GetMigrationLog() (map[string]MigrationLog, error) {
 }
 
 func (mg *Migrator) Start() error {
-	if mg.LogLevel <= log.INFO {
-		log.Info("Migrator: Starting DB migration")
-	}
+	mg.Logger.Info("Starting DB migration")
 
 	logMap, err := mg.GetMigrationLog()
 	if err != nil {
@@ -81,9 +78,7 @@ func (mg *Migrator) Start() error {
 	for _, m := range mg.migrations {
 		_, exists := logMap[m.Id()]
 		if exists {
-			if mg.LogLevel <= log.DEBUG {
-				log.Debug("Migrator: Skipping migration: %v, Already executed", m.Id())
-			}
+			mg.Logger.Debug("Skipping migration: Already executed", "id", m.Id())
 			continue
 		}
 
@@ -95,12 +90,10 @@ func (mg *Migrator) Start() error {
 			Timestamp:   time.Now(),
 		}
 
-		if mg.LogLevel <= log.DEBUG {
-			log.Debug("Migrator: Executing SQL: \n %v \n", sql)
-		}
+		mg.Logger.Debug("Executing", "sql", sql)
 
 		if err := mg.exec(m); err != nil {
-			log.Error(3, "Migrator: error: \n%s:\n%s", err, sql)
+			mg.Logger.Error("Exec failed", "error", err, "sql", sql)
 			record.Error = err.Error()
 			mg.x.Insert(&record)
 			return err
@@ -114,9 +107,7 @@ func (mg *Migrator) Start() error {
 }
 
 func (mg *Migrator) exec(m Migration) error {
-	if mg.LogLevel <= log.INFO {
-		log.Info("Migrator: exec migration id: %v", m.Id())
-	}
+	log.Info("Executing migration", "id", m.Id())
 
 	err := mg.inTransaction(func(sess *xorm.Session) error {
 
@@ -125,14 +116,14 @@ func (mg *Migrator) exec(m Migration) error {
 			sql, args := condition.Sql(mg.dialect)
 			results, err := sess.Query(sql, args...)
 			if err != nil || len(results) == 0 {
-				log.Info("Migrator: skipping migration id: %v, condition not fulfilled", m.Id())
+				mg.Logger.Info("Skipping migration condition not fulfilled", "id", m.Id())
 				return sess.Rollback()
 			}
 		}
 
 		_, err := sess.Exec(m.Sql(mg.dialect))
 		if err != nil {
-			log.Error(3, "Migrator: exec FAILED migration id: %v, err: %v", m.Id(), err)
+			mg.Logger.Error("Executing migration failed", "id", m.Id(), "error", err)
 			return err
 		}
 		return nil

+ 0 - 1
pkg/services/sqlstore/sqlstore.go

@@ -89,7 +89,6 @@ func SetEngine(engine *xorm.Engine, enableLog bool) (err error) {
 	dialect = migrator.NewDialect(x.DriverName())
 
 	migrator := migrator.NewMigrator(x)
-	migrator.LogLevel = log.INFO
 	migrations.AddMigrations(migrator)
 
 	if err := migrator.Start(); err != nil {

+ 4 - 99
pkg/setting/setting.go

@@ -5,7 +5,6 @@ package setting
 
 import (
 	"bytes"
-	"encoding/json"
 	"fmt"
 	"net/url"
 	"os"
@@ -149,7 +148,6 @@ type CommandLineArgs struct {
 
 func init() {
 	IsWindows = runtime.GOOS == "windows"
-	log.NewLogger(0, "console", `{"level": 0, "formatting":true}`)
 }
 
 func parseAppUrlAndSubUrl(section *ini.Section) (string, string) {
@@ -335,7 +333,7 @@ func loadConfiguration(args *CommandLineArgs) {
 
 	// init logging before specific config so we can log errors from here on
 	DataPath = makeAbsolute(Cfg.Section("paths").Key("data").String(), HomePath)
-	initLogging(args)
+	initLogging()
 
 	// load specified config file
 	loadSpecifedConfigFile(args.Config)
@@ -351,7 +349,7 @@ func loadConfiguration(args *CommandLineArgs) {
 
 	// update data path and logging config
 	DataPath = makeAbsolute(Cfg.Section("paths").Key("data").String(), HomePath)
-	initLogging(args)
+	initLogging()
 }
 
 func pathExists(path string) bool {
@@ -543,104 +541,11 @@ func readSessionConfig() {
 	}
 }
 
-var logLevels = map[string]int{
-	"Trace":    0,
-	"Debug":    1,
-	"Info":     2,
-	"Warn":     3,
-	"Error":    4,
-	"Critical": 5,
-}
-
-func getLogLevel(key string, defaultName string) (string, int) {
-	levelName := Cfg.Section(key).Key("level").In(defaultName, []string{"Trace", "Debug", "Info", "Warn", "Error", "Critical"})
-
-	level, ok := logLevels[levelName]
-	if !ok {
-		log.Fatal(4, "Unknown log level: %s", levelName)
-	}
-
-	return levelName, level
-}
-
-func initLogging(args *CommandLineArgs) {
-	//close any existing log handlers.
-	log.Close()
-	// Get and check log mode.
+func initLogging() {
 	LogModes = strings.Split(Cfg.Section("log").Key("mode").MustString("console"), ",")
 	LogsPath = makeAbsolute(Cfg.Section("paths").Key("logs").String(), HomePath)
 
-	defaultLevelName, _ := getLogLevel("log", "Info")
-
-	LogConfigs = make([]util.DynMap, len(LogModes))
-
-	for i, mode := range LogModes {
-
-		mode = strings.TrimSpace(mode)
-		sec, err := Cfg.GetSection("log." + mode)
-		if err != nil {
-			log.Fatal(4, "Unknown log mode: %s", mode)
-		}
-
-		// Log level.
-		_, level := getLogLevel("log."+mode, defaultLevelName)
-
-		// Generate log configuration.
-		switch mode {
-		case "console":
-			formatting := sec.Key("formatting").MustBool(true)
-			LogConfigs[i] = util.DynMap{
-				"level":      level,
-				"formatting": formatting,
-			}
-		case "file":
-			logPath := sec.Key("file_name").MustString(filepath.Join(LogsPath, "grafana.log"))
-			os.MkdirAll(filepath.Dir(logPath), os.ModePerm)
-			LogConfigs[i] = util.DynMap{
-				"level":    level,
-				"filename": logPath,
-				"rotate":   sec.Key("log_rotate").MustBool(true),
-				"maxlines": sec.Key("max_lines").MustInt(1000000),
-				"maxsize":  1 << uint(sec.Key("max_size_shift").MustInt(28)),
-				"daily":    sec.Key("daily_rotate").MustBool(true),
-				"maxdays":  sec.Key("max_days").MustInt(7),
-			}
-		case "conn":
-			LogConfigs[i] = util.DynMap{
-				"level":          level,
-				"reconnectOnMsg": sec.Key("reconnect_on_msg").MustBool(),
-				"reconnect":      sec.Key("reconnect").MustBool(),
-				"net":            sec.Key("protocol").In("tcp", []string{"tcp", "unix", "udp"}),
-				"addr":           sec.Key("addr").MustString(":7020"),
-			}
-		case "smtp":
-			LogConfigs[i] = util.DynMap{
-				"level":     level,
-				"user":      sec.Key("user").MustString("example@example.com"),
-				"passwd":    sec.Key("passwd").MustString("******"),
-				"host":      sec.Key("host").MustString("127.0.0.1:25"),
-				"receivers": sec.Key("receivers").MustString("[]"),
-				"subject":   sec.Key("subject").MustString("Diagnostic message from serve"),
-			}
-		case "database":
-			LogConfigs[i] = util.DynMap{
-				"level":  level,
-				"driver": sec.Key("driver").String(),
-				"conn":   sec.Key("conn").String(),
-			}
-		case "syslog":
-			LogConfigs[i] = util.DynMap{
-				"level":    level,
-				"network":  sec.Key("network").MustString(""),
-				"address":  sec.Key("address").MustString(""),
-				"facility": sec.Key("facility").MustString("local7"),
-				"tag":      sec.Key("tag").MustString(""),
-			}
-		}
-
-		cfgJsonBytes, _ := json.Marshal(LogConfigs[i])
-		log.NewLogger(Cfg.Section("log").Key("buffer_len").MustInt64(10000), mode, string(cfgJsonBytes))
-	}
+	log.ReadLoggingConfig(LogModes, LogsPath, Cfg)
 }
 
 func LogConfigurationInfo() {