feat(logging): progress on new logging #4590

pkg/api/dashboard.go

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

pkg/cmd/grafana-server/main.go

@@ -55,9 +55,6 @@ func main() {
 	setting.BuildCommit = commit
 	setting.BuildCommit = commit
 	setting.BuildStamp = buildstampInt64
 	setting.BuildStamp = buildstampInt64
 
 
-	logger := log.New("main")
-	logger.Info("Starting Grafana", "version", version, "commit", commit, "compiled", time.Unix(buildstampInt64, 0))
-
 	go listenToSystemSignels()
 	go listenToSystemSignels()
 
 
 	flag.Parse()
 	flag.Parse()
@@ -90,8 +87,8 @@ func initRuntime() {
 		log.Fatal(3, err.Error())
 		log.Fatal(3, err.Error())
 	}
 	}
 
 
-	log.Info("Starting Grafana")
-	log.Info("Version: %v, Commit: %v, Build date: %v", setting.BuildVersion, setting.BuildCommit, time.Unix(setting.BuildStamp, 0))
+	logger := log.New("main")
+	logger.Info("Starting Grafana", "version", version, "commit", commit, "compiled", time.Unix(setting.BuildStamp, 0))
 
 
 	setting.LogConfigurationInfo()
 	setting.LogConfigurationInfo()
 
 

pkg/login/settings.go

