GO Logger 日誌實踐

這是一個建立於 的文章，其中的資訊可能已經有所發展或是發生改變。

分析一下用過的列印日誌的log包

1. Go標準庫內建log, 這個log的func比較少, 沒有區分level, 但足夠簡單, 有prefix功能, 可以設定flag來控制時間格式, caller的檔案名稱和行數, 其它的標準包如 net/http database/sql 等也用了此包.
2. 對內建的log進行封裝, 加入level, 顏色. 如ngaut/log, 這個log star數並不多, 還是從最近很火的一個項目pingcap/tidb裡看到的, 有點小清新的感覺, 但這個log可能只是為tidb使用的, 缺少內建log的一些方法, 導致沒法使用在一些可以定製logger的第三方庫如gorm中. 於是我fork了一下https://github.com/hanjm/log, 增加了一些方法, 以便可以給gorm用.
3. 完全自己實現的log, 結構化輸出, 通常是key=value或json, 有名的有logrus, zap等. 第一次看到logrus感覺美極了, 於是大量使用, 直到在關注tidb的時候收到帶日誌的issues郵件, 裡面的日誌帶了caller, 感覺很有用, 於是去搜logrus的issue看有沒有這個功能, 搜到了一個issuehttps://github.com/sirupsen/logrus/issues/63, 討論了三年這個功能還沒加上, 只好放棄美麗的logrus, 找到了替代品zap, zap的設計非常好, 定製性強. log是經常調用的代碼, 每次調用不可避免地要進行記憶體配置, 分配次數和每次分配的記憶體大小將影響效能. 對log內容的處理也是一個涉及到效能的點, 像log.Printf參數是interface{}, logrus的field是map[stirng]interface{}, 列印interface{}只能靠reflect, Go是靜態強型別語言, 用反射的開銷比較大, 所以zap使用了手動指定類型的方式, 從zap提供的benchmark上開看, 效能提升還是蠻大的, 雖然相比logrus使用起來更麻煩, 但為了效能, 還是值得的.

總結

1. 為了方便進行日誌分析, 統一用json行日誌, 這樣用elk時可以免去定製Regex儲存到elasticSearch的field中.
2. net/http database/sql 及一些第三方包可能直接使用了標註庫的log, 有個trick可以改變所有使用標準包log的行為, 通過log.SetOutput(w io.Writer)來改變位置, w是一個實現了Write(p []byte) (n int, err error)方法的io.Writer即可.
3. runtime.Caller可以得到調用者的pc, 檔案名稱, 檔案行數, runtime.FuncForPC(pc).Name()可以得到pc所在的函數名, 對於debug非常有協助. 但有一定效能開銷, 所以方案是: 對於http server的access log, 沒有必要使用帶caller的日誌, 而對於http api具體實現的函數內的log, 有必要記錄caller, 而且光有檔案名稱和行數還不夠, 畢竟改了程式碼數就變了, 而函數名一般不會變, 帶上函數名會更直觀.
4. GitHub搜了一圈, 好多公司都會定製自己的log, 如tidb的ngaut/log, 七牛的qiniu/log, 餓了麼的eleme/log, mailgun的mailgun/log, 是的, 我也造一個小輪子zaplog.zaplog是封裝了zap, 帶caller func name, 相容logrus stdlog 的日誌輸出工具.

