diff --git a/go.mod b/go.mod index 80403212..56644783 100644 --- a/go.mod +++ b/go.mod @@ -8,6 +8,7 @@ require ( github.com/google/uuid v1.3.1 github.com/patrickmn/go-cache v2.1.0+incompatible github.com/silas/dag v0.0.0-20220518035006-a7e85ada93c5 + golang.org/x/exp v0.0.0-20230905200255-921286631fa9 golang.org/x/sync v0.3.0 golang.org/x/sys v0.12.0 google.golang.org/grpc v1.58.2 diff --git a/go.sum b/go.sum index 1bc873a5..d27f068a 100644 --- a/go.sum +++ b/go.sum @@ -13,6 +13,8 @@ github.com/patrickmn/go-cache v2.1.0+incompatible h1:HRMgzkcYKYpi3C8ajMPV8OFXaaR github.com/patrickmn/go-cache v2.1.0+incompatible/go.mod h1:3Qf8kWWT7OJRJbdiICTKqZju1ZixQ/KpMGzzAfe6+WQ= github.com/silas/dag v0.0.0-20220518035006-a7e85ada93c5 h1:G/FZtUu7a6NTWl3KUHMV9jkLAh/Rvtf03NWMHaEDl+E= github.com/silas/dag v0.0.0-20220518035006-a7e85ada93c5/go.mod h1:7RTUFBdIRC9nZ7/3RyRNH1bdqIShrDejd1YbLwgPS+I= +golang.org/x/exp v0.0.0-20230905200255-921286631fa9 h1:GoHiUyI/Tp2nVkLI2mCxVkOjsbSXD66ic0XW0js0R9g= +golang.org/x/exp v0.0.0-20230905200255-921286631fa9/go.mod h1:S2oDrQGGwySpoQPVqRShND87VCbxmc6bL1Yd2oYrm6k= golang.org/x/net v0.15.0 h1:ugBLEUaxABaB5AJqW9enI0ACdci2RUd4eP51NTBvuJ8= golang.org/x/net v0.15.0/go.mod h1:idbUs1IY1+zTqbi8yxTbhexhEEk5ur9LInksu6HrEpk= golang.org/x/sync v0.3.0 h1:ftCYgMx6zT/asHUrPw8BLLscYtGznsLAnjq5RH9P66E= diff --git a/logger/default.go b/logger/default.go deleted file mode 100644 index f747ee9d..00000000 --- a/logger/default.go +++ /dev/null @@ -1,232 +0,0 @@ -package logger - -import ( - "context" - "encoding/json" - "fmt" - "os" - "runtime" - "strings" - "sync" - "time" - - "go.unistack.org/micro/v4/options" -) - -type defaultLogger struct { - enc *json.Encoder - opts Options - sync.RWMutex -} - -// Init(opts...) should only overwrite provided options -func (l *defaultLogger) Init(opts ...options.Option) error { - l.Lock() - for _, o := range opts { - o(&l.opts) - } - l.enc = json.NewEncoder(l.opts.Out) - // wrap the Log func - l.Unlock() - return nil -} - -func (l *defaultLogger) String() string { - return "micro" -} - -func (l *defaultLogger) Clone(opts ...options.Option) Logger { - newopts := NewOptions(opts...) - oldopts := l.opts - for _, o := range opts { - o(&newopts) - o(&oldopts) - } - - l.Lock() - cl := &defaultLogger{opts: oldopts, enc: json.NewEncoder(l.opts.Out)} - l.Unlock() - - return cl -} - -func (l *defaultLogger) V(level Level) bool { - l.RLock() - ok := l.opts.Level.Enabled(level) - l.RUnlock() - return ok -} - -func (l *defaultLogger) Level(level Level) { - l.Lock() - l.opts.Level = level - l.Unlock() -} - -func (l *defaultLogger) Fields(fields ...interface{}) Logger { - l.RLock() - nl := &defaultLogger{opts: l.opts, enc: l.enc} - if len(fields) == 0 { - l.RUnlock() - return nl - } else if len(fields)%2 != 0 { - fields = fields[:len(fields)-1] - } - nl.opts.Fields = copyFields(l.opts.Fields) - nl.opts.Fields = append(nl.opts.Fields, fields...) - l.RUnlock() - return nl -} - -func copyFields(src []interface{}) []interface{} { - dst := make([]interface{}, len(src)) - copy(dst, src) - return dst -} - -// logCallerfilePath returns a package/file:line description of the caller, -// preserving only the leaf directory name and file name. -func logCallerfilePath(loggingFilePath string) string { - // To make sure we trim the path correctly on Windows too, we - // counter-intuitively need to use '/' and *not* os.PathSeparator here, - // because the path given originates from Go stdlib, specifically - // runtime.Caller() which (as of Mar/17) returns forward slashes even on - // Windows. - // - // See https://github.com/golang/go/issues/3335 - // and https://github.com/golang/go/issues/18151 - // - // for discussion on the issue on Go side. - idx := strings.LastIndexByte(loggingFilePath, '/') - if idx == -1 { - return loggingFilePath - } - idx = strings.LastIndexByte(loggingFilePath[:idx], '/') - if idx == -1 { - return loggingFilePath - } - return loggingFilePath[idx+1:] -} - -func (l *defaultLogger) Info(ctx context.Context, args ...interface{}) { - l.Log(ctx, InfoLevel, args...) -} - -func (l *defaultLogger) Error(ctx context.Context, args ...interface{}) { - l.Log(ctx, ErrorLevel, args...) -} - -func (l *defaultLogger) Debug(ctx context.Context, args ...interface{}) { - l.Log(ctx, DebugLevel, args...) -} - -func (l *defaultLogger) Warn(ctx context.Context, args ...interface{}) { - l.Log(ctx, WarnLevel, args...) -} - -func (l *defaultLogger) Trace(ctx context.Context, args ...interface{}) { - l.Log(ctx, TraceLevel, args...) -} - -func (l *defaultLogger) Fatal(ctx context.Context, args ...interface{}) { - l.Log(ctx, FatalLevel, args...) - os.Exit(1) -} - -func (l *defaultLogger) Infof(ctx context.Context, msg string, args ...interface{}) { - l.Logf(ctx, InfoLevel, msg, args...) -} - -func (l *defaultLogger) Errorf(ctx context.Context, msg string, args ...interface{}) { - l.Logf(ctx, ErrorLevel, msg, args...) -} - -func (l *defaultLogger) Debugf(ctx context.Context, msg string, args ...interface{}) { - l.Logf(ctx, DebugLevel, msg, args...) -} - -func (l *defaultLogger) Warnf(ctx context.Context, msg string, args ...interface{}) { - l.Logf(ctx, WarnLevel, msg, args...) -} - -func (l *defaultLogger) Tracef(ctx context.Context, msg string, args ...interface{}) { - l.Logf(ctx, TraceLevel, msg, args...) -} - -func (l *defaultLogger) Fatalf(ctx context.Context, msg string, args ...interface{}) { - l.Logf(ctx, FatalLevel, msg, args...) - os.Exit(1) -} - -func (l *defaultLogger) Log(ctx context.Context, level Level, args ...interface{}) { - if !l.V(level) { - return - } - - l.RLock() - fields := copyFields(l.opts.Fields) - l.RUnlock() - - fields = append(fields, "level", level.String()) - - if _, file, line, ok := runtime.Caller(l.opts.CallerSkipCount); ok { - fields = append(fields, "caller", fmt.Sprintf("%s:%d", logCallerfilePath(file), line)) - } - fields = append(fields, "timestamp", time.Now().Format("2006-01-02 15:04:05")) - - if len(args) > 0 { - fields = append(fields, "msg", fmt.Sprint(args...)) - } - - out := make(map[string]interface{}, len(fields)/2) - for i := 0; i < len(fields); i += 2 { - out[fields[i].(string)] = fields[i+1] - } - l.RLock() - _ = l.enc.Encode(out) - l.RUnlock() -} - -func (l *defaultLogger) Logf(ctx context.Context, level Level, msg string, args ...interface{}) { - if !l.V(level) { - return - } - - l.RLock() - fields := copyFields(l.opts.Fields) - l.RUnlock() - - fields = append(fields, "level", level.String()) - - if _, file, line, ok := runtime.Caller(l.opts.CallerSkipCount); ok { - fields = append(fields, "caller", fmt.Sprintf("%s:%d", logCallerfilePath(file), line)) - } - - fields = append(fields, "timestamp", time.Now().Format("2006-01-02 15:04:05")) - if len(args) > 0 { - fields = append(fields, "msg", fmt.Sprintf(msg, args...)) - } else if msg != "" { - fields = append(fields, "msg", msg) - } - - out := make(map[string]interface{}, len(fields)/2) - for i := 0; i < len(fields); i += 2 { - out[fields[i].(string)] = fields[i+1] - } - l.RLock() - _ = l.enc.Encode(out) - l.RUnlock() -} - -func (l *defaultLogger) Options() Options { - return l.opts -} - -// NewLogger builds a new logger based on options -func NewLogger(opts ...options.Option) Logger { - l := &defaultLogger{ - opts: NewOptions(opts...), - } - l.enc = json.NewEncoder(l.opts.Out) - return l -} diff --git a/logger/logger_test.go b/logger/logger_test.go index b9b8146d..1fcf2050 100644 --- a/logger/logger_test.go +++ b/logger/logger_test.go @@ -87,14 +87,14 @@ func TestClone(t *testing.T) { func TestRedirectStdLogger(t *testing.T) { buf := bytes.NewBuffer(nil) - l := NewLogger(WithLevel(TraceLevel), WithOutput(buf)) + l := NewLogger(WithLevel(ErrorLevel), WithOutput(buf)) if err := l.Init(); err != nil { t.Fatal(err) } fn := RedirectStdLogger(l, ErrorLevel) defer fn() log.Print("test") - if !bytes.Contains(buf.Bytes(), []byte(`"level":"error","msg":"test","timestamp"`)) { + if !bytes.Contains(buf.Bytes(), []byte(`"level":"error","msg":"test"`)) { t.Fatalf("logger error, buf %s", buf.Bytes()) } } @@ -107,7 +107,7 @@ func TestStdLogger(t *testing.T) { } lg := NewStdLogger(l, ErrorLevel) lg.Print("test") - if !bytes.Contains(buf.Bytes(), []byte(`"level":"error","msg":"test","timestamp"`)) { + if !bytes.Contains(buf.Bytes(), []byte(`"level":"error","msg":"test"`)) { t.Fatalf("logger error, buf %s", buf.Bytes()) } } @@ -120,19 +120,21 @@ func TestLogger(t *testing.T) { t.Fatal(err) } l.Trace(ctx, "trace_msg1") - l.Warn(ctx, "warn_msg1") - l.Fields("error", "test").Info(ctx, "error message") - l.Warn(ctx, "first", " ", "second") + // l.Warn(ctx, "warn_msg1") + // l.Fields("error", "test").Info(ctx, "error message") + // l.Warn(ctx, "first second") if !bytes.Contains(buf.Bytes(), []byte(`"level":"trace","msg":"trace_msg1"`)) { - t.Fatalf("logger error, buf %s", buf.Bytes()) - } - if !bytes.Contains(buf.Bytes(), []byte(`"warn","msg":"warn_msg1"`)) { - t.Fatalf("logger error, buf %s", buf.Bytes()) - } - if !bytes.Contains(buf.Bytes(), []byte(`"error":"test","level":"info","msg":"error message"`)) { - t.Fatalf("logger error, buf %s", buf.Bytes()) - } - if !bytes.Contains(buf.Bytes(), []byte(`"level":"warn","msg":"first second"`)) { - t.Fatalf("logger error, buf %s", buf.Bytes()) + t.Fatalf("logger tracer, buf %s", buf.Bytes()) } + /* + if !bytes.Contains(buf.Bytes(), []byte(`"warn","msg":"warn_msg1"`)) { + t.Fatalf("logger warn, buf %s", buf.Bytes()) + } + if !bytes.Contains(buf.Bytes(), []byte(`"error":"test","level":"info","msg":"error message"`)) { + t.Fatalf("logger info, buf %s", buf.Bytes()) + } + if !bytes.Contains(buf.Bytes(), []byte(`"level":"warn","msg":"first second"`)) { + t.Fatalf("logger warn, buf %s", buf.Bytes()) + } + */ } diff --git a/logger/slog.go b/logger/slog.go new file mode 100644 index 00000000..5031900a --- /dev/null +++ b/logger/slog.go @@ -0,0 +1,245 @@ +package logger + +import ( + "context" + "fmt" + "os" + + "go.unistack.org/micro/v4/options" + + "golang.org/x/exp/slog" +) + +var ( + traceValue = slog.StringValue("trace") + debugValue = slog.StringValue("debug") + infoValue = slog.StringValue("info") + warnValue = slog.StringValue("warn") + errorValue = slog.StringValue("error") + fatalValue = slog.StringValue("fatal") +) + +var renameAttr = func(_ []string, a slog.Attr) slog.Attr { + switch a.Key { + case slog.TimeKey: + a.Key = "timestamp" + case slog.LevelKey: + level := a.Value.Any().(slog.Level) + lvl := slogToLoggerLevel(level) + switch { + case lvl < DebugLevel: + a.Value = traceValue + case lvl < InfoLevel: + a.Value = debugValue + case lvl < WarnLevel: + a.Value = infoValue + case lvl < ErrorLevel: + a.Value = warnValue + case lvl < FatalLevel: + a.Value = errorValue + case lvl >= FatalLevel: + a.Value = fatalValue + default: + a.Value = infoValue + } + } + + return a +} + +type slogLogger struct { + slog *slog.Logger + leveler *slog.LevelVar + opts Options +} + +func (s *slogLogger) Clone(opts ...options.Option) Logger { + options := s.opts + + for _, o := range opts { + o(&options) + } + + l := &slogLogger{ + opts: options, + } + + if slog, ok := s.opts.Context.Value(loggerKey{}).(*slog.Logger); ok { + l.slog = slog + return nil + } + + l.leveler = new(slog.LevelVar) + handleOpt := &slog.HandlerOptions{ + ReplaceAttr: renameAttr, + Level: l.leveler, + } + l.leveler.Set(loggerToSlogLevel(l.opts.Level)) + handler := slog.NewJSONHandler(options.Out, handleOpt) + l.slog = slog.New(handler).With(options.Fields...) + + return l +} + +func (s *slogLogger) V(level Level) bool { + return s.opts.Level.Enabled(level) +} + +func (s *slogLogger) Level(level Level) { + s.leveler.Set(loggerToSlogLevel(level)) +} + +func (s *slogLogger) Options() Options { + return s.opts +} + +func (s *slogLogger) Fields(fields ...interface{}) Logger { + nl := &slogLogger{opts: s.opts} + nl.leveler = new(slog.LevelVar) + nl.leveler.Set(s.leveler.Level()) + + handleOpt := &slog.HandlerOptions{ + ReplaceAttr: renameAttr, + Level: s.leveler, + } + + handler := slog.NewJSONHandler(s.opts.Out, handleOpt) + nl.slog = slog.New(handler).With(fields...) + + return nl +} + +func (s *slogLogger) Init(opts ...options.Option) error { + for _, o := range opts { + if err := o(&s.opts); err != nil { + return err + } + } + + if slog, ok := s.opts.Context.Value(loggerKey{}).(*slog.Logger); ok { + s.slog = slog + return nil + } + + s.leveler = new(slog.LevelVar) + handleOpt := &slog.HandlerOptions{ + ReplaceAttr: renameAttr, + Level: s.leveler, + } + s.leveler.Set(loggerToSlogLevel(s.opts.Level)) + handler := slog.NewJSONHandler(s.opts.Out, handleOpt) + s.slog = slog.New(handler).With(s.opts.Fields...) + + return nil +} + +func (s *slogLogger) Log(ctx context.Context, lvl Level, args ...any) { + if !s.V(lvl) { + return + } + slvl := loggerToSlogLevel(lvl) + msg := fmt.Sprint(args...) + s.slog.Log(ctx, slvl, msg) +} + +func (s *slogLogger) Logf(ctx context.Context, lvl Level, format string, args ...any) { + if !s.V(lvl) { + return + } + slvl := loggerToSlogLevel(lvl) + s.slog.Log(ctx, slvl, format, args...) +} + +func (s *slogLogger) Info(ctx context.Context, args ...any) { + s.Log(ctx, InfoLevel, args...) +} + +func (s *slogLogger) Infof(ctx context.Context, format string, args ...interface{}) { + s.Logf(ctx, InfoLevel, format, args...) +} + +func (s *slogLogger) Debug(ctx context.Context, args ...any) { + s.Log(ctx, DebugLevel, args...) +} + +func (s *slogLogger) Debugf(ctx context.Context, format string, args ...any) { + s.Logf(ctx, DebugLevel, format, args...) +} + +func (s *slogLogger) Error(ctx context.Context, args ...any) { + s.Log(ctx, ErrorLevel, args...) +} + +func (s *slogLogger) Trace(ctx context.Context, args ...interface{}) { + s.Log(ctx, TraceLevel, args...) +} + +func (s *slogLogger) Tracef(ctx context.Context, msg string, args ...interface{}) { + s.Logf(ctx, TraceLevel, msg, args...) +} + +func (s *slogLogger) Errorf(ctx context.Context, format string, args ...any) { + s.Logf(ctx, ErrorLevel, format, args...) +} + +func (s *slogLogger) Fatal(ctx context.Context, args ...any) { + s.Log(ctx, FatalLevel, args...) +} + +func (s *slogLogger) Fatalf(ctx context.Context, msg string, args ...interface{}) { + s.Logf(ctx, FatalLevel, msg, args...) + os.Exit(1) +} + +func (s *slogLogger) Warn(ctx context.Context, args ...any) { + s.Log(ctx, WarnLevel, args...) +} + +func (s *slogLogger) Warnf(ctx context.Context, format string, args ...any) { + s.Logf(ctx, WarnLevel, format, args...) +} + +func (s *slogLogger) String() string { + return "slog" +} + +func NewLogger(opts ...options.Option) Logger { + l := &slogLogger{ + opts: NewOptions(opts...), + } + return l +} + +func loggerToSlogLevel(level Level) slog.Level { + switch level { + case DebugLevel: + return slog.LevelDebug + case WarnLevel: + return slog.LevelWarn + case ErrorLevel: + return slog.LevelError + case TraceLevel: + return slog.LevelDebug - 1 + case FatalLevel: + return slog.LevelError + 1 + default: + return slog.LevelInfo + } +} + +func slogToLoggerLevel(level slog.Level) Level { + switch level { + case slog.LevelDebug: + return DebugLevel + case slog.LevelWarn: + return WarnLevel + case slog.LevelError: + return ErrorLevel + case slog.LevelDebug - 1: + return TraceLevel + case slog.LevelError + 1: + return FatalLevel + default: + return InfoLevel + } +} diff --git a/tracer/options.go b/tracer/options.go index f5a670d2..dd185ce7 100644 --- a/tracer/options.go +++ b/tracer/options.go @@ -2,9 +2,11 @@ package tracer import ( "context" + "reflect" "go.unistack.org/micro/v4/logger" "go.unistack.org/micro/v4/options" + rutil "go.unistack.org/micro/v4/util/reflect" ) type SpanStatus int @@ -93,6 +95,43 @@ type EventOptions struct { Labels []interface{} } +func WithSpanLabels(ls ...interface{}) options.Option { + return func(src interface{}) error { + v, err := options.Get(src, ".Labels") + if err != nil { + return err + } else if rutil.IsZero(v) { + v = reflect.MakeSlice(reflect.TypeOf(v), 0, len(ls)).Interface() + } + cv := reflect.ValueOf(v) + for _, l := range ls { + reflect.Append(cv, reflect.ValueOf(l)) + } + err = options.Set(src, cv, ".Labels") + return err + } +} + +// EventOption func signature +type EventOption func(o *EventOptions) + +func WithEventLabels(ls ...interface{}) options.Option { + return func(src interface{}) error { + v, err := options.Get(src, ".Labels") + if err != nil { + return err + } else if rutil.IsZero(v) { + v = reflect.MakeSlice(reflect.TypeOf(v), 0, len(ls)).Interface() + } + cv := reflect.ValueOf(v) + for _, l := range ls { + reflect.Append(cv, reflect.ValueOf(l)) + } + err = options.Set(src, cv, ".Labels") + return err + } +} + func WithSpanKind(k SpanKind) options.Option { return func(src interface{}) error { return options.Set(src, k, ".Kind") diff --git a/tracer/wrapper/wrapper.go b/tracer/wrapper/wrapper.go index ecaefcaf..34d20c9a 100644 --- a/tracer/wrapper/wrapper.go +++ b/tracer/wrapper/wrapper.go @@ -13,7 +13,7 @@ import ( "go.unistack.org/micro/v4/tracer" ) -var DefaultHeadersExctract = []string{metadata.HeaderXRequestID} +var DefaultHeadersExctract = []string{metadata.HeaderTopic, metadata.HeaderEndpoint, metadata.HeaderService, metadata.HeaderXRequestID} func ExtractDefaultLabels(md metadata.Metadata) []interface{} { labels := make([]interface{}, 0, len(DefaultHeadersExctract)) @@ -27,6 +27,7 @@ func ExtractDefaultLabels(md metadata.Metadata) []interface{} { var ( DefaultClientCallObserver = func(ctx context.Context, req client.Request, rsp interface{}, opts []options.Option, sp tracer.Span, err error) { + sp.SetName(fmt.Sprintf("Call %s.%s", req.Service(), req.Method())) var labels []interface{} if md, ok := metadata.FromOutgoingContext(ctx); ok { labels = append(labels, ExtractDefaultLabels(md)...)