diff --git a/models/db/engine_hook.go b/models/db/engine_hook.go index 2c9fc09c99da7..8709a2c2a1393 100644 --- a/models/db/engine_hook.go +++ b/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 } diff --git a/models/db/log.go b/models/db/log.go index 307788ea2e49f..a9df6f541dbf7 100644 --- a/models/db/log.go +++ b/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 diff --git a/modules/log/event_format.go b/modules/log/event_format.go index 8fda0a498071e..c23b3b411baa7 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 a833b6ef0fa71..3fc524d55e875 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 6ce8b70fed620..07c25cd62f6f4 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 b7a1f4e1e117e..551c1454aa94a 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 d76df857af8de..9f604815f6bc2 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 b8fbf846133c5..beddbccb73ad1 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 ae4ce04cf32b1..c9d230e4ac341 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 5f3a7592af025..e3843b14021f7 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 } diff --git a/services/context/access_log.go b/services/context/access_log.go index 001d93a362b8b..925e4a305685c 100644 --- a/services/context/access_log.go +++ b/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 { diff --git a/services/context/access_log_test.go b/services/context/access_log_test.go index bd3e47e0ccd6d..c40ef9acd1d97 100644 --- a/services/context/access_log_test.go +++ b/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...)) } diff --git a/services/doctor/doctor.go b/services/doctor/doctor.go index a4eb5e16b91c5..c6810a5fa07c0 100644 --- a/services/doctor/doctor.go +++ b/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...)