Use stack trace context in XORM trace logger (#43780)

* add caller and stack Valuer functions
* Add WithPrefix and WithSuffix similar to what go-kit offers
* replace New with just `with`. Remove filter wrapper because the first argument of the context argument is not logger but additional context.
* update Xorm logger to use custom depth to display the datastore code instead of xorm

pkg/infra/log/log.go

@@ -15,11 +15,12 @@ import (
 	gokitlog "github.com/go-kit/log"
 	"github.com/go-kit/log/term"
 	"github.com/go-stack/stack"
+	"github.com/mattn/go-isatty"
+	"gopkg.in/ini.v1"
+
 	"github.com/grafana/grafana/pkg/infra/log/level"
 	"github.com/grafana/grafana/pkg/util"
 	"github.com/grafana/grafana/pkg/util/errutil"
-	"github.com/mattn/go-isatty"
-	"gopkg.in/ini.v1"
 )
 
 var loggersToClose []DisposableHandler
@@ -27,6 +28,12 @@ var loggersToReload []ReloadableHandler
 var filters map[string]level.Option
 var Root MultiLoggers
 
+const (
+	// top 7 calls in the stack are within logger
+	DefaultCallerDepth = 7
+	CallerContextKey   = "caller"
+)
+
 func init() {
 	loggersToClose = make([]DisposableHandler, 0)
 	loggersToReload = make([]ReloadableHandler, 0)
@@ -99,24 +106,13 @@ func (ml MultiLoggers) Log(keyvals ...interface{}) error {
 	return nil
 }
 
-// we need to implement new function for multiloggers
+// New creates a new logger from the existing one with additional context
 func (ml MultiLoggers) New(ctx ...interface{}) MultiLoggers {
-	var newloger MultiLoggers
+	return with(ml, gokitlog.With, ctx)
-	for _, logWithFilter := range ml.loggers {
-		logWithFilter.val = gokitlog.With(logWithFilter.val, ctx)
-		if len(ctx) > 0 {
-			v, ok := logWithFilter.filters[ctx[0].(string)]
-			if ok {
-				logWithFilter.val = level.NewFilter(logWithFilter.val, v)
-			} else {
-				logWithFilter.val = level.NewFilter(logWithFilter.val, logWithFilter.maxLevel)
-			}
-		}
-		newloger.loggers = append(newloger.loggers, logWithFilter)
-	}
-	return newloger
 }
 
+// New creates MultiLoggers with the provided context and caller that is added as a suffix.
+// The first element of the context must be the logger name
 func New(ctx ...interface{}) MultiLoggers {
 	if len(ctx) == 0 {
 		return Root
@@ -136,6 +132,28 @@ func New(ctx ...interface{}) MultiLoggers {
 	return newloger
 }
 
+func with(loggers MultiLoggers, withFunc func(gokitlog.Logger, ...interface{}) gokitlog.Logger, ctx []interface{}) MultiLoggers {
+	if len(ctx) == 0 {
+		return loggers
+	}
+	var newloger MultiLoggers
+	for _, l := range loggers.loggers {
+		l.val = withFunc(l.val, ctx...)
+		newloger.loggers = append(newloger.loggers, l)
+	}
+	return newloger
+}
+
+// WithPrefix adds context that will be added to the log message
+func WithPrefix(loggers MultiLoggers, ctx ...interface{}) MultiLoggers {
+	return with(loggers, gokitlog.WithPrefix, ctx)
+}
+
+// WithSuffix adds context that will be appended at the end of the log message
+func WithSuffix(loggers MultiLoggers, ctx ...interface{}) MultiLoggers {
+	return with(loggers, gokitlog.WithSuffix, ctx)
+}
+
 var logLevels = map[string]level.Option{
 	"trace":    level.AllowDebug(),
 	"debug":    level.AllowDebug(),
@@ -183,6 +201,19 @@ func Stack(skip int) string {
 	return s.String()
 }
 
+// StackCaller returns a go-kit Valuer function that returns the stack trace from the place it is called. Argument `skip` allows skipping top n lines from the stack.
+func StackCaller(skip int) gokitlog.Valuer {
+	return func() interface{} {
+		return Stack(skip + 1)
+	}
+}
+
+// Caller proxies go-kit/log Caller and returns a Valuer function that returns a file and line from a specified depth
+// in the callstack
+func Caller(depth int) gokitlog.Valuer {
+	return gokitlog.Caller(depth)
+}
+
 type Formatedlogger func(w io.Writer) gokitlog.Logger
 
 func terminalColorFn(keyvals ...interface{}) term.FgBgColor {

pkg/login/social/generic_oauth_test.go

@@ -7,15 +7,16 @@ import (
 	"testing"
 	"time"
 
-	"github.com/grafana/grafana/pkg/infra/log"
-	"github.com/grafana/grafana/pkg/infra/log/level"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 	"golang.org/x/oauth2"
+
+	"github.com/grafana/grafana/pkg/infra/log"
+	"github.com/grafana/grafana/pkg/infra/log/level"
 )
 
 func newLogger(name string, lev string) log.Logger {
-	logger := log.Root.New("logger", name)
+	logger := log.New(name)
 	logger.AddLogger(logger, lev, map[string]level.Option{})
 	return logger
 }

pkg/services/sqlstore/sqlstore.go

@@ -12,6 +12,9 @@ import (
 	"time"
 
 	"github.com/go-sql-driver/mysql"
+	_ "github.com/lib/pq"
+	"xorm.io/xorm"
+
 	"github.com/grafana/grafana/pkg/bus"
 	"github.com/grafana/grafana/pkg/infra/fs"
 	"github.com/grafana/grafana/pkg/infra/localcache"
@@ -25,8 +28,6 @@ import (
 	"github.com/grafana/grafana/pkg/setting"
 	"github.com/grafana/grafana/pkg/util"
 	"github.com/grafana/grafana/pkg/util/errutil"
-	_ "github.com/lib/pq"
-	"xorm.io/xorm"
 )
 
 var (
@@ -372,7 +373,8 @@ func (ss *SQLStore) initEngine(engine *xorm.Engine) error {
 	if !debugSQL {
 		engine.SetLogger(&xorm.DiscardLogger{})
 	} else {
-		engine.SetLogger(NewXormLogger(log.LvlInfo, log.New("sqlstore.xorm")))
+		// add stack to database calls to be able to see what repository initiated queries. Top 7 items from the stack as they are likely in the xorm library.
+		engine.SetLogger(NewXormLogger(log.LvlInfo, log.WithSuffix(log.New("sqlstore.xorm"), log.CallerContextKey, log.StackCaller(log.DefaultCallerDepth))))
 		engine.ShowSQL(true)
 		engine.ShowExecTime(true)
 	}