forgejo/modules/log/logger_test.go
wxiaoguang 910bf31546
Fix flakey test in logger test (#24883)
Fix #24882

The goroutines are all asynchronized. So it needs a little "sleep" to
make sure the writer's goroutine has been paused before sending messages
to it.

Co-authored-by: Giteabot <teabot@gitea.io>
2023-05-23 16:01:20 +00:00

146 lines
3.5 KiB
Go

// Copyright 2023 The Gitea Authors. All rights reserved.
// SPDX-License-Identifier: MIT
package log
import (
"context"
"sync"
"testing"
"time"
"github.com/stretchr/testify/assert"
)
type dummyWriter struct {
*EventWriterBaseImpl
delay time.Duration
mu sync.Mutex
logs []string
}
func (d *dummyWriter) Write(p []byte) (n int, err error) {
if d.delay > 0 {
time.Sleep(d.delay)
}
d.mu.Lock()
defer d.mu.Unlock()
d.logs = append(d.logs, string(p))
return len(p), nil
}
func (d *dummyWriter) Close() error {
return nil
}
func (d *dummyWriter) GetLogs() []string {
d.mu.Lock()
defer d.mu.Unlock()
logs := make([]string, len(d.logs))
copy(logs, d.logs)
return logs
}
func newDummyWriter(name string, level Level, delay time.Duration) *dummyWriter {
w := &dummyWriter{
EventWriterBaseImpl: NewEventWriterBase(name, "dummy", WriterMode{Level: level, Flags: FlagsFromBits(0)}),
}
w.delay = delay
w.Base().OutputWriteCloser = w
return w
}
func TestLogger(t *testing.T) {
logger := NewLoggerWithWriters(context.Background())
dump := logger.DumpWriters()
assert.EqualValues(t, 0, len(dump))
assert.EqualValues(t, NONE, logger.GetLevel())
assert.False(t, logger.IsEnabled())
w1 := newDummyWriter("dummy-1", DEBUG, 0)
logger.AddWriters(w1)
assert.EqualValues(t, DEBUG, logger.GetLevel())
w2 := newDummyWriter("dummy-2", WARN, 200*time.Millisecond)
logger.AddWriters(w2)
assert.EqualValues(t, DEBUG, logger.GetLevel())
dump = logger.DumpWriters()
assert.EqualValues(t, 2, len(dump))
logger.Trace("trace-level") // this level is not logged
logger.Debug("debug-level")
logger.Error("error-level")
// 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())
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())
}
func TestLoggerPause(t *testing.T) {
logger := NewLoggerWithWriters(context.Background())
w1 := newDummyWriter("dummy-1", DEBUG, 0)
logger.AddWriters(w1)
GetManager().PauseAll()
time.Sleep(50 * time.Millisecond)
logger.Info("info-level")
time.Sleep(100 * time.Millisecond)
assert.Equal(t, []string{}, w1.GetLogs())
GetManager().ResumeAll()
time.Sleep(100 * time.Millisecond)
assert.Equal(t, []string{"info-level\n"}, w1.GetLogs())
logger.Close()
}
type testLogString struct {
Field string
}
func (t testLogString) LogString() string {
return "log-string"
}
func TestLoggerLogString(t *testing.T) {
logger := NewLoggerWithWriters(context.Background())
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.Close()
assert.Equal(t, []string{"log-string log-string log.testLogString{Field:\"detail\"} \x1b[31mlog-string\x1b[0m\n"}, w1.GetLogs())
}
func TestLoggerExpressionFilter(t *testing.T) {
logger := NewLoggerWithWriters(context.Background())
w1 := newDummyWriter("dummy-1", DEBUG, 0)
w1.Mode.Expression = "foo.*"
logger.AddWriters(w1)
logger.Info("foo")
logger.Info("bar")
logger.Info("foo bar")
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())
}