package zaplogimport ("bytes""fmt""go.uber.org/zap""go.uber.org/zap/zapcore""log""runtime""strings")// CallerEncoder will add caller to log. format is "filename:lineNum:funcName", e.g:"zaplog/zaplog_test.go:15:zaplog.TestNewLogger"func CallerEncoder(caller zapcore.EntryCaller, enc zapcore.PrimitiveArrayEncoder) {enc.AppendString(strings.Join([]string{caller.TrimmedPath(), runtime.FuncForPC(caller.PC).Name()}, ":"))}func newLoggerConfig(debugLevel bool) (loggerConfig zap.Config) {loggerConfig = zap.NewProductionConfig()loggerConfig.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoderloggerConfig.EncoderConfig.EncodeCaller = CallerEncoderif debugLevel {loggerConfig.Level = zap.NewAtomicLevelAt(zap.DebugLevel)}return}// NewCustomLoggers is a shortcut to get normal logger, noCallerLogger.func NewCustomLoggers(debugLevel bool) (logger, noCallerLogger *zap.Logger) {loggerConfig := newLoggerConfig(debugLevel)logger, err := loggerConfig.Build()if err != nil {panic(err)}loggerConfig.DisableCaller = truenoCallerLogger, err = loggerConfig.Build()if err != nil {panic(err)}return}// NewLogger return a normal loggerfunc NewLogger(debugLevel bool) (logger *zap.Logger) {loggerConfig := newLoggerConfig(debugLevel)logger, err := loggerConfig.Build()if err != nil {panic(err)}return}// NewNoCallerLogger return a no caller key value, will be fasterfunc NewNoCallerLogger(debugLevel bool) (noCallerLogger *zap.Logger) {loggerConfig := newLoggerConfig(debugLevel)loggerConfig.DisableCaller = truenoCallerLogger, err := loggerConfig.Build()if err != nil {panic(err)}return}// CompatibleLogger is a logger which compatible to logrus/std log/prometheus.// it implements Print() Println() Printf() Dbug() Debugln() Debugf() Info() Infoln() Infof() Warn() Warnln() Warnf()// Error() Errorln() Errorf() Fatal() Fataln() Fatalf() Panic() Panicln() Panicf() With() WithField() WithFields()type CompatibleLogger struct {_log *zap.Logger}// NewCompatibleLogger return CompatibleLogger with caller fieldfunc NewCompatibleLogger(debugLevel bool) *CompatibleLogger {return &CompatibleLogger{NewLogger(debugLevel).WithOptions(zap.AddCallerSkip(1))}}// Print logs a message at level Info on the compatibleLogger.func (l CompatibleLogger) Print(args ...interface{}) {l._log.Info(fmt.Sprint(args...))}// Println logs a message at level Info on the compatibleLogger.func (l CompatibleLogger) Println(args ...interface{}) {l._log.Info(fmt.Sprint(args...))}// Printf logs a message at level Info on the compatibleLogger.func (l CompatibleLogger) Printf(format string, args ...interface{}) {l._log.Info(fmt.Sprintf(format, args...))}// Debug logs a message at level Debug on the compatibleLogger.func (l CompatibleLogger) Debug(args ...interface{}) {l._log.Debug(fmt.Sprint(args...))}// Debugln logs a message at level Debug on the compatibleLogger.func (l CompatibleLogger) Debugln(args ...interface{}) {l._log.Debug(fmt.Sprint(args...))}// Debugf logs a message at level Debug on the compatibleLogger.func (l CompatibleLogger) Debugf(format string, args ...interface{}) {l._log.Debug(fmt.Sprintf(format, args...))}// Info logs a message at level Info on the compatibleLogger.func (l CompatibleLogger) Info(args ...interface{}) {l._log.Info(fmt.Sprint(args...))}// Infoln logs a message at level Info on the compatibleLogger.func (l CompatibleLogger) Infoln(args ...interface{}) {l._log.Info(fmt.Sprint(args...))}// Infof logs a message at level Info on the compatibleLogger.func (l CompatibleLogger) Infof(format string, args ...interface{}) {l._log.Info(fmt.Sprintf(format, args...))}// Warn logs a message at level Warn on the compatibleLogger.func (l CompatibleLogger) Warn(args ...interface{}) {l._log.Warn(fmt.Sprint(args...))}// Warnln logs a message at level Warn on the compatibleLogger.func (l CompatibleLogger) Warnln(args ...interface{}) {l._log.Warn(fmt.Sprint(args...))}// Warnf logs a message at level Warn on the compatibleLogger.func (l CompatibleLogger) Warnf(format string, args ...interface{}) {l._log.Warn(fmt.Sprintf(format, args...))}// Error logs a message at level Error on the compatibleLogger.func (l CompatibleLogger) Error(args ...interface{}) {l._log.Error(fmt.Sprint(args...))}// Errorln logs a message at level Error on the compatibleLogger.func (l CompatibleLogger) Errorln(args ...interface{}) {l._log.Error(fmt.Sprint(args...))}// Errorf logs a message at level Error on the compatibleLogger.func (l CompatibleLogger) Errorf(format string, args ...interface{}) {l._log.Error(fmt.Sprintf(format, args...))}// Fatal logs a message at level Fatal on the compatibleLogger.func (l CompatibleLogger) Fatal(args ...interface{}) {l._log.Fatal(fmt.Sprint(args...))}// Fatalln logs a message at level Fatal on the compatibleLogger.func (l CompatibleLogger) Fatalln(args ...interface{}) {l._log.Fatal(fmt.Sprint(args...))}// Fatalf logs a message at level Fatal on the compatibleLogger.func (l CompatibleLogger) Fatalf(format string, args ...interface{}) {l._log.Fatal(fmt.Sprintf(format, args...))}// Panic logs a message at level Painc on the compatibleLogger.func (l CompatibleLogger) Panic(args ...interface{}) {l._log.Panic(fmt.Sprint(args...))}// Panicln logs a message at level Painc on the compatibleLogger.func (l CompatibleLogger) Panicln(args ...interface{}) {l._log.Panic(fmt.Sprint(args...))}// Panicf logs a message at level Painc on the compatibleLogger.func (l CompatibleLogger) Panicf(format string, args ...interface{}) {l._log.Panic(fmt.Sprintf(format, args...))}// With return a logger with an extra field.func (l *CompatibleLogger) With(key string, value interface{}) *CompatibleLogger {return &CompatibleLogger{l._log.With(zap.Any(key, value))}}// WithField return a logger with an extra field.func (l *CompatibleLogger) WithField(key string, value interface{}) *CompatibleLogger {return &CompatibleLogger{l._log.With(zap.Any(key, value))}}// WithFields return a logger with extra fields.func (l *CompatibleLogger) WithFields(fields map[string]interface{}) *CompatibleLogger {i := 0var clog *CompatibleLoggerfor k, v := range fields {if i == 0 {clog = l.WithField(k, v)} else {clog = clog.WithField(k, v)}i++}return clog}// FormatStdLog set the output of stand package log to zaplogfunc FormatStdLog() {log.SetFlags(log.Llongfile)log.SetOutput(&logWriter{NewNoCallerLogger(false)})}type logWriter struct {logger *zap.Logger}// Write implement io.Writer, as std log's outputfunc (w logWriter) Write(p []byte) (n int, err error) {i := bytes.Index(p, []byte(":")) + 1j := bytes.Index(p[i:], []byte(":")) + 1 + icaller := bytes.TrimRight(p[:j], ":")// find last index of /i = bytes.LastIndex(caller, []byte("/"))// find penultimate index of /i = bytes.LastIndex(caller[:i], []byte("/"))w.logger.Info("stdLog", zap.ByteString("caller", caller[i+1:]), zap.ByteString("log", bytes.TrimSpace(p[j:])))return len(p), nil}