Improve log format (#33814)

8 files changed, 114 insertions, 68 deletions

diff --git a/modules/log/event_format.go b/modules/log/event_format.go
index 8fda0a4980..c23b3b411b 100644
--- a/modules/log/event_format.go
+++ b/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...)
 		}
diff --git a/modules/log/logger.go b/modules/log/logger.go
index a833b6ef0f..3fc524d55e 100644
--- a/modules/log/logger.go
+++ b/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
 }
 
diff --git a/modules/log/logger_global.go b/modules/log/logger_global.go
index 6ce8b70fed..07c25cd62f 100644
--- a/modules/log/logger_global.go
+++ b/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) {
diff --git a/modules/log/logger_impl.go b/modules/log/logger_impl.go
index b7a1f4e1e1..551c1454aa 100644
--- a/modules/log/logger_impl.go
+++ b/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
diff --git a/modules/log/logger_test.go b/modules/log/logger_test.go
index d76df857af..9f604815f6 100644
--- a/modules/log/logger_test.go
+++ b/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())
 }
diff --git a/modules/log/manager_test.go b/modules/log/manager_test.go
index b8fbf84613..beddbccb73 100644
--- a/modules/log/manager_test.go
+++ b/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)
 }
diff --git a/modules/log/misc.go b/modules/log/misc.go
index ae4ce04cf3..c9d230e4ac 100644
--- a/modules/log/misc.go
+++ b/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 {
diff --git a/modules/web/routing/logger.go b/modules/web/routing/logger.go
index 5f3a7592af..e3843b1402 100644
--- a/modules/web/routing/logger.go
+++ b/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
 		}