@@ -2,6 +2,7 @@ package login
 
 
 import (
 import (
 	"fmt"
 	"fmt"
+	"os"
 
 
 	"github.com/BurntSushi/toml"
 	"github.com/BurntSushi/toml"
 	"github.com/grafana/grafana/pkg/log"
 	"github.com/grafana/grafana/pkg/log"
@@ -49,21 +50,24 @@ type LdapGroupToOrgRole struct {
 }
 }
 
 
 var ldapCfg LdapConfig
 var ldapCfg LdapConfig
+var ldapLogger log.Logger = log.New("ldap")
 
 
 func loadLdapConfig() {
 func loadLdapConfig() {
 	if !setting.LdapEnabled {
 	if !setting.LdapEnabled {
 		return
 		return
 	}
 	}
 
 
-	log.Info("Login: Ldap enabled, reading config file: %s", setting.LdapConfigFile)
+	ldapLogger.Info("Ldap enabled, reading config file", "file", setting.LdapConfigFile)
 
 
 	_, err := toml.DecodeFile(setting.LdapConfigFile, &ldapCfg)
 	_, err := toml.DecodeFile(setting.LdapConfigFile, &ldapCfg)
 	if err != nil {
 	if err != nil {
-		log.Fatal(3, "Failed to load ldap config file: %s", err)
+		ldapLogger.Crit("Failed to load ldap config file", "error", err)
+		os.Exit(1)
 	}
 	}
 
 
 	if len(ldapCfg.Servers) == 0 {
 	if len(ldapCfg.Servers) == 0 {
-		log.Fatal(3, "ldap enabled but no ldap servers defined in config file: %s", setting.LdapConfigFile)
+		ldapLogger.Crit("ldap enabled but no ldap servers defined in config file")
+		os.Exit(1)
 	}
 	}
 
 
 	// set default org id
 	// set default org id
@@ -83,11 +87,13 @@ func assertNotEmptyCfg(val interface{}, propName string) {
 	switch v := val.(type) {
 	switch v := val.(type) {
 	case string:
 	case string:
 		if v == "" {
 		if v == "" {
-			log.Fatal(3, "LDAP config file is missing option: %s", propName)
+			ldapLogger.Crit("LDAP config file is missing option", "option", propName)
+			os.Exit(1)
 		}
 		}
 	case []string:
 	case []string:
 		if len(v) == 0 {
 		if len(v) == 0 {
-			log.Fatal(3, "LDAP config file is missing option: %s", propName)
+			ldapLogger.Crit("LDAP config file is missing option", "option", propName)
+			os.Exit(1)
 		}
 		}
 	default:
 	default:
 		fmt.Println("unknown")
 		fmt.Println("unknown")

pkg/metrics/publish.go

@@ -14,6 +14,8 @@ import (
 	"github.com/grafana/grafana/pkg/setting"
 	"github.com/grafana/grafana/pkg/setting"
 )
 )
 
 
+var metricsLogger log.Logger = log.New("metrics")
+
 func Init() {
 func Init() {
 	settings := readSettings()
 	settings := readSettings()
 	initMetricVars(settings)
 	initMetricVars(settings)
@@ -54,7 +56,7 @@ func sendUsageStats() {
 		return
 		return
 	}
 	}
 
 
-	log.Trace("Sending anonymous usage stats to stats.grafana.org")
+	metricsLogger.Debug("Sending anonymous usage stats to stats.grafana.org")
 
 
 	version := strings.Replace(setting.BuildVersion, ".", "_", -1)
 	version := strings.Replace(setting.BuildVersion, ".", "_", -1)
 
 
@@ -66,7 +68,7 @@ func sendUsageStats() {
 
 
 	statsQuery := m.GetSystemStatsQuery{}
 	statsQuery := m.GetSystemStatsQuery{}
 	if err := bus.Dispatch(&statsQuery); err != nil {
 	if err := bus.Dispatch(&statsQuery); err != nil {
-		log.Error(3, "Failed to get system stats", err)
+		metricsLogger.Error("Failed to get system stats", "error", err)
 		return
 		return
 	}
 	}
 
 
@@ -80,7 +82,7 @@ func sendUsageStats() {
 
 
 	dsStats := m.GetDataSourceStatsQuery{}
 	dsStats := m.GetDataSourceStatsQuery{}
 	if err := bus.Dispatch(&dsStats); err != nil {
 	if err := bus.Dispatch(&dsStats); err != nil {
-		log.Error(3, "Failed to get datasource stats", err)
+		metricsLogger.Error("Failed to get datasource stats", "error", err)
 		return
 		return
 	}
 	}
 
 

pkg/metrics/settings.go

 package metrics
 package metrics
 
 
-import (
-	"github.com/grafana/grafana/pkg/log"
-	"github.com/grafana/grafana/pkg/setting"
-)
+import "github.com/grafana/grafana/pkg/setting"
 
 
 type MetricPublisher interface {
 type MetricPublisher interface {
 	Publish(metrics []Metric)
 	Publish(metrics []Metric)
@@ -24,7 +21,7 @@ func readSettings() *MetricSettings {
 
 
 	var section, err = setting.Cfg.GetSection("metrics")
 	var section, err = setting.Cfg.GetSection("metrics")
 	if err != nil {
 	if err != nil {
-		log.Fatal(3, "Unable to find metrics config section")
+		metricsLogger.Crit("Unable to find metrics config section", "error", err)
 		return nil
 		return nil
 	}
 	}
 
 
@@ -36,9 +33,9 @@ func readSettings() *MetricSettings {
 	}
 	}
 
 
 	if graphitePublisher, err := CreateGraphitePublisher(); err != nil {
 	if graphitePublisher, err := CreateGraphitePublisher(); err != nil {
-		log.Error(3, "Metrics: Failed to init Graphite metric publisher", err)
+		metricsLogger.Error("Failed to init Graphite metric publisher", "error", err)
 	} else if graphitePublisher != nil {
 	} else if graphitePublisher != nil {
-		log.Info("Metrics: Graphite publisher initialized")
+		metricsLogger.Info("Metrics publisher initialized", "type", "graphite")
 		settings.Publishers = append(settings.Publishers, graphitePublisher)
 		settings.Publishers = append(settings.Publishers, graphitePublisher)
 	}
 	}
 
 

pkg/middleware/logger.go

@@ -20,7 +20,6 @@ import (
 	"time"
 	"time"
 
 
 	"github.com/grafana/grafana/pkg/metrics"
 	"github.com/grafana/grafana/pkg/metrics"
-	"github.com/grafana/grafana/pkg/setting"
 	"gopkg.in/macaron.v1"
 	"gopkg.in/macaron.v1"
 )
 )
 
 
@@ -29,11 +28,6 @@ func Logger() macaron.Handler {
 		start := time.Now()
 		start := time.Now()
 		c.Data["perfmon.start"] = start
 		c.Data["perfmon.start"] = start
 
 
-		uname := c.GetCookie(setting.CookieUserName)
-		if len(uname) == 0 {
-			uname = "-"
-		}
-
 		rw := res.(macaron.ResponseWriter)
 		rw := res.(macaron.ResponseWriter)
 		c.Next()
 		c.Next()
 
 
@@ -46,13 +40,14 @@ func Logger() macaron.Handler {
 
 
 		status := rw.Status()
 		status := rw.Status()
 		if status == 200 || status == 304 {
 		if status == 200 || status == 304 {
-			if !setting.RouterLogging {
-				return
-			}
+			// if !setting.RouterLogging {
+			// 	return
+			// }
 		}
 		}
 
 
 		if ctx, ok := c.Data["ctx"]; ok {
 		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())
+			ctxTyped := ctx.(*Context)
+			ctxTyped.Logger.Info("Request Completed", "method", req.Method, "path", req.URL.Path, "status", status, "remote_addr", c.RemoteAddr(), "uname", ctxTyped.Login, "time_ns", timeTakenMs, "size", rw.Size())
 		}
 		}
 	}
 	}
 }
 }

pkg/middleware/middleware.go

 package middleware
 package middleware
 
 
 import (
 import (
-	"fmt"
 	"strconv"
 	"strconv"
 	"strings"
 	"strings"
 
 
@@ -52,9 +51,7 @@ func GetContextHandler() macaron.Handler {
 		}
 		}
 
 
 		ctx.Logger = log.New("context", "user", ctx.UserId, "orgId", ctx.OrgId)
 		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)
+		ctx.Data["ctx"] = ctx
 
 
 		c.Map(ctx)
 		c.Map(ctx)
 	}
 	}

pkg/services/sqlstore/sqlstore.go

@@ -40,8 +40,8 @@ var (
 	}
 	}
 
 
 	mysqlConfig MySQLConfig
 	mysqlConfig MySQLConfig
-
 	UseSQLite3  bool
 	UseSQLite3  bool
+	sqlog       log.Logger = log.New("sqlstore")
 )
 )
 
 
 func EnsureAdminUser() {
 func EnsureAdminUser() {
@@ -74,13 +74,15 @@ func NewEngine() {
 	x, err := getEngine()
 	x, err := getEngine()
 
 
 	if err != nil {
 	if err != nil {
-		log.Fatal(3, "Sqlstore: Fail to connect to database: %v", err)
+		sqlog.Crit("Fail to connect to database", "error", err)
+		os.Exit(1)
 	}
 	}
 
 
 	err = SetEngine(x, setting.Env == setting.DEV)
 	err = SetEngine(x, setting.Env == setting.DEV)
 
 
 	if err != nil {
 	if err != nil {
-		log.Fatal(3, "fail to initialize orm engine: %v", err)
+		sqlog.Error("Fail to initialize orm engine: %v", err)
+		os.Exit(1)
 	}
 	}
 }
 }
 
 
@@ -95,17 +97,6 @@ func SetEngine(engine *xorm.Engine, enableLog bool) (err error) {
 		return fmt.Errorf("Sqlstore::Migration failed err: %v\n", err)
 		return fmt.Errorf("Sqlstore::Migration failed err: %v\n", err)
 	}
 	}
 
 
