hoteas
332c2414bc
- WebConnectLog 访问日志新增 ua 字段（User-Agent 按 rune 截断 200 字符），便于按设备归因 - SetSeqWriter 挂 Seq 后业务控制台由 Warn+ 放宽为 Info+，Debug/SQL 仍只进 Seq 与文件 - 新增 Logger.SetConsoleMinLevel，访问日志控制台单独保持 Warn+ Co-authored-by: Cursor <cursoragent@cursor.com>
391 lines
9.5 KiB
Go
391 lines
9.5 KiB
Go
package log
|
|
|
|
import (
|
|
"bytes"
|
|
"encoding/json"
|
|
"io"
|
|
"net/http"
|
|
"net/http/httptest"
|
|
"strings"
|
|
"sync"
|
|
"testing"
|
|
"time"
|
|
|
|
logrus "github.com/sirupsen/logrus"
|
|
"github.com/rs/zerolog"
|
|
)
|
|
|
|
// captureBuf 挂到 multiWriter，收集 EmitCaptured 写入的 JSON 行。
|
|
type captureBuf struct {
|
|
mu sync.Mutex
|
|
lines []string
|
|
}
|
|
|
|
func (c *captureBuf) Write(p []byte) (int, error) {
|
|
c.mu.Lock()
|
|
c.lines = append(c.lines, string(bytes.TrimSpace(p)))
|
|
c.mu.Unlock()
|
|
return len(p), nil
|
|
}
|
|
|
|
func (c *captureBuf) lastJSON() map[string]interface{} {
|
|
c.mu.Lock()
|
|
defer c.mu.Unlock()
|
|
if len(c.lines) == 0 {
|
|
return nil
|
|
}
|
|
var m map[string]interface{}
|
|
_ = json.Unmarshal([]byte(c.lines[len(c.lines)-1]), &m)
|
|
return m
|
|
}
|
|
|
|
func newLoggerWithCapture(logLevel int) (*Logger, *captureBuf) {
|
|
buf := &captureBuf{}
|
|
l := NewLogger(logLevel, "", 0)
|
|
l.mw.add(buf)
|
|
return l, buf
|
|
}
|
|
|
|
func startFakeSeqServer(t *testing.T, onBody func(string)) *httptest.Server {
|
|
t.Helper()
|
|
return httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
|
if r.URL.Path != "/api/events/raw" {
|
|
http.NotFound(w, r)
|
|
return
|
|
}
|
|
body, _ := io.ReadAll(r.Body)
|
|
onBody(string(body))
|
|
w.WriteHeader(http.StatusCreated)
|
|
}))
|
|
}
|
|
|
|
func TestEmitCaptured_LogLevelZero(t *testing.T) {
|
|
l, buf := newLoggerWithCapture(0)
|
|
l.EmitCaptured(zerolog.InfoLevel, "stdout", "请求参数GetReqMap /api/test")
|
|
m := buf.lastJSON()
|
|
if m == nil {
|
|
t.Fatal("expected captured line")
|
|
}
|
|
if m["source"] != "stdout" {
|
|
t.Fatalf("source=%v want stdout", m["source"])
|
|
}
|
|
if m["level"] != "info" {
|
|
t.Fatalf("level=%v want info", m["level"])
|
|
}
|
|
if !strings.Contains(m["message"].(string), "GetReqMap") {
|
|
t.Fatalf("message=%v", m["message"])
|
|
}
|
|
}
|
|
|
|
func TestEmitCaptured_StderrSource(t *testing.T) {
|
|
l, buf := newLoggerWithCapture(0)
|
|
l.EmitCaptured(zerolog.ErrorLevel, "stderr", "driver error")
|
|
m := buf.lastJSON()
|
|
if m["source"] != "stderr" {
|
|
t.Fatalf("source=%v want stderr", m["source"])
|
|
}
|
|
if m["level"] != "error" {
|
|
t.Fatalf("level=%v want error", m["level"])
|
|
}
|
|
}
|
|
|
|
func TestToClef_PlainText(t *testing.T) {
|
|
sw := &SeqWriter{instance: "127.0.0.1:8081"}
|
|
clef := sw.toClef([]byte("plain log line\n"))
|
|
var m map[string]interface{}
|
|
if err := json.Unmarshal(clef, &m); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if m["@m"] != "plain log line" {
|
|
t.Fatalf("@m=%v", m["@m"])
|
|
}
|
|
if m["source"] != "stdout" {
|
|
t.Fatalf("source=%v", m["source"])
|
|
}
|
|
if m["@l"] != "Information" {
|
|
t.Fatalf("@l=%v", m["@l"])
|
|
}
|
|
}
|
|
|
|
func TestWithFields_ChildHasFieldsParentClean(t *testing.T) {
|
|
parent, buf := newLoggerWithCapture(1)
|
|
child := parent.WithFields("sid", "abc123def456", "request_id", "fedcba987654")
|
|
child.Info().Msg("child-msg")
|
|
m := buf.lastJSON()
|
|
if m == nil {
|
|
t.Fatal("no output")
|
|
}
|
|
if m["sid"] != "abc123def456" || m["request_id"] != "fedcba987654" {
|
|
t.Fatalf("child fields missing: %v", m)
|
|
}
|
|
parent.Info().Msg("parent-msg")
|
|
m2 := buf.lastJSON()
|
|
if m2["sid"] != nil || m2["request_id"] != nil {
|
|
t.Fatalf("parent polluted: %v", m2)
|
|
}
|
|
// 错误历史父子共享
|
|
parent2 := NewLogger(1, "", 10)
|
|
child2 := parent2.WithFields("sid", "x")
|
|
child2.Error("shared-err")
|
|
if n := len(parent2.GetRecentErrors()); n != 1 {
|
|
t.Fatalf("shared error store want 1 got %d", n)
|
|
}
|
|
}
|
|
|
|
func TestToClef_MillisecondAndAtM(t *testing.T) {
|
|
sw := &SeqWriter{instance: "test:1"}
|
|
in := []byte(`{"level":"info","time":"2026-07-23 04:50:01.123","message":"hello {name}"}`)
|
|
clef := sw.toClef(in)
|
|
var m map[string]interface{}
|
|
if err := json.Unmarshal(clef, &m); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if m["@m"] != "hello {name}" {
|
|
t.Fatalf("@m=%v", m["@m"])
|
|
}
|
|
if m["@mt"] != nil {
|
|
t.Fatalf("should not have @mt: %v", m["@mt"])
|
|
}
|
|
at, ok := m["@t"].(string)
|
|
if !ok || !strings.Contains(at, ".123") {
|
|
t.Fatalf("@t missing ms: %v", m["@t"])
|
|
}
|
|
}
|
|
|
|
func TestSeqWriter_RetryOnce(t *testing.T) {
|
|
var mu sync.Mutex
|
|
calls := 0
|
|
var gotBody string
|
|
srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
|
body, _ := io.ReadAll(r.Body)
|
|
mu.Lock()
|
|
calls++
|
|
n := calls
|
|
if n == 1 {
|
|
mu.Unlock()
|
|
w.WriteHeader(http.StatusInternalServerError)
|
|
return
|
|
}
|
|
gotBody = string(body)
|
|
mu.Unlock()
|
|
w.WriteHeader(http.StatusCreated)
|
|
}))
|
|
defer srv.Close()
|
|
|
|
l := NewLogger(1, "", 0)
|
|
l.SetSeqWriter(srv.URL, "", "test:retry")
|
|
l.Info().Msg("retry-me")
|
|
|
|
deadline := time.Now().Add(4 * time.Second)
|
|
for time.Now().Before(deadline) {
|
|
mu.Lock()
|
|
ok := calls >= 2 && strings.Contains(gotBody, "retry-me")
|
|
mu.Unlock()
|
|
if ok {
|
|
return
|
|
}
|
|
time.Sleep(50 * time.Millisecond)
|
|
}
|
|
mu.Lock()
|
|
defer mu.Unlock()
|
|
t.Fatalf("retry failed: calls=%d body=%q", calls, gotBody)
|
|
}
|
|
|
|
func TestLevelFilterWriter_WarnOnly(t *testing.T) {
|
|
buf := &captureBuf{}
|
|
w := newLevelFilterWriter(buf, zerolog.WarnLevel)
|
|
mw := &multiWriter{writers: []io.Writer{w}}
|
|
zl := zerolog.New(mw).Level(zerolog.DebugLevel)
|
|
zl.Info().Msg("info-hidden")
|
|
zl.Warn().Msg("warn-shown")
|
|
buf.mu.Lock()
|
|
n := len(buf.lines)
|
|
buf.mu.Unlock()
|
|
if n != 1 {
|
|
t.Fatalf("want 1 console line got %d: %v", n, buf.lines)
|
|
}
|
|
if !strings.Contains(buf.lines[0], "warn-shown") {
|
|
t.Fatalf("unexpected: %v", buf.lines[0])
|
|
}
|
|
}
|
|
|
|
// TestSetSeqWriter_QuietsConsoleKeepsSeqFull 验证挂 Seq 后控制台放宽到 Info+：
|
|
// Debug 不上控制台，Info/Warn 均可见，Seq 侧全量收到（含 Debug）。
|
|
func TestSetSeqWriter_QuietsConsoleKeepsSeqFull(t *testing.T) {
|
|
var mu sync.Mutex
|
|
var gotBody string
|
|
srv := startFakeSeqServer(t, func(body string) {
|
|
mu.Lock()
|
|
gotBody += body
|
|
mu.Unlock()
|
|
})
|
|
defer srv.Close()
|
|
|
|
l := NewLogger(1, "", 0)
|
|
consoleBuf := &captureBuf{}
|
|
l.console.inner = consoleBuf
|
|
l.SetSeqWriter(srv.URL, "", "test:quiet")
|
|
l.Debug().Msg("debug-to-seq-only")
|
|
l.Info().Msg("info-both")
|
|
l.Warn().Msg("warn-both")
|
|
|
|
deadline := time.Now().Add(3 * time.Second)
|
|
for time.Now().Before(deadline) {
|
|
mu.Lock()
|
|
ok := strings.Contains(gotBody, "debug-to-seq-only") && strings.Contains(gotBody, "info-both") && strings.Contains(gotBody, "warn-both")
|
|
mu.Unlock()
|
|
if ok {
|
|
break
|
|
}
|
|
time.Sleep(50 * time.Millisecond)
|
|
}
|
|
mu.Lock()
|
|
body := gotBody
|
|
mu.Unlock()
|
|
if !strings.Contains(body, "debug-to-seq-only") || !strings.Contains(body, "info-both") || !strings.Contains(body, "warn-both") {
|
|
t.Fatalf("Seq incomplete: %q", body)
|
|
}
|
|
consoleBuf.mu.Lock()
|
|
defer consoleBuf.mu.Unlock()
|
|
for _, line := range consoleBuf.lines {
|
|
if strings.Contains(line, "debug-to-seq-only") {
|
|
t.Fatalf("Debug leaked to console: %v", consoleBuf.lines)
|
|
}
|
|
}
|
|
foundInfo, foundWarn := false, false
|
|
for _, line := range consoleBuf.lines {
|
|
if strings.Contains(line, "info-both") {
|
|
foundInfo = true
|
|
}
|
|
if strings.Contains(line, "warn-both") {
|
|
foundWarn = true
|
|
}
|
|
}
|
|
if !foundInfo {
|
|
t.Fatalf("Info missing on console: %v", consoleBuf.lines)
|
|
}
|
|
if !foundWarn {
|
|
t.Fatalf("Warn missing on console: %v", consoleBuf.lines)
|
|
}
|
|
l.CloseSeq()
|
|
}
|
|
|
|
func TestSeqWriter_CloseFlushes(t *testing.T) {
|
|
var mu sync.Mutex
|
|
var gotBody string
|
|
srv := startFakeSeqServer(t, func(body string) {
|
|
mu.Lock()
|
|
gotBody += body
|
|
mu.Unlock()
|
|
})
|
|
defer srv.Close()
|
|
|
|
l := NewLogger(1, "", 0)
|
|
l.SetSeqWriter(srv.URL, "", "test:close")
|
|
l.Info().Msg("flush-on-close")
|
|
l.CloseSeq()
|
|
|
|
mu.Lock()
|
|
defer mu.Unlock()
|
|
if !strings.Contains(gotBody, "flush-on-close") {
|
|
t.Fatalf("Close did not flush: %q", gotBody)
|
|
}
|
|
}
|
|
|
|
func TestStdoutCapture_LongLine(t *testing.T) {
|
|
l, buf := newLoggerWithCapture(1)
|
|
pr, pw := io.Pipe()
|
|
done := make(chan struct{})
|
|
go func() {
|
|
CaptureStream(l, zerolog.InfoLevel, "stdout", pr)
|
|
close(done)
|
|
}()
|
|
|
|
longLine := strings.Repeat("x", 70*1024) + "\n"
|
|
shortLine := "after-long-line\n"
|
|
if _, err := pw.Write([]byte(longLine)); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
if _, err := pw.Write([]byte(shortLine)); err != nil {
|
|
t.Fatal(err)
|
|
}
|
|
time.Sleep(100 * time.Millisecond)
|
|
|
|
buf.mu.Lock()
|
|
n := len(buf.lines)
|
|
buf.mu.Unlock()
|
|
if n < 2 {
|
|
t.Fatalf("expected >=2 captured lines, got %d", n)
|
|
}
|
|
last := buf.lastJSON()
|
|
if last == nil || !strings.Contains(last["message"].(string), "after-long-line") {
|
|
t.Fatalf("short line after long line not captured: %v", last)
|
|
}
|
|
_ = pw.Close()
|
|
<-done
|
|
}
|
|
|
|
func TestLogrusBridge_AfterRedirect(t *testing.T) {
|
|
l, buf := newLoggerWithCapture(1)
|
|
pr, pw := io.Pipe()
|
|
go CaptureStream(l, zerolog.InfoLevel, "stdout", pr)
|
|
|
|
logrus.SetOutput(pw)
|
|
logrus.SetLevel(logrus.InfoLevel)
|
|
logrus.Info("wechat-sdk-log")
|
|
time.Sleep(100 * time.Millisecond)
|
|
|
|
m := buf.lastJSON()
|
|
if m == nil || !strings.Contains(m["message"].(string), "wechat-sdk-log") {
|
|
t.Fatalf("logrus not captured: %v", m)
|
|
}
|
|
}
|
|
|
|
func TestSeqWriter_FakeServer(t *testing.T) {
|
|
var gotBody string
|
|
var mu sync.Mutex
|
|
srv := startFakeSeqServer(t, func(body string) {
|
|
mu.Lock()
|
|
gotBody = body
|
|
mu.Unlock()
|
|
})
|
|
defer srv.Close()
|
|
|
|
l := NewLogger(1, "", 0)
|
|
l.SetSeqWriter(srv.URL, "", "test:8081")
|
|
l.Info().Msg("seq-test-message")
|
|
|
|
deadline := time.Now().Add(2 * time.Second)
|
|
for time.Now().Before(deadline) {
|
|
mu.Lock()
|
|
b := gotBody
|
|
mu.Unlock()
|
|
if strings.Contains(b, "seq-test-message") {
|
|
return
|
|
}
|
|
time.Sleep(50 * time.Millisecond)
|
|
}
|
|
t.Fatalf("Seq did not receive message, body=%q", gotBody)
|
|
}
|
|
|
|
func TestEmitRecoveredPanic_LogFields(t *testing.T) {
|
|
l, buf := newLoggerWithCapture(0)
|
|
l.EmitRecoveredPanic("test panic reason")
|
|
m := buf.lastJSON()
|
|
if m == nil {
|
|
t.Fatal("no output")
|
|
}
|
|
if m["source"] != "panic" {
|
|
t.Fatalf("source=%v", m["source"])
|
|
}
|
|
if m["level"] != "error" {
|
|
t.Fatalf("level=%v", m["level"])
|
|
}
|
|
if !strings.Contains(m["message"].(string), "test panic reason") {
|
|
t.Fatalf("message=%v", m["message"])
|
|
}
|
|
if stack, ok := m["stack"].(string); !ok || stack == "" {
|
|
t.Fatalf("stack missing: %v", m["stack"])
|
|
}
|
|
}
|