Improve log format (#33814)

models/db/engine_hook.go

@@ -41,7 +41,7 @@ func (h *EngineHook) AfterProcess(c *contexts.ContextHook) error {
 		// 8 is the amount of skips passed to runtime.Caller, so that in the log the correct function
 		// is being displayed (the function that ultimately wants to execute the query in the code)
 		// instead of the function of the slow query hook being called.
-		h.Logger.Log(8, log.WARN, "[Slow SQL Query] %s %v - %v", c.SQL, c.Args, c.ExecuteTime)
+		h.Logger.Log(8, &log.Event{Level: log.WARN}, "[Slow SQL Query] %s %v - %v", c.SQL, c.Args, c.ExecuteTime)
 	}
 	return nil
 }

models/db/log.go

@@ -29,7 +29,7 @@ const stackLevel = 8
 
 // Log a message with defined skip and at logging level
 func (l *XORMLogBridge) Log(skip int, level log.Level, format string, v ...any) {
-	l.logger.Log(skip+1, level, format, v...)
+	l.logger.Log(skip+1, &log.Event{Level: level}, format, v...)
 }
 
 // Debug show debug log

modules/log/event_format.go

@@ -125,15 +125,19 @@ func EventFormatTextMessage(mode *WriterMode, event *Event, msgFormat string, ms
 			buf = append(buf, resetBytes...)
 		}
 	}
