diff --git a/internal/log/zap/option_test.go b/internal/log/zap/option_test.go new file mode 100644 index 00000000000..fcca88bdb1a --- /dev/null +++ b/internal/log/zap/option_test.go @@ -0,0 +1,226 @@ +// +// Copyright (C) 2019-2020 Vdaas.org Vald team ( kpango, rinx, kmrmt ) +// +// 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 +// +// https://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, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// +package zap + +import ( + "reflect" + "testing" + + "github.com/vdaas/vald/internal/errors" + "github.com/vdaas/vald/internal/log/format" + "github.com/vdaas/vald/internal/log/level" + "go.uber.org/goleak" +) + +func TestWithLevel(t *testing.T) { + type T = logger + type args struct { + lv string + } + type want struct { + obj *T + } + type test struct { + name string + args args + want want + checkFunc func(want, *T) error + beforeFunc func(args) + afterFunc func(args) + } + + defaultCheckFunc := func(w want, obj *T) error { + if !reflect.DeepEqual(obj, w.obj) { + return errors.Errorf("got: \"%#v\",\n\t\t\t\twant: \"%#v\"", obj, w.obj) + } + return nil + } + + tests := []test{ + { + name: "do nothing if lv is empty string", + args: args{ + lv: "", + }, + want: want{ + obj: new(T), + }, + }, + { + name: "if lv is debug, DEBUG level will be set", + args: args{ + lv: "debug", + }, + want: want{ + obj: &T{ + level: level.DEBUG, + }, + }, + }, + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc(test.args) + } + if test.afterFunc != nil { + defer test.afterFunc(test.args) + } + + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + got := WithLevel(test.args.lv) + obj := new(T) + got(obj) + if err := test.checkFunc(test.want, obj); err != nil { + tt.Errorf("error = %v", err) + } + }) + } +} + +func TestWithFormat(t *testing.T) { + type T = logger + type args struct { + fmt string + } + type want struct { + obj *T + } + type test struct { + name string + args args + want want + checkFunc func(want, *T) error + beforeFunc func(args) + afterFunc func(args) + } + + defaultCheckFunc := func(w want, obj *T) error { + if !reflect.DeepEqual(obj, w.obj) { + return errors.Errorf("got: \"%#v\",\n\t\t\t\twant: \"%#v\"", obj, w.obj) + } + return nil + } + + tests := []test{ + { + name: "do nothing if fmt is empty string", + args: args{ + fmt: "", + }, + want: want{ + obj: new(T), + }, + }, + { + name: "if fmt is json, JSON format will be set", + args: args{ + fmt: "json", + }, + want: want{ + obj: &T{ + format: format.JSON, + }, + }, + }, + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc(test.args) + } + if test.afterFunc != nil { + defer test.afterFunc(test.args) + } + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + got := WithFormat(test.args.fmt) + obj := new(T) + got(obj) + if err := test.checkFunc(test.want, obj); err != nil { + tt.Errorf("error = %v", err) + } + }) + } +} + +func TestWithCaller(t *testing.T) { + type T = logger + type args struct { + enable bool + } + type want struct { + obj *T + } + type test struct { + name string + args args + want want + checkFunc func(want, *T) error + beforeFunc func(args) + afterFunc func(args) + } + + defaultCheckFunc := func(w want, obj *T) error { + if !reflect.DeepEqual(obj, w.obj) { + return errors.Errorf("got: \"%#v\",\n\t\t\t\twant: \"%#v\"", obj, w.obj) + } + return nil + } + + tests := []test{ + { + name: "given value will be set to enableCaller field", + args: args{ + enable: true, + }, + want: want{ + obj: &T{ + enableCaller: true, + }, + }, + }, + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc(test.args) + } + if test.afterFunc != nil { + defer test.afterFunc(test.args) + } + + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + got := WithCaller(test.args.enable) + obj := new(T) + got(obj) + if err := test.checkFunc(test.want, obj); err != nil { + tt.Errorf("error = %v", err) + } + }) + } +} diff --git a/internal/log/zap/zap.go b/internal/log/zap/zap.go index c15c0501b91..f5cd4f843e0 100644 --- a/internal/log/zap/zap.go +++ b/internal/log/zap/zap.go @@ -25,6 +25,13 @@ import ( const ( detailsKey = "details" + + defaultLevel = zapcore.DebugLevel +) + +var ( + zapcore_NewConsoleEncoder = zapcore.NewConsoleEncoder + zapcore_NewJSONEncoder = zapcore.NewJSONEncoder ) type logger struct { @@ -44,7 +51,7 @@ func New(opts ...Option) (*logger, error) { opt(l) } - err := l.initialize() + err := l.initialize("stdout", "stderr") if err != nil { return nil, err } @@ -52,19 +59,34 @@ func New(opts ...Option) (*logger, error) { return l, nil } -func (l *logger) initialize() (err error) { - cfg := zap.NewProductionConfig() - - cfg.Level.SetLevel(toZapLevel(l.level)) - cfg.Encoding = toZapEncoder(l.format) - - cfg.DisableCaller = !l.enableCaller +func (l *logger) initialize(sinkPath, errSinkPath string) (err error) { + sink, closeOut, err := zap.Open(sinkPath) + if err != nil { + return err + } - l.logger, err = cfg.Build() + errSink, _, err := zap.Open(errSinkPath) if err != nil { + closeOut() return err } + core := zapcore.NewCore( + toZapEncoder(l.format), + sink, + toZapLevel(l.level), + ) + + opts := []zap.Option{ + zap.ErrorOutput(errSink), + } + + if l.enableCaller { + opts = append(opts, zap.AddCaller()) + } + + l.logger = zap.New(core, opts...) + l.sugar = l.logger.Sugar() return nil @@ -82,19 +104,25 @@ func toZapLevel(lv level.Level) zapcore.Level { return zapcore.ErrorLevel case level.FATAL: return zapcore.FatalLevel + case level.Unknown: + fallthrough default: - return zapcore.DebugLevel + return defaultLevel } } -func toZapEncoder(fmt format.Format) string { +func toZapEncoder(fmt format.Format) zapcore.Encoder { + cfg := zap.NewDevelopmentEncoderConfig() + switch fmt { case format.RAW: - return "console" + return zapcore_NewConsoleEncoder(cfg) case format.JSON: - return "json" + return zapcore_NewJSONEncoder(cfg) + case format.Unknown: + fallthrough default: - return "json" + return zapcore_NewJSONEncoder(cfg) } } @@ -107,9 +135,12 @@ func (l *logger) log( if msg, ok := vals[0].(string); ok { if len(vals[1:]) == 1 { loggerFunc(msg, zap.Any(detailsKey, vals[1])) + return } + loggerFunc(msg, zap.Any(detailsKey, vals[1:])) + return } } diff --git a/internal/log/zap/zap_test.go b/internal/log/zap/zap_test.go new file mode 100644 index 00000000000..97436021870 --- /dev/null +++ b/internal/log/zap/zap_test.go @@ -0,0 +1,1317 @@ +// +// Copyright (C) 2019-2020 Vdaas.org Vald team ( kpango, rinx, kmrmt ) +// +// 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 +// +// https://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, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +// +package zap + +import ( + "reflect" + "testing" + + "github.com/vdaas/vald/internal/errors" + "github.com/vdaas/vald/internal/log/format" + "github.com/vdaas/vald/internal/log/level" + "go.uber.org/goleak" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" +) + +func TestNew(t *testing.T) { + type args struct { + opts []Option + } + type want struct { + want *logger + err error + } + type test struct { + name string + args args + want want + checkFunc func(want, *logger, error) error + beforeFunc func(args) + afterFunc func(args) + } + defaultCheckFunc := func(w want, got *logger, err error) error { + if !errors.Is(err, w.err) { + return errors.Errorf("got_error: \"%#v\",\n\t\t\t\twant: \"%#v\"", err, w.err) + } + if !reflect.DeepEqual(got, w.want) { + return errors.Errorf("got: \"%#v\",\n\t\t\t\twant: \"%#v\"", got, w.want) + } + return nil + } + tests := []test{ + func() test { + called := false + + return test{ + name: "return new logger instance correctly", + args: args{ + opts: []Option{ + func(l *logger) { + called = true + }, + }, + }, + want: want{ + want: &logger{}, + err: nil, + }, + checkFunc: func(w want, got *logger, err error) error { + if !called { + return errors.New("Option function is not applied") + } + + if got == nil { + return errors.New("logger is not returned") + } + + if !errors.Is(err, w.err) { + return errors.Errorf("got_error: \"%#v\",\n\t\t\t\twant: \"%#v\"", err, w.err) + } + + return nil + }, + } + }(), + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc(test.args) + } + if test.afterFunc != nil { + defer test.afterFunc(test.args) + } + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + + got, err := New(test.args.opts...) + if err := test.checkFunc(test.want, got, err); err != nil { + tt.Errorf("error = %v", err) + } + + }) + } +} + +func Test_logger_initialize(t *testing.T) { + type fields struct { + format format.Format + level level.Level + enableCaller bool + logger *zap.Logger + sugar *zap.SugaredLogger + } + type args struct { + sinkPath string + errSinkPath string + } + type want struct { + err error + } + type test struct { + name string + fields fields + args args + want want + checkFunc func(want, *logger, error) error + beforeFunc func() + afterFunc func() + } + defaultCheckFunc := func(w want, l *logger, err error) error { + if !errors.Is(err, w.err) { + return errors.Errorf("got_error: \"%#v\",\n\t\t\t\twant: \"%#v\"", err, w.err) + } + return nil + } + tests := []test{ + func() test { + _, _, err := zap.Open("") + + return test{ + name: "returns error when sinkPath is invalid", + fields: fields{ + format: format.RAW, + level: level.DEBUG, + }, + args: args{ + sinkPath: "", + errSinkPath: "stderr", + }, + want: want{ + err: err, + }, + checkFunc: func(w want, l *logger, err error) error { + if l.logger != nil { + return errors.New("l.logger is not empty") + } + + if l.sugar != nil { + return errors.New("l.sugar is not empty") + } + + return defaultCheckFunc(w, l, err) + }, + } + }(), + func() test { + _, _, err := zap.Open("xxx:///") + + return test{ + name: "returns error when errSinkPath is invalid", + fields: fields{ + format: format.RAW, + level: level.DEBUG, + }, + args: args{ + sinkPath: "stdout", + errSinkPath: "xxx:///", + }, + want: want{ + err: err, + }, + checkFunc: func(w want, l *logger, err error) error { + if l.logger != nil { + return errors.New("l.logger is not empty") + } + + if l.sugar != nil { + return errors.New("l.sugar is not empty") + } + + return defaultCheckFunc(w, l, err) + }, + } + }(), + { + name: "returns nil and initialize the logger and sugar fields correctly", + fields: fields{ + format: format.RAW, + level: level.DEBUG, + }, + args: args{ + sinkPath: "stdout", + errSinkPath: "stderr", + }, + want: want{ + err: nil, + }, + checkFunc: func(w want, l *logger, err error) error { + if l.logger == nil { + return errors.New("l.logger is nil") + } + + if l.sugar == nil { + return errors.New("l.sugar is nil") + } + + return defaultCheckFunc(w, l, err) + }, + }, + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc() + } + if test.afterFunc != nil { + defer test.afterFunc() + } + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + l := &logger{ + format: test.fields.format, + level: test.fields.level, + enableCaller: test.fields.enableCaller, + logger: test.fields.logger, + sugar: test.fields.sugar, + } + + err := l.initialize(test.args.sinkPath, test.args.errSinkPath) + if err := test.checkFunc(test.want, l, err); err != nil { + tt.Errorf("error = %v", err) + } + + }) + } +} + +func Test_toZapLevel(t *testing.T) { + type args struct { + lv level.Level + } + type want struct { + want zapcore.Level + } + type test struct { + name string + args args + want want + checkFunc func(want, zapcore.Level) error + beforeFunc func(args) + afterFunc func(args) + } + defaultCheckFunc := func(w want, got zapcore.Level) error { + if !reflect.DeepEqual(got, w.want) { + return errors.Errorf("got: \"%#v\",\n\t\t\t\twant: \"%#v\"", got, w.want) + } + return nil + } + tests := []test{ + { + name: "returns DebugLevel if lv is DEBUG", + args: args{ + lv: level.DEBUG, + }, + want: want{ + want: zapcore.DebugLevel, + }, + }, + { + name: "returns InfoLevel if lv is INFO", + args: args{ + lv: level.INFO, + }, + want: want{ + want: zapcore.InfoLevel, + }, + }, + { + name: "returns WarnLevel if lv is WARN", + args: args{ + lv: level.WARN, + }, + want: want{ + want: zapcore.WarnLevel, + }, + }, + { + name: "returns ErrorLevel if lv is Error", + args: args{ + lv: level.ERROR, + }, + want: want{ + want: zapcore.ErrorLevel, + }, + }, + { + name: "returns FatalLevel if lv is FATAL", + args: args{ + lv: level.FATAL, + }, + want: want{ + want: zapcore.FatalLevel, + }, + }, + { + name: "returns defaultLevel if lv is Unknown", + args: args{ + lv: level.Unknown, + }, + want: want{ + want: defaultLevel, + }, + }, + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc(test.args) + } + if test.afterFunc != nil { + defer test.afterFunc(test.args) + } + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + + got := toZapLevel(test.args.lv) + if err := test.checkFunc(test.want, got); err != nil { + tt.Errorf("error = %v", err) + } + + }) + } +} + +func Test_toZapEncoder(t *testing.T) { + type args struct { + fmt format.Format + } + type want struct { + want zapcore.Encoder + } + type test struct { + name string + args args + want want + checkFunc func(want, zapcore.Encoder) error + beforeFunc func(args) + afterFunc func(args) + } + defaultCheckFunc := func(w want, got zapcore.Encoder) error { + if !reflect.DeepEqual(got, w.want) { + return errors.Errorf("got: \"%#v\",\n\t\t\t\twant: \"%#v\"", got, w.want) + } + return nil + } + consoleEnc := zapcore.NewConsoleEncoder(zap.NewDevelopmentEncoderConfig()) + zapcore_NewConsoleEncoder = func(_ zapcore.EncoderConfig) zapcore.Encoder { + return consoleEnc + } + + jsonEnc := zapcore.NewJSONEncoder(zap.NewDevelopmentEncoderConfig()) + zapcore_NewJSONEncoder = func(_ zapcore.EncoderConfig) zapcore.Encoder { + return jsonEnc + } + + tests := []test{ + { + name: "returns ConsoleEncoder if fmt is RAW", + args: args{ + fmt: format.RAW, + }, + want: want{ + want: consoleEnc, + }, + }, + { + name: "returns JSONEncoder if fmt is JSON", + args: args{ + fmt: format.JSON, + }, + want: want{ + want: jsonEnc, + }, + }, + { + name: "returns JSONEncoder if fmt is Unknown", + args: args{ + fmt: format.Unknown, + }, + want: want{ + want: jsonEnc, + }, + }, + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc(test.args) + } + if test.afterFunc != nil { + defer test.afterFunc(test.args) + } + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + + got := toZapEncoder(test.args.fmt) + if err := test.checkFunc(test.want, got); err != nil { + tt.Errorf("error = %v", err) + } + + }) + } +} + +func Test_logger_log(t *testing.T) { + type args struct { + loggerFunc func(msg string, fields ...zapcore.Field) + sugarFunc func(args ...interface{}) + vals []interface{} + } + type fields struct { + format format.Format + level level.Level + enableCaller bool + logger *zap.Logger + sugar *zap.SugaredLogger + } + type want struct { + } + type test struct { + name string + args args + fields fields + want want + checkFunc func(want) error + beforeFunc func(args) + afterFunc func(args) + } + defaultCheckFunc := func(w want) error { + return nil + } + tests := []test{ + func() test { + count := 0 + + return test{ + name: "call sugarFunc when the length of vals is 1", + args: args{ + loggerFunc: nil, + sugarFunc: func(args ...interface{}) { + count++ + }, + vals: []interface{}{"a"}, + }, + fields: fields{ + format: format.RAW, + level: level.DEBUG, + }, + want: want{}, + checkFunc: func(w want) error { + if count != 1 { + return errors.New("sugarFunc is not called") + } + return nil + }, + } + }(), + func() test { + count := 0 + + return test{ + name: "call sugarFunc when the length of vals is greater than 1 and the first argument is not string", + args: args{ + loggerFunc: nil, + sugarFunc: func(args ...interface{}) { + count++ + }, + vals: []interface{}{1, 2, 3}, + }, + fields: fields{ + format: format.RAW, + level: level.DEBUG, + }, + want: want{}, + checkFunc: func(w want) error { + if count != 1 { + return errors.New("sugarFunc is not called") + } + return nil + }, + } + }(), + func() test { + count := 0 + + return test{ + name: "call loggerFunc when the length of vals is 2 and the first argument is string", + args: args{ + loggerFunc: func(msg string, fields ...zapcore.Field) { + count++ + }, + sugarFunc: nil, + vals: []interface{}{"a", "b"}, + }, + fields: fields{ + format: format.RAW, + level: level.DEBUG, + }, + want: want{}, + checkFunc: func(w want) error { + if count != 1 { + return errors.New("loggerFunc is not called") + } + return nil + }, + } + }(), + func() test { + count := 0 + + return test{ + name: "call loggerFunc when the length of vals is greater than 2 and the first argument is string", + args: args{ + loggerFunc: func(msg string, fields ...zapcore.Field) { + count++ + }, + sugarFunc: nil, + vals: []interface{}{"a", "b", "c"}, + }, + fields: fields{ + format: format.RAW, + level: level.DEBUG, + }, + want: want{}, + checkFunc: func(w want) error { + if count != 1 { + return errors.New("loggerFunc is not called") + } + return nil + }, + } + }(), + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc(test.args) + } + if test.afterFunc != nil { + defer test.afterFunc(test.args) + } + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + l := &logger{ + format: test.fields.format, + level: test.fields.level, + enableCaller: test.fields.enableCaller, + logger: test.fields.logger, + sugar: test.fields.sugar, + } + + l.log(test.args.loggerFunc, test.args.sugarFunc, test.args.vals...) + if err := test.checkFunc(test.want); err != nil { + tt.Errorf("error = %v", err) + } + }) + } +} + +func Test_logger_Debug(t *testing.T) { + type args struct { + vals []interface{} + } + type fields struct { + format format.Format + level level.Level + enableCaller bool + logger *zap.Logger + sugar *zap.SugaredLogger + } + type want struct { + } + type test struct { + name string + args args + fields fields + want want + checkFunc func(want) error + beforeFunc func(args) + afterFunc func(args) + } + defaultCheckFunc := func(w want) error { + return nil + } + tests := []test{ + { + name: "just call Debug", + args: args{ + vals: []interface{}{"value"}, + }, + fields: fields{ + format: format.RAW, + level: level.DEBUG, + enableCaller: false, + logger: zap.L(), + sugar: zap.L().Sugar(), + }, + want: want{}, + checkFunc: defaultCheckFunc, + }, + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc(test.args) + } + if test.afterFunc != nil { + defer test.afterFunc(test.args) + } + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + l := &logger{ + format: test.fields.format, + level: test.fields.level, + enableCaller: test.fields.enableCaller, + logger: test.fields.logger, + sugar: test.fields.sugar, + } + + l.Debug(test.args.vals...) + if err := test.checkFunc(test.want); err != nil { + tt.Errorf("error = %v", err) + } + }) + } +} + +func Test_logger_Debugf(t *testing.T) { + type args struct { + format string + vals []interface{} + } + type fields struct { + format format.Format + level level.Level + enableCaller bool + logger *zap.Logger + sugar *zap.SugaredLogger + } + type want struct { + } + type test struct { + name string + args args + fields fields + want want + checkFunc func(want) error + beforeFunc func(args) + afterFunc func(args) + } + defaultCheckFunc := func(w want) error { + return nil + } + tests := []test{ + { + name: "just call Debugf", + args: args{ + format: "%s", + vals: []interface{}{"value"}, + }, + fields: fields{ + format: format.RAW, + level: level.DEBUG, + enableCaller: false, + logger: zap.L(), + sugar: zap.L().Sugar(), + }, + want: want{}, + checkFunc: defaultCheckFunc, + }, + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc(test.args) + } + if test.afterFunc != nil { + defer test.afterFunc(test.args) + } + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + l := &logger{ + format: test.fields.format, + level: test.fields.level, + enableCaller: test.fields.enableCaller, + logger: test.fields.logger, + sugar: test.fields.sugar, + } + + l.Debugf(test.args.format, test.args.vals...) + if err := test.checkFunc(test.want); err != nil { + tt.Errorf("error = %v", err) + } + }) + } +} + +func Test_logger_Info(t *testing.T) { + type args struct { + vals []interface{} + } + type fields struct { + format format.Format + level level.Level + enableCaller bool + logger *zap.Logger + sugar *zap.SugaredLogger + } + type want struct { + } + type test struct { + name string + args args + fields fields + want want + checkFunc func(want) error + beforeFunc func(args) + afterFunc func(args) + } + defaultCheckFunc := func(w want) error { + return nil + } + tests := []test{ + { + name: "just call Info", + args: args{ + vals: []interface{}{"value"}, + }, + fields: fields{ + format: format.RAW, + level: level.DEBUG, + enableCaller: false, + logger: zap.L(), + sugar: zap.L().Sugar(), + }, + want: want{}, + checkFunc: defaultCheckFunc, + }, + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc(test.args) + } + if test.afterFunc != nil { + defer test.afterFunc(test.args) + } + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + l := &logger{ + format: test.fields.format, + level: test.fields.level, + enableCaller: test.fields.enableCaller, + logger: test.fields.logger, + sugar: test.fields.sugar, + } + + l.Info(test.args.vals...) + if err := test.checkFunc(test.want); err != nil { + tt.Errorf("error = %v", err) + } + }) + } +} + +func Test_logger_Infof(t *testing.T) { + type args struct { + format string + vals []interface{} + } + type fields struct { + format format.Format + level level.Level + enableCaller bool + logger *zap.Logger + sugar *zap.SugaredLogger + } + type want struct { + } + type test struct { + name string + args args + fields fields + want want + checkFunc func(want) error + beforeFunc func(args) + afterFunc func(args) + } + defaultCheckFunc := func(w want) error { + return nil + } + tests := []test{ + { + name: "just call Infof", + args: args{ + format: "%s", + vals: []interface{}{"value"}, + }, + fields: fields{ + format: format.RAW, + level: level.DEBUG, + enableCaller: false, + logger: zap.L(), + sugar: zap.L().Sugar(), + }, + want: want{}, + checkFunc: defaultCheckFunc, + }, + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc(test.args) + } + if test.afterFunc != nil { + defer test.afterFunc(test.args) + } + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + l := &logger{ + format: test.fields.format, + level: test.fields.level, + enableCaller: test.fields.enableCaller, + logger: test.fields.logger, + sugar: test.fields.sugar, + } + + l.Infof(test.args.format, test.args.vals...) + if err := test.checkFunc(test.want); err != nil { + tt.Errorf("error = %v", err) + } + }) + } +} + +func Test_logger_Warn(t *testing.T) { + type args struct { + vals []interface{} + } + type fields struct { + format format.Format + level level.Level + enableCaller bool + logger *zap.Logger + sugar *zap.SugaredLogger + } + type want struct { + } + type test struct { + name string + args args + fields fields + want want + checkFunc func(want) error + beforeFunc func(args) + afterFunc func(args) + } + defaultCheckFunc := func(w want) error { + return nil + } + tests := []test{ + { + name: "just call Warn", + args: args{ + vals: []interface{}{"value"}, + }, + fields: fields{ + format: format.RAW, + level: level.DEBUG, + enableCaller: false, + logger: zap.L(), + sugar: zap.L().Sugar(), + }, + want: want{}, + checkFunc: defaultCheckFunc, + }, + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc(test.args) + } + if test.afterFunc != nil { + defer test.afterFunc(test.args) + } + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + l := &logger{ + format: test.fields.format, + level: test.fields.level, + enableCaller: test.fields.enableCaller, + logger: test.fields.logger, + sugar: test.fields.sugar, + } + + l.Warn(test.args.vals...) + if err := test.checkFunc(test.want); err != nil { + tt.Errorf("error = %v", err) + } + }) + } +} + +func Test_logger_Warnf(t *testing.T) { + type args struct { + format string + vals []interface{} + } + type fields struct { + format format.Format + level level.Level + enableCaller bool + logger *zap.Logger + sugar *zap.SugaredLogger + } + type want struct { + } + type test struct { + name string + args args + fields fields + want want + checkFunc func(want) error + beforeFunc func(args) + afterFunc func(args) + } + defaultCheckFunc := func(w want) error { + return nil + } + tests := []test{ + { + name: "just call Warnf", + args: args{ + format: "%s", + vals: []interface{}{"value"}, + }, + fields: fields{ + format: format.RAW, + level: level.DEBUG, + enableCaller: false, + logger: zap.L(), + sugar: zap.L().Sugar(), + }, + want: want{}, + checkFunc: defaultCheckFunc, + }, + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc(test.args) + } + if test.afterFunc != nil { + defer test.afterFunc(test.args) + } + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + l := &logger{ + format: test.fields.format, + level: test.fields.level, + enableCaller: test.fields.enableCaller, + logger: test.fields.logger, + sugar: test.fields.sugar, + } + + l.Warnf(test.args.format, test.args.vals...) + if err := test.checkFunc(test.want); err != nil { + tt.Errorf("error = %v", err) + } + }) + } +} + +func Test_logger_Error(t *testing.T) { + type args struct { + vals []interface{} + } + type fields struct { + format format.Format + level level.Level + enableCaller bool + logger *zap.Logger + sugar *zap.SugaredLogger + } + type want struct { + } + type test struct { + name string + args args + fields fields + want want + checkFunc func(want) error + beforeFunc func(args) + afterFunc func(args) + } + defaultCheckFunc := func(w want) error { + return nil + } + tests := []test{ + { + name: "just call Error", + args: args{ + vals: []interface{}{"value"}, + }, + fields: fields{ + format: format.RAW, + level: level.DEBUG, + enableCaller: false, + logger: zap.L(), + sugar: zap.L().Sugar(), + }, + want: want{}, + checkFunc: defaultCheckFunc, + }, + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc(test.args) + } + if test.afterFunc != nil { + defer test.afterFunc(test.args) + } + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + l := &logger{ + format: test.fields.format, + level: test.fields.level, + enableCaller: test.fields.enableCaller, + logger: test.fields.logger, + sugar: test.fields.sugar, + } + + l.Error(test.args.vals...) + if err := test.checkFunc(test.want); err != nil { + tt.Errorf("error = %v", err) + } + }) + } +} + +func Test_logger_Errorf(t *testing.T) { + type args struct { + format string + vals []interface{} + } + type fields struct { + format format.Format + level level.Level + enableCaller bool + logger *zap.Logger + sugar *zap.SugaredLogger + } + type want struct { + } + type test struct { + name string + args args + fields fields + want want + checkFunc func(want) error + beforeFunc func(args) + afterFunc func(args) + } + defaultCheckFunc := func(w want) error { + return nil + } + tests := []test{ + { + name: "just call Errorf", + args: args{ + format: "%s", + vals: []interface{}{"value"}, + }, + fields: fields{ + format: format.RAW, + level: level.DEBUG, + enableCaller: false, + logger: zap.L(), + sugar: zap.L().Sugar(), + }, + want: want{}, + checkFunc: defaultCheckFunc, + }, + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc(test.args) + } + if test.afterFunc != nil { + defer test.afterFunc(test.args) + } + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + l := &logger{ + format: test.fields.format, + level: test.fields.level, + enableCaller: test.fields.enableCaller, + logger: test.fields.logger, + sugar: test.fields.sugar, + } + + l.Errorf(test.args.format, test.args.vals...) + if err := test.checkFunc(test.want); err != nil { + tt.Errorf("error = %v", err) + } + }) + } +} + +func Test_logger_Fatal(t *testing.T) { + type args struct { + vals []interface{} + } + type fields struct { + format format.Format + level level.Level + enableCaller bool + logger *zap.Logger + sugar *zap.SugaredLogger + } + type want struct { + } + type test struct { + name string + args args + fields fields + want want + checkFunc func(want) error + beforeFunc func(args) + afterFunc func(args) + } + defaultCheckFunc := func(w want) error { + return nil + } + tests := []test{ + // { + // name: "just call Fatal", + // args: args{ + // vals: []interface{}{"value"}, + // }, + // fields: fields{ + // format: format.RAW, + // level: level.DEBUG, + // enableCaller: false, + // logger: zap.L(), + // sugar: zap.L().Sugar(), + // }, + // want: want{}, + // checkFunc: defaultCheckFunc, + // }, + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc(test.args) + } + if test.afterFunc != nil { + defer test.afterFunc(test.args) + } + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + l := &logger{ + format: test.fields.format, + level: test.fields.level, + enableCaller: test.fields.enableCaller, + logger: test.fields.logger, + sugar: test.fields.sugar, + } + + l.Fatal(test.args.vals...) + if err := test.checkFunc(test.want); err != nil { + tt.Errorf("error = %v", err) + } + }) + } +} + +func Test_logger_Fatalf(t *testing.T) { + type args struct { + format string + vals []interface{} + } + type fields struct { + format format.Format + level level.Level + enableCaller bool + logger *zap.Logger + sugar *zap.SugaredLogger + } + type want struct { + } + type test struct { + name string + args args + fields fields + want want + checkFunc func(want) error + beforeFunc func(args) + afterFunc func(args) + } + defaultCheckFunc := func(w want) error { + return nil + } + tests := []test{ + // { + // name: "just call Fatalf", + // args: args{ + // format: "%s", + // vals: []interface{}{"value"}, + // }, + // fields: fields{ + // format: format.RAW, + // level: level.DEBUG, + // enableCaller: false, + // logger: zap.L(), + // sugar: zap.L().Sugar(), + // }, + // want: want{}, + // checkFunc: defaultCheckFunc, + // }, + } + + for _, test := range tests { + t.Run(test.name, func(tt *testing.T) { + defer goleak.VerifyNone(tt) + if test.beforeFunc != nil { + test.beforeFunc(test.args) + } + if test.afterFunc != nil { + defer test.afterFunc(test.args) + } + if test.checkFunc == nil { + test.checkFunc = defaultCheckFunc + } + l := &logger{ + format: test.fields.format, + level: test.fields.level, + enableCaller: test.fields.enableCaller, + logger: test.fields.logger, + sugar: test.fields.sugar, + } + + l.Fatalf(test.args.format, test.args.vals...) + if err := test.checkFunc(test.want); err != nil { + tt.Errorf("error = %v", err) + } + }) + } +} diff --git a/internal/net/grpc/interceptor.go b/internal/net/grpc/interceptor.go index ee34e00118c..8868ab5c79f 100644 --- a/internal/net/grpc/interceptor.go +++ b/internal/net/grpc/interceptor.go @@ -19,7 +19,11 @@ package grpc import ( "context" + "path" + "time" + "github.com/vdaas/vald/internal/log" + "github.com/vdaas/vald/internal/observability/trace" "github.com/vdaas/vald/internal/safety" "google.golang.org/grpc" ) @@ -61,3 +65,62 @@ func RecoverStreamInterceptor() StreamServerInterceptor { })() } } + +func AccessLogInterceptor() UnaryServerInterceptor { + return func( + ctx context.Context, + req interface{}, + info *grpc.UnaryServerInfo, + handler grpc.UnaryHandler, + ) (resp interface{}, err error) { + var traceID string + + span := trace.FromContext(ctx) + if span != nil { + traceID = span.SpanContext().TraceID.String() + } + + start := time.Now() + + resp, err = handler(ctx, req) + + latency := float64(time.Since(start)) / float64(time.Second) + startTime := float64(start.UnixNano()) / float64(time.Second) + + service, method := parseMethod(info.FullMethod) + + if err != nil { + log.Error( + "rpc call proceeded", + map[string]interface{}{ + "grpcService": service, + "grpcMethod": method, + "startTime": startTime, + "latency": latency, + "traceID": traceID, + "error": err, + }, + ) + } else { + log.Info( + "rpc call proceeded", + map[string]interface{}{ + "grpcService": service, + "grpcMethod": method, + "startTime": startTime, + "latency": latency, + "traceID": traceID, + }, + ) + } + + return resp, err + } +} + +func parseMethod(fullMethod string) (service, method string) { + service = path.Dir(fullMethod)[1:] + method = path.Base(fullMethod) + + return service, method +} diff --git a/pkg/agent/core/ngt/usecase/agentd.go b/pkg/agent/core/ngt/usecase/agentd.go index dbd939453dd..6c9e7ac9ae8 100644 --- a/pkg/agent/core/ngt/usecase/agentd.go +++ b/pkg/agent/core/ngt/usecase/agentd.go @@ -78,7 +78,10 @@ func New(cfg *config.Data) (r runner.Runner, err error) { agent.RegisterAgentServer(srv, g) }), server.WithGRPCOption( - grpc.ChainUnaryInterceptor(grpc.RecoverInterceptor()), + grpc.ChainUnaryInterceptor( + grpc.RecoverInterceptor(), + grpc.AccessLogInterceptor(), + ), grpc.ChainStreamInterceptor(grpc.RecoverStreamInterceptor()), ), server.WithPreStartFunc(func() error {