This commit is contained in:
2026-08-16 20:58:57 +08:00
parent a85477be80
commit a9e1f9e6f8
42 changed files with 1569 additions and 156 deletions
+98
View File
@@ -0,0 +1,98 @@
package logging
import (
"fmt"
"go/ast"
"go/parser"
"go/token"
"os"
"regexp"
"strconv"
"strings"
)
type stackFrame struct {
File string
Line int
Func string
}
var stackFileLinePattern = regexp.MustCompile(`\s*(.+\.go):(\d+)\s*$`)
func finalApplicationCaller(stack string) (stackFrame, bool) {
if stack == "" {
return stackFrame{}, false
}
functionName := ""
for _, raw := range strings.Split(stack, "\n") {
line := strings.TrimSpace(raw)
if line == "" {
continue
}
matches := stackFileLinePattern.FindStringSubmatch(line)
if matches == nil {
functionName = line
continue
}
lineNumber, _ := strconv.Atoi(matches[2])
if skipStackFile(matches[1]) {
functionName = ""
continue
}
return stackFrame{File: matches[1], Line: lineNumber, Func: functionName}, true
}
return stackFrame{}, false
}
func skipStackFile(filename string) bool {
normalized := strings.ReplaceAll(filename, "\\", "/")
for _, marker := range []string{
"/go/pkg/mod/",
"/go.uber.org/",
"/gorm.io/",
"/pkg/logging/",
"/internal/server/middleware/",
"/internal/server/router/",
} {
if strings.Contains(normalized, marker) {
return true
}
}
return strings.Contains(normalized, "/src/") &&
(strings.Contains(normalized, "/go/go") || strings.Contains(normalized, "/go/src/"))
}
func functionSourceAt(filename string, line int) (name, source string, startLine, endLine int, err error) {
content, err := os.ReadFile(filename)
if err != nil {
return "", "", 0, 0, fmt.Errorf("read file failed: %w", err)
}
files := token.NewFileSet()
parsed, err := parser.ParseFile(files, filename, content, parser.ParseComments)
if err != nil {
return "", "", 0, 0, fmt.Errorf("parse file failed: %w", err)
}
var target *ast.FuncDecl
ast.Inspect(parsed, func(node ast.Node) bool {
declaration, ok := node.(*ast.FuncDecl)
if !ok {
return true
}
start := files.Position(declaration.Pos()).Line
end := files.Position(declaration.End()).Line
if line >= start && line <= end {
target, startLine, endLine = declaration, start, end
return false
}
return true
})
if target == nil {
return "", "", 0, 0, fmt.Errorf("no function encloses line %d in %s", line, filename)
}
start := files.Position(target.Pos()).Offset
end := files.Position(target.End()).Offset
if start < 0 || end > len(content) || start >= end {
return "", "", 0, 0, fmt.Errorf("invalid offsets for function: start=%d end=%d len=%d", start, end, len(content))
}
return target.Name.Name, string(content[start:end]), startLine, endLine, nil
}
+121 -8
View File
@@ -24,6 +24,42 @@ type Options struct {
FileOnlyModules []string
}
// ErrorEntry is the storage-neutral representation of an Error-level log.
// Keeping it in pkg/logging lets the log core report failures without taking a
// dependency on the application service or persistence layers.
type ErrorEntry struct {
Form, Info, Level, RequestID, TraceID string
}
// ErrorSink receives Error-level log entries. The sink must not log failures
// through the same logger, otherwise a storage failure could recurse forever.
type ErrorSink interface {
RecordLogError(context.Context, ErrorEntry) error
}
type ErrorSinkFunc func(context.Context, ErrorEntry) error
func (f ErrorSinkFunc) RecordLogError(ctx context.Context, entry ErrorEntry) error {
return f(ctx, entry)
}
type errorSinkState struct {
mu sync.RWMutex
sink ErrorSink
}
func (s *errorSinkState) record(entry ErrorEntry) {
if s == nil {
return
}
s.mu.RLock()
sink := s.sink
s.mu.RUnlock()
if sink != nil {
_ = sink.RecordLogError(context.Background(), entry)
}
}
type handlerOperation struct {
attrs []slog.Attr
group string
@@ -77,12 +113,13 @@ func (h *reloadableHandler) WithGroup(name string) slog.Handler {
}
type ReloadableLogger struct {
state *reloadableHandlerState
filename string
state *reloadableHandlerState
filename string
errorSink *errorSinkState
}
func (l *ReloadableLogger) Reload(root string, options Options) {
handler, cleanup := newZapHandler(root, l.filename, options)
handler, cleanup := newZapHandler(root, l.filename, options, l.errorSink)
l.state.mu.Lock()
previous := l.state.cleanup
l.state.handler = handler
@@ -93,6 +130,17 @@ func (l *ReloadableLogger) Reload(root string, options Options) {
}
}
// SetErrorSink changes the database/audit target while keeping the current
// logger and its hot-reload state intact.
func (l *ReloadableLogger) SetErrorSink(sink ErrorSink) {
if l == nil || l.errorSink == nil {
return
}
l.errorSink.mu.Lock()
l.errorSink.sink = sink
l.errorSink.mu.Unlock()
}
func (l *ReloadableLogger) Close() {
l.state.mu.Lock()
cleanup := l.state.cleanup
@@ -162,6 +210,7 @@ type routedFileCore struct {
retentionDay int
state *routedFileState
fields []zapcore.Field
errorSink *errorSinkState
}
func (c *routedFileCore) Enabled(level zapcore.Level) bool { return c.level.Enabled(level) }
@@ -169,7 +218,7 @@ func (c *routedFileCore) Enabled(level zapcore.Level) bool { return c.level.Enab
func (c *routedFileCore) With(fields []zapcore.Field) zapcore.Core {
inherited := append([]zapcore.Field(nil), c.fields...)
inherited = append(inherited, fields...)
return &routedFileCore{base: c.base.With(fields), encoder: c.encoder, level: c.level, root: c.root, retentionDay: c.retentionDay, state: c.state, fields: inherited}
return &routedFileCore{base: c.base.With(fields), encoder: c.encoder, level: c.level, root: c.root, retentionDay: c.retentionDay, state: c.state, fields: inherited, errorSink: c.errorSink}
}
func (c *routedFileCore) Check(entry zapcore.Entry, checked *zapcore.CheckedEntry) *zapcore.CheckedEntry {
@@ -183,6 +232,9 @@ func (c *routedFileCore) Write(entry zapcore.Entry, fields []zapcore.Field) erro
baseErr := c.base.Write(entry, fields)
allFields := append([]zapcore.Field(nil), c.fields...)
allFields = append(allFields, fields...)
if entry.Level >= zapcore.ErrorLevel && !isGORMLoggerEntry(entry.Caller.File, allFields) {
c.errorSink.record(errorEntryFromZap(entry, allFields))
}
paths := routedLogPaths(moduleField(allFields), entry.Level)
if len(paths) == 0 {
return baseErr
@@ -204,6 +256,66 @@ func (c *routedFileCore) Write(entry zapcore.Entry, fields []zapcore.Field) erro
return baseErr
}
func isGORMLoggerEntry(filename string, fields []zapcore.Field) bool {
for _, field := range fields {
if field.Key == "gorm_logger" {
return true
}
}
normalized := strings.ReplaceAll(filename, "\\", "/")
return strings.HasSuffix(normalized, "/gorm_logger_writer.go") ||
strings.HasSuffix(normalized, "/internal/data/gorm_logger.go")
}
func errorEntryFromZap(entry zapcore.Entry, fields []zapcore.Field) ErrorEntry {
requestID, traceID, errorText := "", "", ""
for _, field := range fields {
switch field.Key {
case "request_id":
if requestID == "" {
requestID = zapFieldString(field)
}
case "trace_id":
if traceID == "" {
traceID = zapFieldString(field)
}
case "error", "err":
if errorText == "" {
errorText = zapFieldString(field)
}
}
}
info := entry.Message
if errorText != "" {
info += " | 错误: " + errorText
}
if entry.Caller.File != "" {
info += fmt.Sprintf(" \n 源文件:%s:%d", entry.Caller.File, entry.Caller.Line)
}
if entry.Stack != "" {
info += " \n 调用栈:" + entry.Stack
if frame, ok := finalApplicationCaller(entry.Stack); ok {
functionName, source, startLine, endLine, err := functionSourceAt(frame.File, frame.Line)
if err == nil {
info += fmt.Sprintf(" \n 最终调用方法:%s:%d (%s lines %d-%d)\n----- 产生日志的方法代码如下 -----\n%s", frame.File, frame.Line, functionName, startLine, endLine, source)
} else {
info += fmt.Sprintf(" \n 最终调用方法:%s:%d (%s) | extract_err=%v", frame.File, frame.Line, functionName, err)
}
}
}
return ErrorEntry{Form: "后端", Info: info, Level: entry.Level.String(), RequestID: requestID, TraceID: traceID}
}
func zapFieldString(field zapcore.Field) string {
if field.String != "" {
return field.String
}
if field.Interface != nil {
return fmt.Sprint(field.Interface)
}
return ""
}
func (c *routedFileCore) Sync() error {
result := c.base.Sync()
c.state.mu.Lock()
@@ -274,7 +386,7 @@ func safeModuleName(value string) string {
// NewZapLogger adapts a Zap core to the slog logger used by Kratos v3.
// The file layout remains compatible with the administration log viewer.
func newZapHandler(root, filename string, options Options) (slog.Handler, func()) {
func newZapHandler(root, filename string, options Options, errorSink *errorSinkState) (slog.Handler, func()) {
file := NewDailyWriter(root, filename, options.RetentionDay)
encoder := zap.NewProductionEncoderConfig()
encoder.EncodeTime = zapcore.RFC3339NanoTimeEncoder
@@ -324,7 +436,7 @@ func newZapHandler(root, filename string, options Options) (slog.Handler, func()
consoleCore := zapcore.NewCore(outputEncoder.Clone(), zapcore.AddSync(os.Stdout), levelEnabler)
core = zapcore.NewTee(fileCore, &moduleFilterCore{Core: consoleCore, fileOnly: fileOnly})
}
routed := &routedFileCore{base: core, encoder: outputEncoder.Clone(), level: levelEnabler, root: root, retentionDay: options.RetentionDay, state: &routedFileState{writers: map[string]*DailyWriter{}}}
routed := &routedFileCore{base: core, encoder: outputEncoder.Clone(), level: levelEnabler, root: root, retentionDay: options.RetentionDay, state: &routedFileState{writers: map[string]*DailyWriter{}}, errorSink: errorSink}
zapLogger := zap.New(routed)
handlerOptions := []zapslog.HandlerOption{zapslog.AddStacktraceAt(slog.LevelError)}
if options.ShowLine {
@@ -342,9 +454,10 @@ func newZapHandler(root, filename string, options Options) (slog.Handler, func()
// NewReloadableZapLogger keeps the slog/Kratos adapter stable while replacing
// the underlying Zap core when the runtime configuration changes.
func NewReloadableZapLogger(root, filename string, options Options, attrs ...any) (*slog.Logger, *ReloadableLogger) {
baseHandler, cleanup := newZapHandler(root, filename, options)
errorSink := &errorSinkState{}
baseHandler, cleanup := newZapHandler(root, filename, options, errorSink)
state := &reloadableHandlerState{handler: baseHandler, cleanup: cleanup}
control := &ReloadableLogger{state: state, filename: filename}
control := &ReloadableLogger{state: state, filename: filename, errorSink: errorSink}
handler := &contextHandler{handler: &reloadableHandler{state: state}}
logger := kratoslog.NewLogger(handler, kratoslog.WithExtractor(tracing.TraceAttrs)).With(attrs...)
return logger, control
+63 -3
View File
@@ -5,12 +5,16 @@ import (
"log/slog"
"os"
"path/filepath"
"strings"
"testing"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"
)
func TestZapHandlerHonorsConfiguredLevel(t *testing.T) {
root := t.TempDir()
handler, cleanup := newZapHandler(root, "application.log", Options{Level: "error", Format: "json"})
handler, cleanup := newZapHandler(root, "application.log", Options{Level: "error", Format: "json"}, nil)
defer cleanup()
if handler.Enabled(context.Background(), slog.LevelInfo) {
@@ -23,7 +27,7 @@ func TestZapHandlerHonorsConfiguredLevel(t *testing.T) {
func TestZapHandlerUsesDebugFallbackForInvalidLevel(t *testing.T) {
root := t.TempDir()
handler, cleanup := newZapHandler(root, "application.log", Options{Level: "not-a-level", Format: "json"})
handler, cleanup := newZapHandler(root, "application.log", Options{Level: "not-a-level", Format: "json"}, nil)
defer cleanup()
if !handler.Enabled(context.Background(), slog.LevelDebug) {
@@ -33,7 +37,7 @@ func TestZapHandlerUsesDebugFallbackForInvalidLevel(t *testing.T) {
func TestZapHandlerRoutesHTTPAndErrorLogs(t *testing.T) {
root := t.TempDir()
handler, cleanup := newZapHandler(root, "application.log", Options{Level: "info", Format: "json"})
handler, cleanup := newZapHandler(root, "application.log", Options{Level: "info", Format: "json"}, nil)
logger := slog.New(handler)
logger.Info("request", "mod", "http", "request_id", "req-1")
logger.Error("failed", "mod", "users")
@@ -56,3 +60,59 @@ func TestZapHandlerRoutesHTTPAndErrorLogs(t *testing.T) {
}
}
}
func TestZapHandlerRecordsEveryErrorThroughSink(t *testing.T) {
root := t.TempDir()
var entries []ErrorEntry
logger, control := NewReloadableZapLogger(root, "application.log", Options{Level: "info", Format: "json"})
defer control.Close()
control.SetErrorSink(ErrorSinkFunc(func(_ context.Context, entry ErrorEntry) error {
entries = append(entries, entry)
return nil
}))
logger.Error("task execution failed", "mod", "timedTask", "request_id", "request-1", "trace_id", "trace-1", "error", os.ErrPermission)
control.Reload(t.TempDir(), Options{Level: "info", Format: "json"})
logger.Error("reloaded logger failure", "mod", "system")
if len(entries) != 2 {
t.Fatalf("expected two error entries across reload, got %d", len(entries))
}
entry := entries[0]
if entry.Form != "后端" || entry.Level != "error" || entry.RequestID != "request-1" || entry.TraceID != "trace-1" || !strings.Contains(entry.Info, "task execution failed") || !strings.Contains(entry.Info, os.ErrPermission.Error()) {
t.Fatalf("unexpected error entry: %+v", entry)
}
}
func TestErrorEntryIncludesFinalApplicationSource(t *testing.T) {
filename := filepath.Join(t.TempDir(), "worker.go")
content := "package sample\n\nfunc execute() {\n\tprintln(\"failed\")\n}\n"
if err := os.WriteFile(filename, []byte(content), 0o600); err != nil {
t.Fatal(err)
}
entry := errorEntryFromZap(zapcore.Entry{Message: "task failed", Level: zapcore.ErrorLevel, Stack: "kra/internal/worker.execute\n" + filename + ":4"}, nil)
if !strings.Contains(entry.Info, "最终调用方法:"+filename+":4 (execute lines 3-5)") || !strings.Contains(entry.Info, "func execute()") {
t.Fatalf("expected final caller source in error entry: %s", entry.Info)
}
}
func TestErrorSinkSkipsGORMBridge(t *testing.T) {
root := t.TempDir()
var entries []ErrorEntry
state := &errorSinkState{sink: ErrorSinkFunc(func(_ context.Context, entry ErrorEntry) error {
entries = append(entries, entry)
return nil
})}
base := zapcore.NewNopCore()
core := &routedFileCore{base: base, encoder: zapcore.NewJSONEncoder(zap.NewProductionEncoderConfig()), level: zapcore.ErrorLevel, root: root, state: &routedFileState{writers: map[string]*DailyWriter{}}, errorSink: state}
for _, filename := range []string{"/tmp/gorm_logger_writer.go", "/workspace/internal/data/gorm_logger.go"} {
if err := core.Write(zapcore.Entry{Level: zapcore.ErrorLevel, Message: "database failed", Caller: zapcore.EntryCaller{Defined: true, File: filename, Line: 10}}, nil); err != nil {
t.Fatal(err)
}
}
if err := core.Write(zapcore.Entry{Level: zapcore.ErrorLevel, Message: "database failed"}, []zapcore.Field{zap.Bool("gorm_logger", true)}); err != nil {
t.Fatal(err)
}
if len(entries) != 0 {
t.Fatalf("gorm bridge error must not recurse into sys_error: %+v", entries)
}
}