-	if flags&(Lshortfile|Llongfile) != 0 {
+	if flags&(Lshortfile|Llongfile) != 0 && event.Filename != "" {
 		if mode.Colorize {
 			buf = append(buf, fgGreenBytes...)
 		}
 		file := event.Filename
 		if flags&Lmedfile == Lmedfile {
-			startIndex := len(file) - 20
-			if startIndex > 0 {
-				file = "..." + file[startIndex:]
+			fileLen := len(file)
+			const softLimit = 20
+			if fileLen > softLimit {
+				slashIndex := strings.LastIndexByte(file[:fileLen-softLimit], '/')
+				if slashIndex != -1 {
+					file = ".../" + file[slashIndex+1:]
+				}
 			}
 		} else if flags&Lshortfile != 0 {
 			startIndex := strings.LastIndexByte(file, '/')
@@ -157,14 +161,22 @@ func EventFormatTextMessage(mode *WriterMode, event *Event, msgFormat string, ms
 		if mode.Colorize {
 			buf = append(buf, fgGreenBytes...)
 		}
-		funcname := event.Caller
+		funcName := event.Caller
+		shortFuncName := funcName
 		if flags&Lshortfuncname != 0 {
-			lastIndex := strings.LastIndexByte(funcname, '.')
-			if lastIndex > 0 && len(funcname) > lastIndex+1 {
-				funcname = funcname[lastIndex+1:]
+			// funcName = "code.gitea.io/gitea/modules/foo/bar.MyFunc.func1.2()"
+			slashPos := strings.LastIndexByte(funcName, '/')
+			dotPos := strings.IndexByte(funcName[slashPos+1:], '.')
+			if dotPos > 0 {
+				// shortFuncName = "MyFunc.func1.2()"
+				shortFuncName = funcName[slashPos+1+dotPos+1:]
+				if strings.Contains(shortFuncName, ".") {
+					shortFuncName = strings.ReplaceAll(shortFuncName, ".func", ".")
+				}
 			}
+			funcName = shortFuncName
 		}
-		buf = append(buf, funcname...)
+		buf = append(buf, funcName...)
 		if mode.Colorize {
 			buf = append(buf, resetBytes...)
 		}

modules/log/logger.go

@@ -24,7 +24,7 @@ package log
 
 // BaseLogger provides the basic logging functions
 type BaseLogger interface {
-	Log(skip int, level Level, format string, v ...any)
+	Log(skip int, event *Event, format string, v ...any)
 	GetLevel() Level
 }
 

modules/log/logger_global.go

@@ -18,7 +18,7 @@ func GetLevel() Level {
 }
 
 func Log(skip int, level Level, format string, v ...any) {
-	GetLogger(DEFAULT).Log(skip+1, level, format, v...)
+	GetLogger(DEFAULT).Log(skip+1, &Event{Level: level}, format, v...)
 }
 
 func Trace(format string, v ...any) {

modules/log/logger_impl.go

@@ -191,28 +191,27 @@ func asLogStringer(v any) LogStringer {
 }
 
 // Log prepares the log event, if the level matches, the event will be sent to the writers
-func (l *LoggerImpl) Log(skip int, level Level, format string, logArgs ...any) {
-	if Level(l.level.Load()) > level {
+func (l *LoggerImpl) Log(skip int, event *Event, format string, logArgs ...any) {
+	if Level(l.level.Load()) > event.Level {
 		return
 	}
 
-	event := &Event{
-		Time:   time.Now(),
-		Level:  level,
-		Caller: "?()",
+	if event.Time.IsZero() {
+		event.Time = time.Now()
 	}
-
-	pc, filename, line, ok := runtime.Caller(skip + 1)
-	if ok {
-		fn := runtime.FuncForPC(pc)
-		if fn != nil {
-			event.Caller = fn.Name() + "()"
+	if event.Caller == "" {
+		pc, filename, line, ok := runtime.Caller(skip + 1)
+		if ok {
+			fn := runtime.FuncForPC(pc)
+			if fn != nil {
+				fnName := fn.Name()
+				event.Caller = strings.ReplaceAll(fnName, "[...]", "") + "()" // generic function names are "foo[...]"
+			}
+		}
+		event.Filename, event.Line = strings.TrimPrefix(filename, projectPackagePrefix), line
+		if l.stacktraceLevel.Load() <= int32(event.Level) {
+			event.Stacktrace = Stack(skip + 1)
 		}
-	}
-	event.Filename, event.Line = strings.TrimPrefix(filename, projectPackagePrefix), line
-
-	if l.stacktraceLevel.Load() <= int32(level) {
-		event.Stacktrace = Stack(skip + 1)
 	}
 
 	// get a simple text message without color

modules/log/logger_test.go

@@ -4,6 +4,7 @@
 package log
 
 import (
+	"regexp"
 	"sync"
 	"testing"
 	"time"
@@ -34,11 +35,11 @@ func (d *dummyWriter) Close() error {
 	return nil
 }
 
-func (d *dummyWriter) GetLogs() []string {
+func (d *dummyWriter) FetchLogs() []string {
 	d.mu.Lock()
 	defer d.mu.Unlock()
-	logs := make([]string, len(d.logs))
-	copy(logs, d.logs)
+	logs := d.logs
+	d.logs = nil
 	return logs
 }
 
@@ -76,14 +77,14 @@ func TestLogger(t *testing.T) {
 
 	// w2 is slow, so only w1 has logs
 	time.Sleep(100 * time.Millisecond)
-	assert.Equal(t, []string{"debug-level\n", "error-level\n"}, w1.GetLogs())
-	assert.Equal(t, []string{}, w2.GetLogs())
+	assert.Equal(t, []string{"debug-level\n", "error-level\n"}, w1.FetchLogs())
+	assert.Empty(t, w2.FetchLogs())
 
 	logger.Close()
 
 	// after Close, all logs are flushed
-	assert.Equal(t, []string{"debug-level\n", "error-level\n"}, w1.GetLogs())
-	assert.Equal(t, []string{"error-level\n"}, w2.GetLogs())
+	assert.Empty(t, w1.FetchLogs())
+	assert.Equal(t, []string{"error-level\n"}, w2.FetchLogs())
 }
 
 func TestLoggerPause(t *testing.T) {
@@ -97,12 +98,12 @@ func TestLoggerPause(t *testing.T) {
 
 	logger.Info("info-level")
 	time.Sleep(100 * time.Millisecond)
-	assert.Equal(t, []string{}, w1.GetLogs())
+	assert.Empty(t, w1.FetchLogs())
 
 	GetManager().ResumeAll()
 
 	time.Sleep(100 * time.Millisecond)
-	assert.Equal(t, []string{"info-level\n"}, w1.GetLogs())
+	assert.Equal(t, []string{"info-level\n"}, w1.FetchLogs())
 
 	logger.Close()
 }
@@ -123,21 +124,42 @@ func (t *testLogStringPtrReceiver) LogString() string {
 	return "log-string-ptr-receiver"
 }
 
-func TestLoggerLogString(t *testing.T) {
-	logger := NewLoggerWithWriters(t.Context(), "test")
-
-	w1 := newDummyWriter("dummy-1", DEBUG, 0)
-	w1.Mode.Colorize = true
-	logger.AddWriters(w1)
-
-	logger.Info("%s %s %#v %v", testLogString{}, &testLogString{}, testLogString{Field: "detail"}, NewColoredValue(testLogString{}, FgRed))
-	logger.Info("%s %s %#v %v", testLogStringPtrReceiver{}, &testLogStringPtrReceiver{}, testLogStringPtrReceiver{Field: "detail"}, NewColoredValue(testLogStringPtrReceiver{}, FgRed))
-	logger.Close()
+func genericFunc[T any](logger Logger, v T) {
+	logger.Info("from genericFunc: %v", v)
+}
 
-	assert.Equal(t, []string{
-		"log-string log-string log.testLogString{Field:\"detail\"} \x1b[31mlog-string\x1b[0m\n",
-		"log-string-ptr-receiver log-string-ptr-receiver &log.testLogStringPtrReceiver{Field:\"detail\"} \x1b[31mlog-string-ptr-receiver\x1b[0m\n",
-	}, w1.GetLogs())
+func TestLoggerOutput(t *testing.T) {
+	t.Run("LogString", func(t *testing.T) {
+		logger := NewLoggerWithWriters(t.Context(), "test")
+		w1 := newDummyWriter("dummy-1", DEBUG, 0)
+		w1.Mode.Colorize = true
+		logger.AddWriters(w1)
+		logger.Info("%s %s %#v %v", testLogString{}, &testLogString{}, testLogString{Field: "detail"}, NewColoredValue(testLogString{}, FgRed))
+		logger.Info("%s %s %#v %v", testLogStringPtrReceiver{}, &testLogStringPtrReceiver{}, testLogStringPtrReceiver{Field: "detail"}, NewColoredValue(testLogStringPtrReceiver{}, FgRed))
+		logger.Close()
+
+		assert.Equal(t, []string{
+			"log-string log-string log.testLogString{Field:\"detail\"} \x1b[31mlog-string\x1b[0m\n",
+			"log-string-ptr-receiver log-string-ptr-receiver &log.testLogStringPtrReceiver{Field:\"detail\"} \x1b[31mlog-string-ptr-receiver\x1b[0m\n",
+		}, w1.FetchLogs())
+	})
+
+	t.Run("Caller", func(t *testing.T) {
+		logger := NewLoggerWithWriters(t.Context(), "test")
+		w1 := newDummyWriter("dummy-1", DEBUG, 0)
+		w1.EventWriterBaseImpl.Mode.Flags.flags = Lmedfile | Lshortfuncname
+		logger.AddWriters(w1)
+		anonymousFunc := func(logger Logger) {
+			logger.Info("from anonymousFunc")
+		}
+		genericFunc(logger, "123")
+		anonymousFunc(logger)
+		logger.Close()
+		logs := w1.FetchLogs()
+		assert.Len(t, logs, 2)
+		assert.Regexp(t, `modules/log/logger_test.go:\w+:`+regexp.QuoteMeta(`genericFunc() from genericFunc: 123`), logs[0])
+		assert.Regexp(t, `modules/log/logger_test.go:\w+:`+regexp.QuoteMeta(`TestLoggerOutput.2.1() from anonymousFunc`), logs[1])
+	})
 }
 
 func TestLoggerExpressionFilter(t *testing.T) {
@@ -153,5 +175,5 @@ func TestLoggerExpressionFilter(t *testing.T) {
 	logger.SendLogEvent(&Event{Level: INFO, Filename: "foo.go", MsgSimpleText: "by filename"})
 	logger.Close()
 
-	assert.Equal(t, []string{"foo\n", "foo bar\n", "by filename\n"}, w1.GetLogs())
+	assert.Equal(t, []string{"foo\n", "foo bar\n", "by filename\n"}, w1.FetchLogs())
 }

modules/log/manager_test.go

@@ -37,6 +37,6 @@ func TestSharedWorker(t *testing.T) {
 
 	m.Close()
 
-	logs := w.(*dummyWriter).GetLogs()
+	logs := w.(*dummyWriter).FetchLogs()
 	assert.Equal(t, []string{"msg-1\n", "msg-2\n", "msg-3\n"}, logs)
 }

modules/log/misc.go

@@ -19,8 +19,8 @@ func BaseLoggerToGeneralLogger(b BaseLogger) Logger {
 
 var _ Logger = (*baseToLogger)(nil)
 
-func (s *baseToLogger) Log(skip int, level Level, format string, v ...any) {
-	s.base.Log(skip+1, level, format, v...)
+func (s *baseToLogger) Log(skip int, event *Event, format string, v ...any) {
+	s.base.Log(skip+1, event, format, v...)
 }
 
 func (s *baseToLogger) GetLevel() Level {
@@ -32,27 +32,27 @@ func (s *baseToLogger) LevelEnabled(level Level) bool {
 }
 
 func (s *baseToLogger) Trace(format string, v ...any) {
-	s.base.Log(1, TRACE, format, v...)
+	s.base.Log(1, &Event{Level: TRACE}, format, v...)
 }
 
 func (s *baseToLogger) Debug(format string, v ...any) {
-	s.base.Log(1, DEBUG, format, v...)
+	s.base.Log(1, &Event{Level: DEBUG}, format, v...)
 }
 
 func (s *baseToLogger) Info(format string, v ...any) {
-	s.base.Log(1, INFO, format, v...)
+	s.base.Log(1, &Event{Level: INFO}, format, v...)
 }
 
 func (s *baseToLogger) Warn(format string, v ...any) {
-	s.base.Log(1, WARN, format, v...)
+	s.base.Log(1, &Event{Level: WARN}, format, v...)
 }
 
 func (s *baseToLogger) Error(format string, v ...any) {
-	s.base.Log(1, ERROR, format, v...)
+	s.base.Log(1, &Event{Level: ERROR}, format, v...)
 }
 
 func (s *baseToLogger) Critical(format string, v ...any) {
-	s.base.Log(1, CRITICAL, format, v...)
+	s.base.Log(1, &Event{Level: CRITICAL}, format, v...)
 }
 
 type PrintfLogger struct {

modules/web/routing/logger.go

@@ -35,6 +35,19 @@ var (
 )
 
 func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) {
+	const callerName = "HTTPRequest"
+	logTrace := func(fmt string, args ...any) {
+		logger.Log(2, &log.Event{Level: log.TRACE, Caller: callerName}, fmt, args...)
+	}
+	logInfo := func(fmt string, args ...any) {
+		logger.Log(2, &log.Event{Level: log.INFO, Caller: callerName}, fmt, args...)
+	}
+	logWarn := func(fmt string, args ...any) {
+		logger.Log(2, &log.Event{Level: log.WARN, Caller: callerName}, fmt, args...)
+	}
+	logError := func(fmt string, args ...any) {
+		logger.Log(2, &log.Event{Level: log.ERROR, Caller: callerName}, fmt, args...)
+	}
 	return func(trigger Event, record *requestRecord) {
 		if trigger == StartEvent {
 			if !logger.LevelEnabled(log.TRACE) {
@@ -44,7 +57,7 @@ func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) {
 			}
 			// when a request starts, we have no information about the handler function information, we only have the request path
 			req := record.request
-			logger.Trace("router: %s %v %s for %s", startMessage, log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr)
+			logTrace("router: %s %v %s for %s", startMessage, log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr)
 			return
 		}
 
@@ -60,9 +73,9 @@ func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) {
 
 		if trigger == StillExecutingEvent {
 			message := slowMessage
-			logf := logger.Warn
+			logf := logWarn
 			if isLongPolling {
-				logf = logger.Info
+				logf = logInfo
 				message = pollingMessage
 			}
 			logf("router: %s %v %s for %s, elapsed %v @ %s",
@@ -75,7 +88,7 @@ func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) {
 		}
 
 		if panicErr != nil {
-			logger.Warn("router: %s %v %s for %s, panic in %v @ %s, err=%v",
+			logWarn("router: %s %v %s for %s, panic in %v @ %s, err=%v",
 				failedMessage,
 				log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr,
 				log.ColoredTime(time.Since(record.startTime)),
@@ -89,13 +102,13 @@ func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) {
 		if v, ok := record.responseWriter.(types.ResponseStatusProvider); ok {
 			status = v.WrittenStatus()
 		}
-		logf := logger.Info
+		logf := logInfo
 		if strings.HasPrefix(req.RequestURI, "/assets/") {
-			logf = logger.Trace
+			logf = logTrace
 		}
 		message := completedMessage
 		if isUnknownHandler {
-			logf = logger.Error
+			logf = logError
 			message = unknownHandlerMessage
 		}
 

services/context/access_log.go

@@ -92,7 +92,7 @@ func (lr *accessLogRecorder) record(start time.Time, respWriter ResponseWriter,
 		log.Error("Could not execute access logger template: %v", err.Error())
 	}
 
-	lr.logger.Log(1, log.INFO, "%s", buf.String())
+	lr.logger.Log(1, &log.Event{Level: log.INFO}, "%s", buf.String())
 }
 
 func newAccessLogRecorder() *accessLogRecorder {

services/context/access_log_test.go

@@ -20,7 +20,7 @@ type testAccessLoggerMock struct {
 	logs []string
 }
 
-func (t *testAccessLoggerMock) Log(skip int, level log.Level, format string, v ...any) {
+func (t *testAccessLoggerMock) Log(skip int, event *log.Event, format string, v ...any) {
 	t.logs = append(t.logs, fmt.Sprintf(format, v...))
 }
 

services/doctor/doctor.go

@@ -48,7 +48,7 @@ type doctorCheckLogger struct {
 
 var _ log.BaseLogger = (*doctorCheckLogger)(nil)
 
-func (d *doctorCheckLogger) Log(skip int, level log.Level, format string, v ...any) {
+func (d *doctorCheckLogger) Log(skip int, event *log.Event, format string, v ...any) {
 	_, _ = fmt.Fprintf(os.Stdout, format+"\n", v...)
 }
 
@@ -62,11 +62,11 @@ type doctorCheckStepLogger struct {
 
 var _ log.BaseLogger = (*doctorCheckStepLogger)(nil)
 
-func (d *doctorCheckStepLogger) Log(skip int, level log.Level, format string, v ...any) {
-	levelChar := fmt.Sprintf("[%s]", strings.ToUpper(level.String()[0:1]))
+func (d *doctorCheckStepLogger) Log(skip int, event *log.Event, format string, v ...any) {
+	levelChar := fmt.Sprintf("[%s]", strings.ToUpper(event.Level.String()[0:1]))
 	var levelArg any = levelChar
 	if d.colorize {
-		levelArg = log.NewColoredValue(levelChar, level.ColorAttributes()...)
+		levelArg = log.NewColoredValue(levelChar, event.Level.ColorAttributes()...)
 	}
 	args := append([]any{levelArg}, v...)
 	_, _ = fmt.Fprintf(os.Stdout, " - %s "+format+"\n", args...)