You can not select more than 25 topics
Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.
429 lines
11 KiB
429 lines
11 KiB
// Copyright 2017 PingCAP, Inc.
|
|
//
|
|
// Licensed under the Apache License, Version 2.0 (the "License");
|
|
// you may not use this file except in compliance with the License.
|
|
// You may obtain a copy of the License at
|
|
//
|
|
// http://www.apache.org/licenses/LICENSE-2.0
|
|
//
|
|
// Unless required by applicable law or agreed to in writing, software
|
|
// distributed under the License is distributed on an "AS IS" BASIS,
|
|
// See the License for the specific language governing permissions and
|
|
// limitations under the License.
|
|
|
|
package logutil
|
|
|
|
import (
|
|
"bytes"
|
|
"context"
|
|
"fmt"
|
|
"os"
|
|
"path/filepath"
|
|
"runtime"
|
|
"runtime/trace"
|
|
"sort"
|
|
"strings"
|
|
"time"
|
|
|
|
"github.com/opentracing/opentracing-go"
|
|
tlog "github.com/opentracing/opentracing-go/log"
|
|
"github.com/pingcap/errors"
|
|
zaplog "github.com/pingcap/log"
|
|
log "github.com/sirupsen/logrus"
|
|
"go.uber.org/zap"
|
|
"go.uber.org/zap/zapcore"
|
|
"gopkg.in/natefinch/lumberjack.v2"
|
|
)
|
|
|
|
const (
|
|
defaultLogTimeFormat = "2006/01/02 15:04:05.000"
|
|
// DefaultLogMaxSize is the default size of log files.
|
|
DefaultLogMaxSize = 300 // MB
|
|
// DefaultLogFormat is the default format of the log.
|
|
DefaultLogFormat = "text"
|
|
defaultLogLevel = log.InfoLevel
|
|
// DefaultSlowThreshold is the default slow log threshold in millisecond.
|
|
DefaultSlowThreshold = 300
|
|
// DefaultQueryLogMaxLen is the default max length of the query in the log.
|
|
DefaultQueryLogMaxLen = 4096
|
|
// DefaultRecordPlanInSlowLog is the default value for whether enable log query plan in the slow log.
|
|
DefaultRecordPlanInSlowLog = 1
|
|
// DefaultTiDBEnableSlowLog enables TiDB to log slow queries.
|
|
DefaultTiDBEnableSlowLog = true
|
|
)
|
|
|
|
// EmptyFileLogConfig is an empty FileLogConfig.
|
|
var EmptyFileLogConfig = FileLogConfig{}
|
|
|
|
// FileLogConfig serializes file log related config in toml/json.
|
|
type FileLogConfig struct {
|
|
zaplog.FileLogConfig
|
|
}
|
|
|
|
// NewFileLogConfig creates a FileLogConfig.
|
|
func NewFileLogConfig(maxSize uint) FileLogConfig {
|
|
return FileLogConfig{FileLogConfig: zaplog.FileLogConfig{
|
|
MaxSize: int(maxSize),
|
|
},
|
|
}
|
|
}
|
|
|
|
// LogConfig serializes log related config in toml/json.
|
|
type LogConfig struct {
|
|
zaplog.Config
|
|
|
|
// SlowQueryFile filename, default to File log config on empty.
|
|
SlowQueryFile string
|
|
}
|
|
|
|
// NewLogConfig creates a LogConfig.
|
|
func NewLogConfig(level, format, slowQueryFile string, fileCfg FileLogConfig, disableTimestamp bool, opts ...func(*zaplog.Config)) *LogConfig {
|
|
c := &LogConfig{
|
|
Config: zaplog.Config{
|
|
Level: level,
|
|
Format: format,
|
|
DisableTimestamp: disableTimestamp,
|
|
File: fileCfg.FileLogConfig,
|
|
},
|
|
SlowQueryFile: slowQueryFile,
|
|
}
|
|
for _, opt := range opts {
|
|
opt(&c.Config)
|
|
}
|
|
return c
|
|
}
|
|
|
|
// isSKippedPackageName tests wether path name is on log library calling stack.
|
|
func isSkippedPackageName(name string) bool {
|
|
return strings.Contains(name, "github.com/sirupsen/logrus") ||
|
|
strings.Contains(name, "github.com/coreos/pkg/capnslog")
|
|
}
|
|
|
|
// modifyHook injects file name and line pos into log entry.
|
|
type contextHook struct{}
|
|
|
|
// Fire implements logrus.Hook interface
|
|
// https://github.com/sirupsen/logrus/issues/63
|
|
func (hook *contextHook) Fire(entry *log.Entry) error {
|
|
pc := make([]uintptr, 4)
|
|
cnt := runtime.Callers(8, pc)
|
|
|
|
for i := 0; i < cnt; i++ {
|
|
fu := runtime.FuncForPC(pc[i] - 1)
|
|
name := fu.Name()
|
|
if !isSkippedPackageName(name) {
|
|
file, line := fu.FileLine(pc[i] - 1)
|
|
entry.Data["file"] = filepath.Base(file)
|
|
entry.Data["line"] = line
|
|
break
|
|
}
|
|
}
|
|
return nil
|
|
}
|
|
|
|
// Levels implements logrus.Hook interface.
|
|
func (hook *contextHook) Levels() []log.Level {
|
|
return log.AllLevels
|
|
}
|
|
|
|
func stringToLogLevel(level string) log.Level {
|
|
switch strings.ToLower(level) {
|
|
case "fatal":
|
|
return log.FatalLevel
|
|
case "error":
|
|
return log.ErrorLevel
|
|
case "warn", "warning":
|
|
return log.WarnLevel
|
|
case "debug":
|
|
return log.DebugLevel
|
|
case "info":
|
|
return log.InfoLevel
|
|
}
|
|
return defaultLogLevel
|
|
}
|
|
|
|
// textFormatter is for compatibility with ngaut/log
|
|
type textFormatter struct {
|
|
DisableTimestamp bool
|
|
EnableEntryOrder bool
|
|
}
|
|
|
|
// Format implements logrus.Formatter
|
|
func (f *textFormatter) Format(entry *log.Entry) ([]byte, error) {
|
|
var b *bytes.Buffer
|
|
if entry.Buffer != nil {
|
|
b = entry.Buffer
|
|
} else {
|
|
b = &bytes.Buffer{}
|
|
}
|
|
|
|
if !f.DisableTimestamp {
|
|
fmt.Fprintf(b, "%s ", entry.Time.Format(defaultLogTimeFormat))
|
|
}
|
|
if file, ok := entry.Data["file"]; ok {
|
|
fmt.Fprintf(b, "%s:%v:", file, entry.Data["line"])
|
|
}
|
|
fmt.Fprintf(b, " [%s] %s", entry.Level.String(), entry.Message)
|
|
|
|
if f.EnableEntryOrder {
|
|
keys := make([]string, 0, len(entry.Data))
|
|
for k := range entry.Data {
|
|
if k != "file" && k != "line" {
|
|
keys = append(keys, k)
|
|
}
|
|
}
|
|
sort.Strings(keys)
|
|
for _, k := range keys {
|
|
fmt.Fprintf(b, " %v=%v", k, entry.Data[k])
|
|
}
|
|
} else {
|
|
for k, v := range entry.Data {
|
|
if k != "file" && k != "line" {
|
|
fmt.Fprintf(b, " %v=%v", k, v)
|
|
}
|
|
}
|
|
}
|
|
|
|
b.WriteByte('\n')
|
|
|
|
return b.Bytes(), nil
|
|
}
|
|
|
|
const (
|
|
// SlowLogTimeFormat is the time format for slow log.
|
|
SlowLogTimeFormat = time.RFC3339Nano
|
|
// OldSlowLogTimeFormat is the first version of the the time format for slow log, This is use for compatibility.
|
|
OldSlowLogTimeFormat = "2006-01-02-15:04:05.999999999 -0700"
|
|
)
|
|
|
|
type slowLogFormatter struct{}
|
|
|
|
func (f *slowLogFormatter) Format(entry *log.Entry) ([]byte, error) {
|
|
var b *bytes.Buffer
|
|
if entry.Buffer != nil {
|
|
b = entry.Buffer
|
|
} else {
|
|
b = &bytes.Buffer{}
|
|
}
|
|
|
|
fmt.Fprintf(b, "# Time: %s\n", entry.Time.Format(SlowLogTimeFormat))
|
|
fmt.Fprintf(b, "%s\n", entry.Message)
|
|
return b.Bytes(), nil
|
|
}
|
|
|
|
func stringToLogFormatter(format string, disableTimestamp bool) log.Formatter {
|
|
switch strings.ToLower(format) {
|
|
case "text":
|
|
return &textFormatter{
|
|
DisableTimestamp: disableTimestamp,
|
|
}
|
|
default:
|
|
return &textFormatter{}
|
|
}
|
|
}
|
|
|
|
// initFileLog initializes file based logging options.
|
|
func initFileLog(cfg *zaplog.FileLogConfig, logger *log.Logger) error {
|
|
if st, err := os.Stat(cfg.Filename); err == nil {
|
|
if st.IsDir() {
|
|
return errors.New("can't use directory as log file name")
|
|
}
|
|
}
|
|
if cfg.MaxSize == 0 {
|
|
cfg.MaxSize = DefaultLogMaxSize
|
|
}
|
|
|
|
// use lumberjack to logrotate
|
|
output := &lumberjack.Logger{
|
|
Filename: cfg.Filename,
|
|
MaxSize: int(cfg.MaxSize),
|
|
MaxBackups: int(cfg.MaxBackups),
|
|
MaxAge: int(cfg.MaxDays),
|
|
LocalTime: true,
|
|
}
|
|
|
|
if logger == nil {
|
|
log.SetOutput(output)
|
|
} else {
|
|
logger.Out = output
|
|
}
|
|
return nil
|
|
}
|
|
|
|
// SlowQueryLogger is used to log slow query, InitLogger will modify it according to config file.
|
|
var SlowQueryLogger = log.StandardLogger()
|
|
|
|
// SlowQueryZapLogger is used to log slow query, InitZapLogger will modify it according to config file.
|
|
var SlowQueryZapLogger = zaplog.L()
|
|
|
|
// InitLogger initializes PD's logger.
|
|
func InitLogger(cfg *LogConfig) error {
|
|
log.SetLevel(stringToLogLevel(cfg.Level))
|
|
log.AddHook(&contextHook{})
|
|
|
|
if cfg.Format == "" {
|
|
cfg.Format = DefaultLogFormat
|
|
}
|
|
formatter := stringToLogFormatter(cfg.Format, cfg.DisableTimestamp)
|
|
log.SetFormatter(formatter)
|
|
|
|
if len(cfg.File.Filename) != 0 {
|
|
if err := initFileLog(&cfg.File, nil); err != nil {
|
|
return errors.Trace(err)
|
|
}
|
|
}
|
|
|
|
if len(cfg.SlowQueryFile) != 0 {
|
|
SlowQueryLogger = log.New()
|
|
tmp := cfg.File
|
|
tmp.Filename = cfg.SlowQueryFile
|
|
if err := initFileLog(&tmp, SlowQueryLogger); err != nil {
|
|
return errors.Trace(err)
|
|
}
|
|
SlowQueryLogger.Formatter = &slowLogFormatter{}
|
|
}
|
|
|
|
return nil
|
|
}
|
|
|
|
// InitZapLogger initializes a zap logger with cfg.
|
|
func InitZapLogger(cfg *LogConfig) error {
|
|
gl, props, err := zaplog.InitLogger(&cfg.Config, zap.AddStacktrace(zapcore.FatalLevel))
|
|
if err != nil {
|
|
return errors.Trace(err)
|
|
}
|
|
zaplog.ReplaceGlobals(gl, props)
|
|
|
|
if len(cfg.SlowQueryFile) != 0 {
|
|
sqfCfg := zaplog.FileLogConfig{
|
|
MaxSize: cfg.File.MaxSize,
|
|
Filename: cfg.SlowQueryFile,
|
|
}
|
|
sqCfg := &zaplog.Config{
|
|
Level: cfg.Level,
|
|
Format: cfg.Format,
|
|
DisableTimestamp: cfg.DisableTimestamp,
|
|
File: sqfCfg,
|
|
}
|
|
sqLogger, _, err := zaplog.InitLogger(sqCfg)
|
|
if err != nil {
|
|
return errors.Trace(err)
|
|
}
|
|
SlowQueryZapLogger = sqLogger
|
|
} else {
|
|
SlowQueryZapLogger = gl
|
|
}
|
|
|
|
return nil
|
|
}
|
|
|
|
// SetLevel sets the zap logger's level.
|
|
func SetLevel(level string) error {
|
|
l := zap.NewAtomicLevel()
|
|
if err := l.UnmarshalText([]byte(level)); err != nil {
|
|
return errors.Trace(err)
|
|
}
|
|
zaplog.SetLevel(l.Level())
|
|
return nil
|
|
}
|
|
|
|
type ctxLogKeyType struct{}
|
|
|
|
var ctxLogKey = ctxLogKeyType{}
|
|
|
|
// Logger gets a contextual logger from current context.
|
|
// contextual logger will output common fields from context.
|
|
func Logger(ctx context.Context) *zap.Logger {
|
|
if ctxlogger, ok := ctx.Value(ctxLogKey).(*zap.Logger); ok {
|
|
return ctxlogger
|
|
}
|
|
return zaplog.L()
|
|
}
|
|
|
|
// BgLogger is alias of `logutil.BgLogger()`
|
|
func BgLogger() *zap.Logger {
|
|
return zaplog.L()
|
|
}
|
|
|
|
// WithConnID attaches connId to context.
|
|
func WithConnID(ctx context.Context, connID uint32) context.Context {
|
|
var logger *zap.Logger
|
|
if ctxLogger, ok := ctx.Value(ctxLogKey).(*zap.Logger); ok {
|
|
logger = ctxLogger
|
|
} else {
|
|
logger = zaplog.L()
|
|
}
|
|
return context.WithValue(ctx, ctxLogKey, logger.With(zap.Uint32("conn", connID)))
|
|
}
|
|
|
|
// WithTraceLogger attaches trace identifier to context
|
|
func WithTraceLogger(ctx context.Context, connID uint32) context.Context {
|
|
var logger *zap.Logger
|
|
if ctxLogger, ok := ctx.Value(ctxLogKey).(*zap.Logger); ok {
|
|
logger = ctxLogger
|
|
} else {
|
|
logger = zaplog.L()
|
|
}
|
|
return context.WithValue(ctx, ctxLogKey, wrapTraceLogger(ctx, connID, logger))
|
|
}
|
|
|
|
func wrapTraceLogger(ctx context.Context, connID uint32, logger *zap.Logger) *zap.Logger {
|
|
return logger.WithOptions(zap.WrapCore(func(core zapcore.Core) zapcore.Core {
|
|
tl := &traceLog{ctx: ctx}
|
|
traceCore := zaplog.NewTextCore(zaplog.NewTextEncoder(&zaplog.Config{}), tl, tl).
|
|
With([]zapcore.Field{zap.Uint32("conn", connID)})
|
|
return zapcore.NewTee(traceCore, core)
|
|
}))
|
|
}
|
|
|
|
type traceLog struct {
|
|
ctx context.Context
|
|
}
|
|
|
|
func (t *traceLog) Enabled(_ zapcore.Level) bool {
|
|
return true
|
|
}
|
|
|
|
func (t *traceLog) Write(p []byte) (n int, err error) {
|
|
trace.Log(t.ctx, "log", string(p))
|
|
return len(p), nil
|
|
}
|
|
|
|
func (t *traceLog) Sync() error {
|
|
return nil
|
|
}
|
|
|
|
// WithKeyValue attaches key/value to context.
|
|
func WithKeyValue(ctx context.Context, key, value string) context.Context {
|
|
var logger *zap.Logger
|
|
if ctxLogger, ok := ctx.Value(ctxLogKey).(*zap.Logger); ok {
|
|
logger = ctxLogger
|
|
} else {
|
|
logger = zaplog.L()
|
|
}
|
|
return context.WithValue(ctx, ctxLogKey, logger.With(zap.String(key, value)))
|
|
}
|
|
|
|
// TraceEventKey presents the TraceEventKey in span log.
|
|
const TraceEventKey = "event"
|
|
|
|
// Event records event in current tracing span.
|
|
func Event(ctx context.Context, event string) {
|
|
if span := opentracing.SpanFromContext(ctx); span != nil && span.Tracer() != nil {
|
|
span.LogFields(tlog.String(TraceEventKey, event))
|
|
}
|
|
}
|
|
|
|
// Eventf records event in current tracing span with format support.
|
|
func Eventf(ctx context.Context, format string, args ...interface{}) {
|
|
if span := opentracing.SpanFromContext(ctx); span != nil && span.Tracer() != nil {
|
|
span.LogFields(tlog.String(TraceEventKey, fmt.Sprintf(format, args...)))
|
|
}
|
|
}
|
|
|
|
// SetTag sets tag kv-pair in current tracing span
|
|
func SetTag(ctx context.Context, key string, value interface{}) {
|
|
if span := opentracing.SpanFromContext(ctx); span != nil && span.Tracer() != nil {
|
|
span.SetTag(key, value)
|
|
}
|
|
}
|
|
|