Skip to content

Commit 4ed71eb

Browse files
wxiaoguangwxiaoguang
authored
Improve log format (go-gitea#33814)
1 parent 6422f05 commit 4ed71eb

File tree

13 files changed

+122
-76
lines changed

13 files changed

+122
-76
lines changed

‎models/db/engine_hook.go‎

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

‎models/db/log.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,7 @@ const stackLevel = 8
2929

3030
// Log a message with defined skip and at logging level
3131
func (l *XORMLogBridge) Log(skip int, level log.Level, format string, v ...any) {
32-
l.logger.Log(skip+1, level, format, v...)
32+
l.logger.Log(skip+1, &log.Event{Level: level}, format, v...)
3333
}
3434

3535
// Debug show debug log

‎modules/log/event_format.go‎

Lines changed: 21 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -125,15 +125,19 @@ func EventFormatTextMessage(mode *WriterMode, event *Event, msgFormat string, ms
125125
buf = append(buf, resetBytes...)
126126
}
127127
}
128-
if flags&(Lshortfile|Llongfile) != 0 {
128+
if flags&(Lshortfile|Llongfile) != 0 && event.Filename != "" {
129129
if mode.Colorize {
130130
buf = append(buf, fgGreenBytes...)
131131
}
132132
file := event.Filename
133133
if flags&Lmedfile == Lmedfile {
134-
startIndex := len(file) - 20
135-
if startIndex > 0 {
136-
file = "..." + file[startIndex:]
134+
fileLen := len(file)
135+
const softLimit = 20
136+
if fileLen > softLimit {
137+
slashIndex := strings.LastIndexByte(file[:fileLen-softLimit], '/')
138+
if slashIndex != -1 {
139+
file = ".../" + file[slashIndex+1:]
140+
}
137141
}
138142
} else if flags&Lshortfile != 0 {
139143
startIndex := strings.LastIndexByte(file, '/')
@@ -157,14 +161,22 @@ func EventFormatTextMessage(mode *WriterMode, event *Event, msgFormat string, ms
157161
if mode.Colorize {
158162
buf = append(buf, fgGreenBytes...)
159163
}
160-
funcname := event.Caller
164+
funcName := event.Caller
165+
shortFuncName := funcName
161166
if flags&Lshortfuncname != 0 {
162-
lastIndex := strings.LastIndexByte(funcname, '.')
163-
if lastIndex > 0 && len(funcname) > lastIndex+1 {
164-
funcname = funcname[lastIndex+1:]
167+
// funcName = "code.gitea.io/gitea/modules/foo/bar.MyFunc.func1.2()"
168+
slashPos := strings.LastIndexByte(funcName, '/')
169+
dotPos := strings.IndexByte(funcName[slashPos+1:], '.')
170+
if dotPos > 0 {
171+
// shortFuncName = "MyFunc.func1.2()"
172+
shortFuncName = funcName[slashPos+1+dotPos+1:]
173+
if strings.Contains(shortFuncName, ".") {
174+
shortFuncName = strings.ReplaceAll(shortFuncName, ".func", ".")
175+
}
165176
}
177+
funcName = shortFuncName
166178
}
167-
buf = append(buf, funcname...)
179+
buf = append(buf, funcName...)
168180
if mode.Colorize {
169181
buf = append(buf, resetBytes...)
170182
}

‎modules/log/logger.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -24,7 +24,7 @@ package log
2424

2525
// BaseLogger provides the basic logging functions
2626
type BaseLogger interface {
27-
Log(skip int, level Level, format string, v ...any)
27+
Log(skip int, event *Event, format string, v ...any)
2828
GetLevel() Level
2929
}
3030

‎modules/log/logger_global.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -18,7 +18,7 @@ func GetLevel() Level {
1818
}
1919

2020
func Log(skip int, level Level, format string, v ...any) {
21-
GetLogger(DEFAULT).Log(skip+1, level, format, v...)
21+
GetLogger(DEFAULT).Log(skip+1, &Event{Level: level}, format, v...)
2222
}
2323

2424
func Trace(format string, v ...any) {

‎modules/log/logger_impl.go‎

Lines changed: 16 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -191,28 +191,27 @@ func asLogStringer(v any) LogStringer {
191191
}
192192

193193
// Log prepares the log event, if the level matches, the event will be sent to the writers
194-
func (l *LoggerImpl) Log(skip int, level Level, format string, logArgs ...any) {
195-
if Level(l.level.Load()) > level {
194+
func (l *LoggerImpl) Log(skip int, event *Event, format string, logArgs ...any) {
195+
if Level(l.level.Load()) > event.Level {
196196
return
197197
}
198198

199-
event := &Event{
200-
Time: time.Now(),
201-
Level: level,
202-
Caller: "?()",
199+
if event.Time.IsZero() {
200+
event.Time = time.Now()
203201
}
204-
205-
pc, filename, line, ok := runtime.Caller(skip + 1)
206-
if ok {
207-
fn := runtime.FuncForPC(pc)
208-
if fn != nil {
209-
event.Caller = fn.Name() + "()"
202+
if event.Caller == "" {
203+
pc, filename, line, ok := runtime.Caller(skip + 1)
204+
if ok {
205+
fn := runtime.FuncForPC(pc)
206+
if fn != nil {
207+
fnName := fn.Name()
208+
event.Caller = strings.ReplaceAll(fnName, "[...]", "") + "()" // generic function names are "foo[...]"
209+
}
210+
}
211+
event.Filename, event.Line = strings.TrimPrefix(filename, projectPackagePrefix), line
212+
if l.stacktraceLevel.Load() <= int32(event.Level) {
213+
event.Stacktrace = Stack(skip + 1)
210214
}
211-
}
212-
event.Filename, event.Line = strings.TrimPrefix(filename, projectPackagePrefix), line
213-
214-
if l.stacktraceLevel.Load() <= int32(level) {
215-
event.Stacktrace = Stack(skip + 1)
216215
}
217216

218217
// get a simple text message without color

‎modules/log/logger_test.go‎

Lines changed: 46 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44
package log
55

66
import (
7+
"regexp"
78
"sync"
89
"testing"
910
"time"
@@ -34,11 +35,11 @@ func (d *dummyWriter) Close() error {
3435
return nil
3536
}
3637

37-
func (d *dummyWriter) GetLogs() []string {
38+
func (d *dummyWriter) FetchLogs() []string {
3839
d.mu.Lock()
3940
defer d.mu.Unlock()
40-
logs := make([]string, len(d.logs))
41-
copy(logs, d.logs)
41+
logs := d.logs
42+
d.logs = nil
4243
return logs
4344
}
4445

@@ -76,14 +77,14 @@ func TestLogger(t *testing.T) {
7677

7778
// w2 is slow, so only w1 has logs
7879
time.Sleep(100 * time.Millisecond)
79-
assert.Equal(t, []string{"debug-level\n", "error-level\n"}, w1.GetLogs())
80-
assert.Equal(t, []string{}, w2.GetLogs())
80+
assert.Equal(t, []string{"debug-level\n", "error-level\n"}, w1.FetchLogs())
81+
assert.Empty(t, w2.FetchLogs())
8182

8283
logger.Close()
8384

8485
// after Close, all logs are flushed
85-
assert.Equal(t, []string{"debug-level\n", "error-level\n"}, w1.GetLogs())
86-
assert.Equal(t, []string{"error-level\n"}, w2.GetLogs())
86+
assert.Empty(t, w1.FetchLogs())
87+
assert.Equal(t, []string{"error-level\n"}, w2.FetchLogs())
8788
}
8889

8990
func TestLoggerPause(t *testing.T) {
@@ -97,12 +98,12 @@ func TestLoggerPause(t *testing.T) {
9798

9899
logger.Info("info-level")
99100
time.Sleep(100 * time.Millisecond)
100-
assert.Equal(t, []string{}, w1.GetLogs())
101+
assert.Empty(t, w1.FetchLogs())
101102

102103
GetManager().ResumeAll()
103104

104105
time.Sleep(100 * time.Millisecond)
105-
assert.Equal(t, []string{"info-level\n"}, w1.GetLogs())
106+
assert.Equal(t, []string{"info-level\n"}, w1.FetchLogs())
106107

107108
logger.Close()
108109
}
@@ -123,21 +124,42 @@ func (t *testLogStringPtrReceiver) LogString() string {
123124
return "log-string-ptr-receiver"
124125
}
125126

126-
func TestLoggerLogString(t *testing.T) {
127-
logger := NewLoggerWithWriters(t.Context(), "test")
128-
129-
w1 := newDummyWriter("dummy-1", DEBUG, 0)
130-
w1.Mode.Colorize = true
131-
logger.AddWriters(w1)
132-
133-
logger.Info("%s %s %#v %v", testLogString{}, &testLogString{}, testLogString{Field: "detail"}, NewColoredValue(testLogString{}, FgRed))
134-
logger.Info("%s %s %#v %v", testLogStringPtrReceiver{}, &testLogStringPtrReceiver{}, testLogStringPtrReceiver{Field: "detail"}, NewColoredValue(testLogStringPtrReceiver{}, FgRed))
135-
logger.Close()
127+
func genericFunc[T any](logger Logger, v T) {
128+
logger.Info("from genericFunc: %v", v)
129+
}
136130

137-
assert.Equal(t, []string{
138-
"log-string log-string log.testLogString{Field:\"detail\"} \x1b[31mlog-string\x1b[0m\n",
139-
"log-string-ptr-receiver log-string-ptr-receiver &log.testLogStringPtrReceiver{Field:\"detail\"} \x1b[31mlog-string-ptr-receiver\x1b[0m\n",
140-
}, w1.GetLogs())
131+
func TestLoggerOutput(t *testing.T) {
132+
t.Run("LogString", func(t *testing.T) {
133+
logger := NewLoggerWithWriters(t.Context(), "test")
134+
w1 := newDummyWriter("dummy-1", DEBUG, 0)
135+
w1.Mode.Colorize = true
136+
logger.AddWriters(w1)
137+
logger.Info("%s %s %#v %v", testLogString{}, &testLogString{}, testLogString{Field: "detail"}, NewColoredValue(testLogString{}, FgRed))
138+
logger.Info("%s %s %#v %v", testLogStringPtrReceiver{}, &testLogStringPtrReceiver{}, testLogStringPtrReceiver{Field: "detail"}, NewColoredValue(testLogStringPtrReceiver{}, FgRed))
139+
logger.Close()
140+
141+
assert.Equal(t, []string{
142+
"log-string log-string log.testLogString{Field:\"detail\"} \x1b[31mlog-string\x1b[0m\n",
143+
"log-string-ptr-receiver log-string-ptr-receiver &log.testLogStringPtrReceiver{Field:\"detail\"} \x1b[31mlog-string-ptr-receiver\x1b[0m\n",
144+
}, w1.FetchLogs())
145+
})
146+
147+
t.Run("Caller", func(t *testing.T) {
148+
logger := NewLoggerWithWriters(t.Context(), "test")
149+
w1 := newDummyWriter("dummy-1", DEBUG, 0)
150+
w1.EventWriterBaseImpl.Mode.Flags.flags = Lmedfile | Lshortfuncname
151+
logger.AddWriters(w1)
152+
anonymousFunc := func(logger Logger) {
153+
logger.Info("from anonymousFunc")
154+
}
155+
genericFunc(logger, "123")
156+
anonymousFunc(logger)
157+
logger.Close()
158+
logs := w1.FetchLogs()
159+
assert.Len(t, logs, 2)
160+
assert.Regexp(t, `modules/log/logger_test.go:\w+:`+regexp.QuoteMeta(`genericFunc() from genericFunc: 123`), logs[0])
161+
assert.Regexp(t, `modules/log/logger_test.go:\w+:`+regexp.QuoteMeta(`TestLoggerOutput.2.1() from anonymousFunc`), logs[1])
162+
})
141163
}
142164

143165
func TestLoggerExpressionFilter(t *testing.T) {
@@ -153,5 +175,5 @@ func TestLoggerExpressionFilter(t *testing.T) {
153175
logger.SendLogEvent(&Event{Level: INFO, Filename: "foo.go", MsgSimpleText: "by filename"})
154176
logger.Close()
155177

156-
assert.Equal(t, []string{"foo\n", "foo bar\n", "by filename\n"}, w1.GetLogs())
178+
assert.Equal(t, []string{"foo\n", "foo bar\n", "by filename\n"}, w1.FetchLogs())
157179
}

‎modules/log/manager_test.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -37,6 +37,6 @@ func TestSharedWorker(t *testing.T) {
3737

3838
m.Close()
3939

40-
logs := w.(*dummyWriter).GetLogs()
40+
logs := w.(*dummyWriter).FetchLogs()
4141
assert.Equal(t, []string{"msg-1\n", "msg-2\n", "msg-3\n"}, logs)
4242
}

‎modules/log/misc.go‎

Lines changed: 8 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -19,8 +19,8 @@ func BaseLoggerToGeneralLogger(b BaseLogger) Logger {
1919

2020
var _ Logger = (*baseToLogger)(nil)
2121

22-
func (s *baseToLogger) Log(skip int, level Level, format string, v ...any) {
23-
s.base.Log(skip+1, level, format, v...)
22+
func (s *baseToLogger) Log(skip int, event *Event, format string, v ...any) {
23+
s.base.Log(skip+1, event, format, v...)
2424
}
2525

2626
func (s *baseToLogger) GetLevel() Level {
@@ -32,27 +32,27 @@ func (s *baseToLogger) LevelEnabled(level Level) bool {
3232
}
3333

3434
func (s *baseToLogger) Trace(format string, v ...any) {
35-
s.base.Log(1, TRACE, format, v...)
35+
s.base.Log(1, &Event{Level: TRACE}, format, v...)
3636
}
3737

3838
func (s *baseToLogger) Debug(format string, v ...any) {
39-
s.base.Log(1, DEBUG, format, v...)
39+
s.base.Log(1, &Event{Level: DEBUG}, format, v...)
4040
}
4141

4242
func (s *baseToLogger) Info(format string, v ...any) {
43-
s.base.Log(1, INFO, format, v...)
43+
s.base.Log(1, &Event{Level: INFO}, format, v...)
4444
}
4545

4646
func (s *baseToLogger) Warn(format string, v ...any) {
47-
s.base.Log(1, WARN, format, v...)
47+
s.base.Log(1, &Event{Level: WARN}, format, v...)
4848
}
4949

5050
func (s *baseToLogger) Error(format string, v ...any) {
51-
s.base.Log(1, ERROR, format, v...)
51+
s.base.Log(1, &Event{Level: ERROR}, format, v...)
5252
}
5353

5454
func (s *baseToLogger) Critical(format string, v ...any) {
55-
s.base.Log(1, CRITICAL, format, v...)
55+
s.base.Log(1, &Event{Level: CRITICAL}, format, v...)
5656
}
5757

5858
type PrintfLogger struct {

‎modules/web/routing/logger.go‎

Lines changed: 20 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -35,6 +35,19 @@ var (
3535
)
3636

3737
func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) {
38+
const callerName = "HTTPRequest"
39+
logTrace := func(fmt string, args ...any) {
40+
logger.Log(2, &log.Event{Level: log.TRACE, Caller: callerName}, fmt, args...)
41+
}
42+
logInfo := func(fmt string, args ...any) {
43+
logger.Log(2, &log.Event{Level: log.INFO, Caller: callerName}, fmt, args...)
44+
}
45+
logWarn := func(fmt string, args ...any) {
46+
logger.Log(2, &log.Event{Level: log.WARN, Caller: callerName}, fmt, args...)
47+
}
48+
logError := func(fmt string, args ...any) {
49+
logger.Log(2, &log.Event{Level: log.ERROR, Caller: callerName}, fmt, args...)
50+
}
3851
return func(trigger Event, record *requestRecord) {
3952
if trigger == StartEvent {
4053
if !logger.LevelEnabled(log.TRACE) {
@@ -44,7 +57,7 @@ func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) {
4457
}
4558
// when a request starts, we have no information about the handler function information, we only have the request path
4659
req := record.request
47-
logger.Trace("router: %s %v %s for %s", startMessage, log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr)
60+
logTrace("router: %s %v %s for %s", startMessage, log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr)
4861
return
4962
}
5063

@@ -60,9 +73,9 @@ func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) {
6073

6174
if trigger == StillExecutingEvent {
6275
message := slowMessage
63-
logf := logger.Warn
76+
logf := logWarn
6477
if isLongPolling {
65-
logf = logger.Info
78+
logf = logInfo
6679
message = pollingMessage
6780
}
6881
logf("router: %s %v %s for %s, elapsed %v @ %s",
@@ -75,7 +88,7 @@ func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) {
7588
}
7689

7790
if panicErr != nil {
78-
logger.Warn("router: %s %v %s for %s, panic in %v @ %s, err=%v",
91+
logWarn("router: %s %v %s for %s, panic in %v @ %s, err=%v",
7992
failedMessage,
8093
log.ColoredMethod(req.Method), req.RequestURI, req.RemoteAddr,
8194
log.ColoredTime(time.Since(record.startTime)),
@@ -89,13 +102,13 @@ func logPrinter(logger log.Logger) func(trigger Event, record *requestRecord) {
89102
if v, ok := record.responseWriter.(types.ResponseStatusProvider); ok {
90103
status = v.WrittenStatus()
91104
}
92-
logf := logger.Info
105+
logf := logInfo
93106
if strings.HasPrefix(req.RequestURI, "/assets/") {
94-
logf = logger.Trace
107+
logf = logTrace
95108
}
96109
message := completedMessage
97110
if isUnknownHandler {
98-
logf = logger.Error
111+
logf = logError
99112
message = unknownHandlerMessage
100113
}
101114

0 commit comments

Comments
 (0)