From 3df8723d9fb2f42743491645a199859093ff35cd Mon Sep 17 00:00:00 2001 From: Mulavar <978007503@qq.com> Date: Mon, 17 Jul 2023 19:45:12 +0800 Subject: [PATCH] [LOG]Support logging with context(#596) (#705) 1. add composite logger to manage main/sql/tx logger 2. support to parse and propagate the trace context to logging 3. make the logger achieve context level isolation --- cmd/admin/admin.go | 2 +- conf/bootstrap.yaml | 2 +- pkg/executor/redirect.go | 14 +- pkg/trace/jaeger/jaeger.go | 16 +- pkg/trace/trace.go | 6 +- pkg/util/log/logging.go | 317 +++++++++++++++++++++++++------------ 6 files changed, 247 insertions(+), 110 deletions(-) diff --git a/cmd/admin/admin.go b/cmd/admin/admin.go index 6fa205f4..2cd4863a 100644 --- a/cmd/admin/admin.go +++ b/cmd/admin/admin.go @@ -87,7 +87,7 @@ func Run(bootstrapPath string, addr string) error { registryConf := discovery.GetServiceRegistry(context.Background()) serviceDiscovery, err := registry.InitDiscovery(registryConf.Name, registryConf.Options) if err != nil { - log.Fatal("init service discovert failed: %v", err) + log.Fatal("init service discovery failed: %v", err) return err } diff --git a/conf/bootstrap.yaml b/conf/bootstrap.yaml index d42423e0..14f6664a 100644 --- a/conf/bootstrap.yaml +++ b/conf/bootstrap.yaml @@ -67,7 +67,7 @@ supervisor: password: root logging_config: - log_name: arana_log + log_name: arana.log log_path: log log_level: 7 #KERN_DEBUG log_max_size: 10 diff --git a/pkg/executor/redirect.go b/pkg/executor/redirect.go index a29b475f..6a8aee4f 100644 --- a/pkg/executor/redirect.go +++ b/pkg/executor/redirect.go @@ -34,6 +34,10 @@ import ( "github.com/pkg/errors" + rtrace "go.opentelemetry.io/otel/trace" + + "go.uber.org/zap" + "golang.org/x/exp/slices" ) @@ -174,7 +178,15 @@ func (executor *RedirectExecutor) doExecutorComQuery(ctx *proto.Context, act ast hints = append(hints, h) } - trace.Extract(ctx, hints) + // extract trace context + if trace.Extract(ctx, hints) { + traceBytes, err := rtrace.SpanFromContext(ctx).SpanContext().MarshalJSON() + if err != nil { + return nil, 0, err + } + ctx.Context = log.NewContext(ctx.Context, ctx.C.ID(), zap.String("trace-context", strings.ReplaceAll(string(traceBytes), "\"", ""))) + } + metrics.ParserDuration.Observe(time.Since(start).Seconds()) if len(ctx.C.Schema()) < 1 { diff --git a/pkg/trace/jaeger/jaeger.go b/pkg/trace/jaeger/jaeger.go index ee740be1..07791f71 100644 --- a/pkg/trace/jaeger/jaeger.go +++ b/pkg/trace/jaeger/jaeger.go @@ -55,6 +55,7 @@ func (j *Jaeger) Initialize(_ context.Context, traceCfg *config.Trace) error { // Register our TracerProvider as the global so any imported // instrumentation in the future will default to using it. otel.SetTracerProvider(tp) + otel.SetTextMapPropagator(&propagation.TraceContext{}) return nil } @@ -76,17 +77,20 @@ func (j *Jaeger) tracerProvider(traceCfg *config.Trace) (*tracesdk.TracerProvide return tp, nil } -func (j *Jaeger) Extract(ctx *proto.Context, hints []*hint.Hint) { - var traceId string +func (j *Jaeger) Extract(ctx *proto.Context, hints []*hint.Hint) bool { + var ( + traceContext string + ) for _, h := range hints { if h.Type != hint.TypeTrace { continue } - traceId = h.Inputs[0].V + traceContext = h.Inputs[0].V break } - if len(traceId) == 0 { - return + if len(traceContext) == 0 { + return false } - ctx.Context = otel.GetTextMapPropagator().Extract(ctx.Context, propagation.MapCarrier{parentKey: traceId}) + ctx.Context = otel.GetTextMapPropagator().Extract(ctx.Context, propagation.MapCarrier{parentKey: traceContext}) + return true } diff --git a/pkg/trace/trace.go b/pkg/trace/trace.go index 6a11c301..04e6f173 100644 --- a/pkg/trace/trace.go +++ b/pkg/trace/trace.go @@ -63,11 +63,11 @@ func Initialize(ctx context.Context, traceCfg *config.Trace) error { return err } -func Extract(ctx *proto.Context, hints []*hint.Hint) { - currentProvider.Extract(ctx, hints) +func Extract(ctx *proto.Context, hints []*hint.Hint) bool { + return currentProvider.Extract(ctx, hints) } type Provider interface { Initialize(ctx context.Context, traceCfg *config.Trace) error - Extract(ctx *proto.Context, hints []*hint.Hint) + Extract(ctx *proto.Context, hints []*hint.Hint) bool } diff --git a/pkg/util/log/logging.go b/pkg/util/log/logging.go index 9bf46221..d7085307 100644 --- a/pkg/util/log/logging.go +++ b/pkg/util/log/logging.go @@ -19,10 +19,12 @@ package log import ( "bytes" + "context" "errors" "fmt" "os" "path/filepath" + "strconv" ) import ( @@ -35,8 +37,10 @@ import ( type ( // LogLevel represents the level of logging. LogLevel int8 - // LogType represents the type of logging + // LogType represents the type of logging. LogType string + // LoggerKey represents the context key of logging. + LoggerKey string ) const ( @@ -112,6 +116,7 @@ func (l *LogLevel) unmarshalText(text []byte) bool { return true } +//Logger TODO add methods support LogType type Logger interface { Debug(v ...interface{}) Debugf(format string, v ...interface{}) @@ -128,15 +133,9 @@ type Logger interface { } var ( - mainLog Logger - logicalSqlLog Logger - physicalSqlLog Logger - txLog Logger + globalLogger *compositeLogger - loggerCfg *LoggingConfig - zapLogger *zap.Logger - - zapLoggerConfig = zap.NewDevelopmentConfig() + // TODO remove in the future zapLoggerEncoderConfig = zapcore.EncoderConfig{ TimeKey: "time", LevelKey: "level", @@ -149,20 +148,52 @@ var ( EncodeDuration: zapcore.SecondsDurationEncoder, EncodeCaller: zapcore.ShortCallerEncoder, } + defaultLoggingConfig = &LoggingConfig{ + LogName: "arana.log", + LogPath: "log", + LogLevel: -1, + LogMaxSize: 10, + LogMaxBackups: 5, + LogMaxAge: 30, + LogCompress: false, + DefaultLogName: "arana.log", + TxLogName: "tx.log", + SqlLogEnabled: true, + SqlLogName: "sql.log", + PhysicalSqlLogName: "physql.log", + } + loggerCfg = defaultLoggingConfig ) func init() { - zapLoggerConfig.EncoderConfig = zapLoggerEncoderConfig - zapLogger, _ = zapLoggerConfig.Build(zap.AddCallerSkip(1)) - mainLog = zapLogger.Sugar() + globalLogger = NewCompositeLogger(defaultLoggingConfig) } func Init(cfg *LoggingConfig) { loggerCfg = cfg - mainLog = NewLogger(MainLog, cfg) - logicalSqlLog = NewLogger(LogicalSqlLog, cfg) - physicalSqlLog = NewLogger(PhysicalSqlLog, cfg) - txLog = NewLogger(TxLog, cfg) + globalLogger = NewCompositeLogger(cfg) +} + +type compositeLogger struct { + loggerCfg *LoggingConfig + + mainLog *zap.SugaredLogger + logicalSqlLog *zap.SugaredLogger + physicalSqlLog *zap.SugaredLogger + txLog *zap.SugaredLogger + + // TODO replace global slowLog + slowLog *zap.SugaredLogger +} + +func NewCompositeLogger(cfg *LoggingConfig) *compositeLogger { + return &compositeLogger{ + loggerCfg: cfg, + mainLog: NewLogger(MainLog, cfg), + logicalSqlLog: NewLogger(LogicalSqlLog, cfg), + physicalSqlLog: NewLogger(PhysicalSqlLog, cfg), + txLog: NewLogger(TxLog, cfg), + } } func NewLogger(logType LogType, cfg *LoggingConfig) *zap.SugaredLogger { @@ -172,13 +203,14 @@ func NewLogger(logType LogType, cfg *LoggingConfig) *zap.SugaredLogger { encoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder encoderConfig.EncodeLevel = zapcore.CapitalLevelEncoder + // notice: can use zapLoggerEncoderConfig directly, because it would write gibberish into the file. encoder := zapcore.NewConsoleEncoder(encoderConfig) level := zap.DebugLevel if logType == MainLog { level = getLoggerLevel(cfg.LogLevel) } core := zapcore.NewCore(encoder, syncer, zap.NewAtomicLevelAt(level)) - return zap.New(core, zap.AddCaller(), zap.AddCallerSkip(1)).Sugar() + return zap.New(core, zap.AddCaller(), zap.AddCallerSkip(2)).Sugar() } //nolint:staticcheck @@ -191,7 +223,7 @@ func NewSlowLogger(logPath string, cfg *LoggingConfig) *zap.SugaredLogger { encoder := zapcore.NewConsoleEncoder(encoderConfig) core := zapcore.NewCore(encoder, syncer, zap.NewAtomicLevelAt(zap.WarnLevel)) - return zap.New(core, zap.AddCaller(), zap.AddCallerSkip(1)).Sugar() + return zap.New(core, zap.AddCaller(), zap.AddCallerSkip(2)).Sugar() } //nolint:staticcheck @@ -222,6 +254,21 @@ func buildLumberJack(logPath string, logType LogType, cfg *LoggingConfig) *lumbe } } +func NewContext(ctx context.Context, connectionID uint32, fields ...zapcore.Field) context.Context { + return context.WithValue(ctx, LoggerKey(strconv.Itoa(int(connectionID))), WithContext(connectionID, ctx).With(fields...)) +} + +func WithContext(connectionID uint32, ctx context.Context) *compositeLogger { + if ctx == nil { + return globalLogger + } + ctxLogger, ok := ctx.Value(LoggerKey(strconv.Itoa(int(connectionID)))).(*compositeLogger) + if ok { + return ctxLogger + } + return NewCompositeLogger(loggerCfg) +} + func getLoggerLevel(level int) zapcore.Level { logLevel := LogLevel(level) if logLevel < _minLevel || logLevel > _maxLevel { @@ -233,167 +280,241 @@ func getLoggerLevel(level int) zapcore.Level { func currentPath() string { dir, err := filepath.Abs(filepath.Dir(os.Args[0])) if err != nil { - mainLog.Error("can not get current path") + globalLogger.Error("can not get current path") } return dir } -// SetLogger customize yourself logger. -func SetLogger(logger Logger) { - mainLog = logger +func (c *compositeLogger) Debug(v ...interface{}) { + c.mainLog.Debug(v...) } -// GetLogger get logger -func GetLogger() Logger { - return mainLog +func (c *compositeLogger) Debugf(format string, v ...interface{}) { + c.mainLog.Debugf(format, v...) } -// Debug ... -func Debug(v ...interface{}) { - mainLog.Debug(v...) +func (c *compositeLogger) DebugfWithLogType(logType LogType, format string, v ...interface{}) { + c.mainLog.Debugf(format, v...) + switch logType { + case LogicalSqlLog: + c.logicalSqlLog.Debugf(format, v...) + case PhysicalSqlLog: + c.physicalSqlLog.Debugf(format, v...) + case TxLog: + c.txLog.Debugf(format, v...) + case MainLog: + break + } } -// Debugf ... -func Debugf(format string, v ...interface{}) { - mainLog.Debugf(format, v...) +func (c *compositeLogger) Info(v ...interface{}) { + c.mainLog.Info(v...) } -// DebugfWithLogType ... -func DebugfWithLogType(logType LogType, format string, v ...interface{}) { - mainLog.Debugf(format, v...) +func (c *compositeLogger) Infof(format string, v ...interface{}) { + c.mainLog.Infof(format, v...) +} + +func (c *compositeLogger) InfofWithLogType(logType LogType, format string, v ...interface{}) { + c.mainLog.Infof(format, v...) switch logType { case LogicalSqlLog: - logicalSqlLog.Debugf(format, v) + c.logicalSqlLog.Infof(format, v...) case PhysicalSqlLog: - physicalSqlLog.Debugf(format, v) + c.physicalSqlLog.Infof(format, v...) case TxLog: - txLog.Debugf(format, v) + c.txLog.Infof(format, v...) case MainLog: break } } -// Info ... -func Info(v ...interface{}) { - mainLog.Info(v...) +func (c *compositeLogger) Warn(v ...interface{}) { + c.mainLog.Warn(v...) } -// Infof ... -func Infof(format string, v ...interface{}) { - mainLog.Infof(format, v...) +func (c *compositeLogger) Warnf(format string, v ...interface{}) { + c.mainLog.Warnf(format, v...) } -// InfofWithLogType ... -func InfofWithLogType(logType LogType, format string, v ...interface{}) { - mainLog.Infof(format, v...) +func (c *compositeLogger) WarnfWithLogType(logType LogType, format string, v ...interface{}) { + c.mainLog.Warnf(format, v...) switch logType { case LogicalSqlLog: - logicalSqlLog.Infof(format, v) + c.logicalSqlLog.Warnf(format, v...) case PhysicalSqlLog: - physicalSqlLog.Infof(format, v) + c.physicalSqlLog.Warnf(format, v...) case TxLog: - txLog.Infof(format, v) + c.txLog.Warnf(format, v...) case MainLog: break } } -// Warn ... -func Warn(v ...interface{}) { - mainLog.Warn(v...) +func (c *compositeLogger) Error(v ...interface{}) { + c.mainLog.Error(v...) } -// Warnf ... -func Warnf(format string, v ...interface{}) { - mainLog.Warnf(format, v...) +func (c *compositeLogger) Errorf(format string, v ...interface{}) { + c.mainLog.Errorf(format, v...) } -// WarnfWithLogType ... -func WarnfWithLogType(logType LogType, format string, v ...interface{}) { - mainLog.Warnf(format, v...) +func (c *compositeLogger) ErrorfWithLogType(logType LogType, format string, v ...interface{}) { + c.mainLog.Errorf(format, v...) switch logType { case LogicalSqlLog: - logicalSqlLog.Warnf(format, v) + c.logicalSqlLog.Errorf(format, v...) case PhysicalSqlLog: - physicalSqlLog.Warnf(format, v) + c.physicalSqlLog.Errorf(format, v...) case TxLog: - txLog.Warnf(format, v) + c.txLog.Errorf(format, v...) case MainLog: break } } -// Error ... -func Error(v ...interface{}) { - mainLog.Error(v...) +func (c *compositeLogger) Panic(v ...interface{}) { + c.mainLog.Panic(v...) } -// Errorf ... -func Errorf(format string, v ...interface{}) { - mainLog.Errorf(format, v...) +func (c *compositeLogger) Panicf(format string, v ...interface{}) { + c.mainLog.Panicf(format, v...) } -// ErrorfWithLogType ... -func ErrorfWithLogType(logType LogType, format string, v ...interface{}) { - mainLog.Errorf(format, v...) +func (c *compositeLogger) PanicfWithLogType(logType LogType, format string, v ...interface{}) { + c.mainLog.Panicf(format, v...) switch logType { case LogicalSqlLog: - logicalSqlLog.Errorf(format, v) + c.logicalSqlLog.Panicf(format, v...) case PhysicalSqlLog: - physicalSqlLog.Errorf(format, v) + c.physicalSqlLog.Panicf(format, v...) case TxLog: - txLog.Errorf(format, v) + c.txLog.Panicf(format, v...) case MainLog: break } } -// Panic ... -func Panic(v ...interface{}) { - mainLog.Panic(v...) +func (c *compositeLogger) Fatal(v ...interface{}) { + c.mainLog.Fatal(v...) } -// Panicf ... -func Panicf(format string, v ...interface{}) { - mainLog.Panicf(format, v...) +func (c *compositeLogger) Fatalf(format string, v ...interface{}) { + c.mainLog.Fatalf(format, v...) } -// ErrorfWithLogType ... -func PanicfWithLogType(logType LogType, format string, v ...interface{}) { - mainLog.Panicf(format, v...) +func (c *compositeLogger) FatalfWithLogType(logType LogType, format string, v ...interface{}) { + c.mainLog.Fatalf(format, v...) switch logType { case LogicalSqlLog: - logicalSqlLog.Panicf(format, v) + c.logicalSqlLog.Fatalf(format, v...) case PhysicalSqlLog: - physicalSqlLog.Panicf(format, v) + c.physicalSqlLog.Fatalf(format, v...) case TxLog: - txLog.Panicf(format, v) + c.txLog.Fatalf(format, v...) case MainLog: break } } +func (c *compositeLogger) With(fields ...zap.Field) *compositeLogger { + args := make([]interface{}, 0, len(fields)) + for _, field := range fields { + args = append(args, field) + } + c.mainLog = c.mainLog.With(args...) + c.logicalSqlLog = c.logicalSqlLog.With(args...) + c.physicalSqlLog = c.physicalSqlLog.With(args...) + c.txLog = c.txLog.With(args...) + return c +} + +// Debug ... +func Debug(v ...interface{}) { + globalLogger.Debug(v...) +} + +// Debugf ... +func Debugf(format string, v ...interface{}) { + globalLogger.Debugf(format, v...) +} + +// DebugfWithLogType ... +func DebugfWithLogType(logType LogType, format string, v ...interface{}) { + globalLogger.DebugfWithLogType(logType, format, v) +} + +// Info ... +func Info(v ...interface{}) { + globalLogger.Info(v...) +} + +// Infof ... +func Infof(format string, v ...interface{}) { + globalLogger.Infof(format, v...) +} + +// InfofWithLogType ... +func InfofWithLogType(logType LogType, format string, v ...interface{}) { + globalLogger.InfofWithLogType(logType, format, v) +} + +// Warn ... +func Warn(v ...interface{}) { + globalLogger.Warn(v...) +} + +// Warnf ... +func Warnf(format string, v ...interface{}) { + globalLogger.Warnf(format, v...) +} + +// WarnfWithLogType ... +func WarnfWithLogType(logType LogType, format string, v ...interface{}) { + globalLogger.WarnfWithLogType(logType, format, v) +} + +// Error ... +func Error(v ...interface{}) { + globalLogger.Error(v...) +} + +// Errorf ... +func Errorf(format string, v ...interface{}) { + globalLogger.Errorf(format, v...) +} + +// ErrorfWithLogType ... +func ErrorfWithLogType(logType LogType, format string, v ...interface{}) { + globalLogger.ErrorfWithLogType(logType, format, v) +} + +// Panic ... +func Panic(v ...interface{}) { + globalLogger.Panic(v...) +} + +// Panicf ... +func Panicf(format string, v ...interface{}) { + globalLogger.Panicf(format, v...) +} + +// ErrorfWithLogType ... +func PanicfWithLogType(logType LogType, format string, v ...interface{}) { + globalLogger.PanicfWithLogType(logType, format, v) +} + // Fatal ... func Fatal(v ...interface{}) { - mainLog.Fatal(v...) + globalLogger.Fatal(v...) } // Fatalf ... func Fatalf(format string, v ...interface{}) { - mainLog.Fatalf(format, v...) + globalLogger.Fatalf(format, v...) } // FatalfWithLogType ... func FatalfWithLogType(logType LogType, format string, v ...interface{}) { - mainLog.Fatalf(format, v...) - switch logType { - case LogicalSqlLog: - logicalSqlLog.Fatalf(format, v) - case PhysicalSqlLog: - physicalSqlLog.Fatalf(format, v) - case TxLog: - txLog.Fatalf(format, v) - case MainLog: - break - } + globalLogger.FatalfWithLogType(logType, format, v) }