-	if enableLog {
-		logPath := path.Join(setting.LogsPath, "xorm.log")
-		os.MkdirAll(path.Dir(logPath), os.ModePerm)
-
-		f, err := os.Create(logPath)
-		if err != nil {
-			return fmt.Errorf("sqlstore.init(fail to create xorm.log): %v", err)
-		}
-		x.Logger = xorm.NewSimpleLogger(f)
-	}
-
 	return nil
 	return nil
 }
 }
 
 
@@ -157,8 +148,7 @@ func getEngine() (*xorm.Engine, error) {
 		return nil, fmt.Errorf("Unknown database type: %s", DbCfg.Type)
 		return nil, fmt.Errorf("Unknown database type: %s", DbCfg.Type)
 	}
 	}
 
 
-	log.Info("Database: %v", DbCfg.Type)
-
+	sqlog.Info("Initializing DB", "dbtype", DbCfg.Type)
 	return xorm.NewEngine(DbCfg.Type, cnnstr)
 	return xorm.NewEngine(DbCfg.Type, cnnstr)
 }
 }
 
 

pkg/setting/setting.go

@@ -138,6 +138,9 @@ var (
 
 
 	// QUOTA
 	// QUOTA
 	Quota QuotaSettings
 	Quota QuotaSettings
+
+	// logger
+	logger log.Logger
 )
 )
 
 
 type CommandLineArgs struct {
 type CommandLineArgs struct {
@@ -148,6 +151,7 @@ type CommandLineArgs struct {
 
 
 func init() {
 func init() {
 	IsWindows = runtime.GOOS == "windows"
 	IsWindows = runtime.GOOS == "windows"
+	logger = log.New("settings")
 }
 }
 
 
 func parseAppUrlAndSubUrl(section *ini.Section) (string, string) {
 func parseAppUrlAndSubUrl(section *ini.Section) (string, string) {
@@ -544,38 +548,31 @@ func readSessionConfig() {
 func initLogging() {
 func initLogging() {
 	LogModes = strings.Split(Cfg.Section("log").Key("mode").MustString("console"), ",")
 	LogModes = strings.Split(Cfg.Section("log").Key("mode").MustString("console"), ",")
 	LogsPath = makeAbsolute(Cfg.Section("paths").Key("logs").String(), HomePath)
 	LogsPath = makeAbsolute(Cfg.Section("paths").Key("logs").String(), HomePath)
-
 	log.ReadLoggingConfig(LogModes, LogsPath, Cfg)
 	log.ReadLoggingConfig(LogModes, LogsPath, Cfg)
 }
 }
 
 
 func LogConfigurationInfo() {
 func LogConfigurationInfo() {
 	var text bytes.Buffer
 	var text bytes.Buffer
-	text.WriteString("Configuration Info\n")
 
 
-	text.WriteString("Config files:\n")
-	for i, file := range configFiles {
-		text.WriteString(fmt.Sprintf("  [%d]: %s\n", i, file))
+	for _, file := range configFiles {
+		logger.Info("Config loaded from", "file", file)
 	}
 	}
 
 
 	if len(appliedCommandLineProperties) > 0 {
 	if len(appliedCommandLineProperties) > 0 {
-		text.WriteString("Command lines overrides:\n")
-		for i, prop := range appliedCommandLineProperties {
-			text.WriteString(fmt.Sprintf("  [%d]: %s\n", i, prop))
+		for _, prop := range appliedCommandLineProperties {
+			logger.Info("Config overriden from command line", "arg", prop)
 		}
 		}
 	}
 	}
 
 
 	if len(appliedEnvOverrides) > 0 {
 	if len(appliedEnvOverrides) > 0 {
 		text.WriteString("\tEnvironment variables used:\n")
 		text.WriteString("\tEnvironment variables used:\n")
-		for i, prop := range appliedEnvOverrides {
-			text.WriteString(fmt.Sprintf("  [%d]: %s\n", i, prop))
+		for _, prop := range appliedEnvOverrides {
+			logger.Info("Config overriden from Environment variable", "var", prop)
 		}
 		}
 	}
 	}
 
 
-	text.WriteString("Paths:\n")
-	text.WriteString(fmt.Sprintf("  home: %s\n", HomePath))
-	text.WriteString(fmt.Sprintf("  data: %s\n", DataPath))
-	text.WriteString(fmt.Sprintf("  logs: %s\n", LogsPath))
-	text.WriteString(fmt.Sprintf("  plugins: %s\n", PluginsPath))
-
-	log.Info(text.String())
+	logger.Info("Path Home", "path", HomePath)
+	logger.Info("Path Data", "path", DataPath)
+	logger.Info("Path Logs", "path", LogsPath)
+	logger.Info("Path Plugins", "path", PluginsPath)
 }
 }