Logging refactoring: define interface and migrate existing tags and t…

…ag values (cadence-workflow#1618) * define interface * define static tagValues * Define all tags * fix comment * fix comment * fix comment * fix comment * enforce type for helper functions * fix name * Address comments * strongly type all tag values * stash * define interface and migrate tag/tagValues * add call at * refactor * remove unused * Implement logger * add throttle logger * add throttle logger * add copyright * fix lint warninig * fix comment * unit test * fix unit test * fix test * fix xdc- * address comments * address comments * address comments(value names * remove unsed value type defs * address comments * add bench test * fix copyright * fix lint * fix import * fix
MartinGomes · Apr 12, 2019 · e1eae28 · e1eae28
1 parent 6c03362
commit e1eae28
Show file tree

Hide file tree

Showing 7 changed files with 1,262 additions and 0 deletions.
diff --git a/common/log/logger.go b/common/log/logger.go
@@ -0,0 +1,129 @@
+// Copyright (c) 2017 Uber Technologies, Inc.
+//
+// Permission is hereby granted, free of charge, to any person obtaining a copy
+// of this software and associated documentation files (the "Software"), to deal
+// in the Software without restriction, including without limitation the rights
+// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+// copies of the Software, and to permit persons to whom the Software is
+// furnished to do so, subject to the following conditions:
+//
+// The above copyright notice and this permission notice shall be included in
+// all copies or substantial portions of the Software.
+//
+// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+// THE SOFTWARE.
+
+package log
+
+import (
+	"fmt"
+	"path/filepath"
+	"runtime"
+
+	"github.com/uber/cadence/common/log/tag"
+	"go.uber.org/zap"
+)
+
+// Logger is our abstraction for logging
+// Usage examples:
+//  import "github.com/uber/cadence/common/log/tag"
+//  1) logger = logger.WithTags(
+//          tag.WorkflowNextEventID( 123),
+//          tag.WorkflowActionWorkflowStarted,
+//          tag.WorkflowDomainID("test-domain-id"))
+//     logger.Info("hello world")
+//  2) logger.Info("hello world",
+//          tag.WorkflowNextEventID( 123),
+//          tag.WorkflowActionWorkflowStarted,
+//          tag.WorkflowDomainID("test-domain-id"))
+//	   )
+//  Note: msg should be static, it is not recommended to use fmt.Sprintf() for msg.
+//        Anything dynamic should be tagged.
+type Logger interface {
+	Debug(msg string, tags ...tag.Tag)
+	Info(msg string, tags ...tag.Tag)
+	Warn(msg string, tags ...tag.Tag)
+	Error(msg string, tags ...tag.Tag)
+	Fatal(msg string, tags ...tag.Tag)
+	WithTags(tags ...tag.Tag) Logger
+}
+
+type loggerImpl struct {
+	zapLogger *zap.Logger
+	skip      int
+}
+
+var _ Logger = (*loggerImpl)(nil)
+
+const skipForDefaultLogger = 3
+
+// NewLogger returns a new logger
+func NewLogger(zapLogger *zap.Logger) Logger {
+	return &loggerImpl{
+		zapLogger: zapLogger,
+		skip:      skipForDefaultLogger,
+	}
+}
+
+func caller(skip int) string {
+	_, path, lineno, ok := runtime.Caller(skip)
+	if !ok {
+		return ""
+	}
+	return fmt.Sprintf("%v:%v", filepath.Base(path), lineno)
+}
+
+func (lg *loggerImpl) buildFieldsWithCallat(tags []tag.Tag) []zap.Field {
+	fs := lg.buildFields(tags)
+	fs = append(fs, zap.String(tag.LoggingCallAtKey, caller(lg.skip)))
+	return fs
+}
+
+func (lg *loggerImpl) buildFields(tags []tag.Tag) []zap.Field {
+	fs := make([]zap.Field, 0, len(tags))
+	for _, t := range tags {
+		f := t.Field()
+		if f.Key == "" {
+			// ignore empty field(which can be constructed manually)
+			continue
+		}
+		fs = append(fs, f)
+	}
+	return fs
+}
+
+func (lg *loggerImpl) Debug(msg string, tags ...tag.Tag) {
+	fields := lg.buildFieldsWithCallat(tags)
+	lg.zapLogger.Debug(msg, fields...)
+}
+
+func (lg *loggerImpl) Info(msg string, tags ...tag.Tag) {
+	fields := lg.buildFieldsWithCallat(tags)
+	lg.zapLogger.Info(msg, fields...)
+}
+
+func (lg *loggerImpl) Warn(msg string, tags ...tag.Tag) {
+	fields := lg.buildFieldsWithCallat(tags)
+	lg.zapLogger.Warn(msg, fields...)
+}
+
+func (lg *loggerImpl) Error(msg string, tags ...tag.Tag) {
+	fields := lg.buildFieldsWithCallat(tags)
+	lg.zapLogger.Error(msg, fields...)
+}
+
+func (lg *loggerImpl) Fatal(msg string, tags ...tag.Tag) {
+	fields := lg.buildFieldsWithCallat(tags)
+	lg.zapLogger.Fatal(msg, fields...)
+}
+
+func (lg *loggerImpl) WithTags(tags ...tag.Tag) Logger {
+	fields := lg.buildFields(tags)
+	zapLogger := lg.zapLogger.With(fields...)
+	return NewLogger(zapLogger)
+}
diff --git a/common/log/logger_bench_test.go b/common/log/logger_bench_test.go
@@ -0,0 +1,139 @@
+// Copyright (c) 2017 Uber Technologies, Inc.
+//
+// Permission is hereby granted, free of charge, to any person obtaining a copy
+// of this software and associated documentation files (the "Software"), to deal
+// in the Software without restriction, including without limitation the rights
+// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+// copies of the Software, and to permit persons to whom the Software is
+// furnished to do so, subject to the following conditions:
+//
+// The above copyright notice and this permission notice shall be included in
+// all copies or substantial portions of the Software.
+//
+// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+// THE SOFTWARE.
+package log
+
+import (
+	"testing"
+
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+
+	"github.com/uber/cadence/common/log/tag"
+)
+
+/**
+longer@~/gocode/src/github.com/uber/cadence/common/log:(log)$ go test -v -bench=. | egrep "(Bench)|(ns/op)"
+BenchmarkZapLoggerWithFields-8      	{"level":"info","ts":1555094254.794006,"caller":"log/logger_bench_test.go:21","msg":"msg to print log, 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890","wf-schedule-id":0,"cluster-name":"this is a very long value: 1234567890 1234567890 1234567890 1234567890","wf-domain-name":"test-domain-name"}
+  200000	      8609 ns/op
+BenchmarkLoggerWithFields-8         	{"level":"info","ts":1555094256.608516,"msg":"msg to print log, 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890","wf-schedule-id":0,"cluster-name":"this is a very long value: 1234567890 1234567890 1234567890 1234567890","wf-domain-name":"test-domain-name","logging-call-at":"logger_bench_test.go:36"}
+  200000	      8773 ns/op
+BenchmarkZapLoggerWithoutFields-8   	{"level":"info","ts":1555094258.4521542,"caller":"log/logger_bench_test.go:49","msg":"msg to print log, 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890","wf-schedule-id":0,"cluster-name":"this is a very long value: 1234567890 1234567890 1234567890 1234567890","wf-domain-name":"test-domain-name"}
+  200000	      8535 ns/op
+BenchmarkLoggerWithoutFields-8      	{"level":"info","ts":1555094260.2499342,"msg":"msg to print log, 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890","wf-domain-name":"test-domain-name","wf-schedule-id":0,"cluster-name":"this is a very long value: 1234567890 1234567890 1234567890 1234567890","logging-call-at":"logger_bench_test.go:64"}
+  200000	      8998 ns/op
+*/
+
+func BenchmarkZapLoggerWithFields(b *testing.B) {
+	zapLogger, err := buildZapLoggerForZap()
+	if err != nil {
+		b.Fail()
+	}
+
+	for i := 0; i < b.N; i++ {
+		lg := zapLogger.With(zap.Int64("wf-schedule-id", int64(i)), zap.String("cluster-name", "this is a very long value: 1234567890 1234567890 1234567890 1234567890"))
+		lg.Info("msg to print log, 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890",
+			zap.String("wf-domain-name", "test-domain-name"))
+	}
+
+}
+
+func BenchmarkLoggerWithFields(b *testing.B) {
+	zapLogger, err := buildZapLoggerForDefault()
+	if err != nil {
+		b.Fail()
+	}
+	logger := NewLogger(zapLogger)
+
+	for i := 0; i < b.N; i++ {
+		lg := logger.WithTags(tag.WorkflowScheduleID(int64(i)), tag.ClusterName("this is a very long value: 1234567890 1234567890 1234567890 1234567890"))
+		lg.Info("msg to print log, 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890",
+			tag.WorkflowDomainName("test-domain-name"))
+	}
+
+}
+
+func BenchmarkZapLoggerWithoutFields(b *testing.B) {
+	zapLogger, err := buildZapLoggerForZap()
+	if err != nil {
+		b.Fail()
+	}
+
+	for i := 0; i < b.N; i++ {
+		zapLogger.Info("msg to print log, 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890",
+			zap.Int64("wf-schedule-id", int64(i)), zap.String("cluster-name", "this is a very long value: 1234567890 1234567890 1234567890 1234567890"),
+			zap.String("wf-domain-name", "test-domain-name"))
+	}
+
+}
+
+func BenchmarkLoggerWithoutFields(b *testing.B) {
+	zapLogger, err := buildZapLoggerForDefault()
+	if err != nil {
+		b.Fail()
+	}
+	logger := NewLogger(zapLogger)
+
+	for i := 0; i < b.N; i++ {
+		logger.Info("msg to print log, 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890 1234567890",
+			tag.WorkflowDomainName("test-domain-name"),
+			tag.WorkflowScheduleID(int64(i)), tag.ClusterName("this is a very long value: 1234567890 1234567890 1234567890 1234567890"))
+	}
+}
+
+func buildZapLoggerForZap() (*zap.Logger, error) {
+	encConfig := zap.NewProductionEncoderConfig()
+	cfg := zap.Config{
+		Level:            zap.NewAtomicLevelAt(zap.InfoLevel),
+		Development:      false,
+		Sampling:         nil,
+		Encoding:         "json",
+		EncoderConfig:    encConfig,
+		OutputPaths:      []string{"stderr"},
+		ErrorOutputPaths: []string{"stderr"},
+	}
+	return cfg.Build()
+}
+
+// only difference here is we disable caller since we already have another one
+func buildZapLoggerForDefault() (*zap.Logger, error) {
+	encConfig := zapcore.EncoderConfig{
+		TimeKey:        "ts",
+		LevelKey:       "level",
+		NameKey:        "logger",
+		CallerKey:      "", // disable caller here since we already have another one
+		MessageKey:     "msg",
+		StacktraceKey:  "stacktrace",
+		LineEnding:     zapcore.DefaultLineEnding,
+		EncodeLevel:    zapcore.LowercaseLevelEncoder,
+		EncodeTime:     zapcore.EpochTimeEncoder,
+		EncodeDuration: zapcore.SecondsDurationEncoder,
+		EncodeCaller:   nil,
+	}
+	cfg := zap.Config{
+		Level:            zap.NewAtomicLevelAt(zap.InfoLevel),
+		Development:      false,
+		Sampling:         nil,
+		Encoding:         "json",
+		EncoderConfig:    encConfig,
+		OutputPaths:      []string{"stderr"},
+		ErrorOutputPaths: []string{"stderr"},
+	}
+	return cfg.Build()
+}
diff --git a/common/log/logger_test.go b/common/log/logger_test.go
@@ -0,0 +1,104 @@
+// Copyright (c) 2017 Uber Technologies, Inc.
+//
+// Permission is hereby granted, free of charge, to any person obtaining a copy
+// of this software and associated documentation files (the "Software"), to deal
+// in the Software without restriction, including without limitation the rights
+// to use, copy, modify, merge, publish, distribute, sublicense, and/or sell
+// copies of the Software, and to permit persons to whom the Software is
+// furnished to do so, subject to the following conditions:
+//
+// The above copyright notice and this permission notice shall be included in
+// all copies or substantial portions of the Software.
+//
+// THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR
+// IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY,
+// FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE
+// AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
+// LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
+// OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
+// THE SOFTWARE.
+
+package log
+
+import (
+	"bytes"
+	"fmt"
+	"io"
+	"os"
+	"strconv"
+	"strings"
+	"testing"
+
+	"github.com/sirupsen/logrus"
+	"github.com/stretchr/testify/assert"
+	"github.com/uber-common/bark"
+	"go.uber.org/zap"
+
+	"github.com/uber/cadence/common/log/tag"
+	"github.com/uber/cadence/common/service/dynamicconfig"
+)
+
+func TestDefaultLogger(t *testing.T) {
+	old := os.Stdout // keep backup of the real stdout
+	r, w, _ := os.Pipe()
+	os.Stdout = w
+	outC := make(chan string)
+	// copy the output in a separate goroutine so logging can't block indefinitely
+	go func() {
+		var buf bytes.Buffer
+		io.Copy(&buf, r)
+		outC <- buf.String()
+	}()
+
+	var zapLogger *zap.Logger
+	zapLogger = zap.NewExample()
+
+	logger := NewLogger(zapLogger)
+	preCaller := caller(1)
+	logger.WithTags(tag.Error(fmt.Errorf("test error"))).Info("test info", tag.WorkflowActionWorkflowStarted)
+
+	// back to normal state
+	w.Close()
+	os.Stdout = old // restoring the real stdout
+	out := <-outC
+	sps := strings.Split(preCaller, ":")
+	par, err := strconv.Atoi(sps[1])
+	assert.Nil(t, err)
+	lineNum := fmt.Sprintf("%v", par+1)
+	fmt.Println(out, lineNum)
+	assert.Equal(t, out, `{"level":"info","msg":"test info","error":"test error","wf-action":"add-workflowexecution-started-event","logging-call-at":"logger_test.go:`+lineNum+`"}`+"\n")
+
+}
+
+func TestThrottleLogger(t *testing.T) {
+	old := os.Stdout // keep backup of the real stdout
+	r, w, _ := os.Pipe()
+	os.Stdout = w
+	outC := make(chan string)
+	// copy the output in a separate goroutine so logging can't block indefinitely
+	go func() {
+		var buf bytes.Buffer
+		io.Copy(&buf, r)
+		outC <- buf.String()
+	}()
+
+	var zapLogger *zap.Logger
+	zapLogger = zap.NewExample()
+
+	dc := dynamicconfig.NewNopClient()
+	cln := dynamicconfig.NewCollection(dc, bark.NewLoggerFromLogrus(logrus.New()))
+	logger := NewThrottledLogger(zapLogger, cln.GetIntProperty(dynamicconfig.FrontendRPS, 1))
+	preCaller := caller(1)
+	logger.WithTags(tag.Error(fmt.Errorf("test error"))).Info("test info", tag.WorkflowActionWorkflowStarted)
+
+	// back to normal state
+	w.Close()
+	os.Stdout = old // restoring the real stdout
+	out := <-outC
+	sps := strings.Split(preCaller, ":")
+	par, err := strconv.Atoi(sps[1])
+	assert.Nil(t, err)
+	lineNum := fmt.Sprintf("%v", par+1)
+	fmt.Println(out, lineNum)
+	assert.Equal(t, out, `{"level":"info","msg":"test info","error":"test error","wf-action":"add-workflowexecution-started-event","logging-call-at":"logger_test.go:`+lineNum+`"}`+"\n")
+}