From 3830b3ef114b5f5853859b4140c4e835ad2a8490 Mon Sep 17 00:00:00 2001 From: yoyinzyc Date: Wed, 18 Sep 2019 12:46:34 -0700 Subject: [PATCH] pkg: add field to record additional detail of trace; add stepThreshold to reduce log volume. --- etcdserver/apply.go | 12 +- etcdserver/util.go | 14 +- etcdserver/v3_server.go | 19 ++- mvcc/kv_test.go | 3 +- mvcc/kv_view.go | 11 +- mvcc/kvstore_test.go | 7 +- mvcc/kvstore_txn.go | 10 +- pkg/traceutil/trace.go | 123 +++++++++++--- pkg/traceutil/trace_test.go | 325 ++++++++++++++++++++++++++++++++++-- 9 files changed, 449 insertions(+), 75 deletions(-) diff --git a/etcdserver/apply.go b/etcdserver/apply.go index f5b3c24b0..7ce4ffd83 100644 --- a/etcdserver/apply.go +++ b/etcdserver/apply.go @@ -34,7 +34,8 @@ import ( ) const ( - warnApplyDuration = 100 * time.Millisecond + warnApplyDuration = 100 * time.Millisecond + rangeTraceThreshold = 100 * time.Millisecond ) type applyResult struct { @@ -247,11 +248,7 @@ func (a *applierV3backend) DeleteRange(txn mvcc.TxnWrite, dr *pb.DeleteRangeRequ } func (a *applierV3backend) Range(ctx context.Context, txn mvcc.TxnRead, r *pb.RangeRequest) (*pb.RangeResponse, error) { - trace, ok := ctx.Value("trace").(*traceutil.Trace) - if !ok || trace == nil { - trace = traceutil.New("Apply Range") - ctx = context.WithValue(ctx, "trace", trace) - } + trace := traceutil.Get(ctx) resp := &pb.RangeResponse{} resp.Header = &pb.ResponseHeader{} @@ -350,8 +347,7 @@ func (a *applierV3backend) Range(ctx context.Context, txn mvcc.TxnRead, r *pb.Ra func (a *applierV3backend) Txn(rt *pb.TxnRequest) (*pb.TxnResponse, error) { isWrite := !isTxnReadonly(rt) - trace := traceutil.New("ReadOnlyTxn") - txn := mvcc.NewReadOnlyTxnWrite(a.s.KV().Read(trace)) + txn := mvcc.NewReadOnlyTxnWrite(a.s.KV().Read(traceutil.TODO())) txnPath := compareToPath(txn, rt) if isWrite { diff --git a/etcdserver/util.go b/etcdserver/util.go index 4db42d065..fe5024ef0 100644 --- a/etcdserver/util.go +++ b/etcdserver/util.go @@ -24,7 +24,6 @@ import ( "go.etcd.io/etcd/etcdserver/api/membership" "go.etcd.io/etcd/etcdserver/api/rafthttp" pb "go.etcd.io/etcd/etcdserver/etcdserverpb" - "go.etcd.io/etcd/pkg/traceutil" "go.etcd.io/etcd/pkg/types" "go.uber.org/zap" @@ -109,7 +108,7 @@ func warnOfExpensiveRequest(lg *zap.Logger, now time.Time, reqStringer fmt.Strin if !isNil(respMsg) { resp = fmt.Sprintf("size:%d", proto.Size(respMsg)) } - warnOfExpensiveGenericRequest(lg, nil, now, reqStringer, "", resp, err) + warnOfExpensiveGenericRequest(lg, now, reqStringer, "", resp, err) } func warnOfExpensiveReadOnlyTxnRequest(lg *zap.Logger, now time.Time, r *pb.TxnRequest, txnResponse *pb.TxnResponse, err error) { @@ -127,18 +126,18 @@ func warnOfExpensiveReadOnlyTxnRequest(lg *zap.Logger, now time.Time, r *pb.TxnR } resp = fmt.Sprintf("responses:<%s> size:%d", strings.Join(resps, " "), proto.Size(txnResponse)) } - warnOfExpensiveGenericRequest(lg, nil, now, reqStringer, "read-only range ", resp, err) + warnOfExpensiveGenericRequest(lg, now, reqStringer, "read-only range ", resp, err) } -func warnOfExpensiveReadOnlyRangeRequest(lg *zap.Logger, trace *traceutil.Trace, now time.Time, reqStringer fmt.Stringer, rangeResponse *pb.RangeResponse, err error) { +func warnOfExpensiveReadOnlyRangeRequest(lg *zap.Logger, now time.Time, reqStringer fmt.Stringer, rangeResponse *pb.RangeResponse, err error) { var resp string if !isNil(rangeResponse) { resp = fmt.Sprintf("range_response_count:%d size:%d", len(rangeResponse.Kvs), proto.Size(rangeResponse)) } - warnOfExpensiveGenericRequest(lg, trace, now, reqStringer, "read-only range ", resp, err) + warnOfExpensiveGenericRequest(lg, now, reqStringer, "read-only range ", resp, err) } -func warnOfExpensiveGenericRequest(lg *zap.Logger, trace *traceutil.Trace, now time.Time, reqStringer fmt.Stringer, prefix string, resp string, err error) { +func warnOfExpensiveGenericRequest(lg *zap.Logger, now time.Time, reqStringer fmt.Stringer, prefix string, resp string, err error) { d := time.Since(now) if d > warnApplyDuration { if lg != nil { @@ -160,9 +159,6 @@ func warnOfExpensiveGenericRequest(lg *zap.Logger, trace *traceutil.Trace, now t } plog.Warningf("%srequest %q with result %q took too long (%v) to execute", prefix, reqStringer.String(), result, d) } - if trace != nil { - trace.Log(lg) - } slowApplies.Inc() } } diff --git a/etcdserver/v3_server.go b/etcdserver/v3_server.go index efe3bfe35..6f10f87b9 100644 --- a/etcdserver/v3_server.go +++ b/etcdserver/v3_server.go @@ -86,13 +86,23 @@ type Authenticator interface { } func (s *EtcdServer) Range(ctx context.Context, r *pb.RangeRequest) (*pb.RangeResponse, error) { - trace := traceutil.New("Range") + trace := traceutil.New("Range", + traceutil.Field{Key: "RangeBegin", Value: string(r.Key)}, + traceutil.Field{Key: "RangeEnd", Value: string(r.RangeEnd)}, + ) ctx = context.WithValue(ctx, "trace", trace) var resp *pb.RangeResponse var err error defer func(start time.Time) { - warnOfExpensiveReadOnlyRangeRequest(s.getLogger(), trace, start, r, resp, err) + warnOfExpensiveReadOnlyRangeRequest(s.getLogger(), start, r, resp, err) + if resp != nil { + trace.AddField( + traceutil.Field{Key: "ResponseCount", Value: len(resp.Kvs)}, + traceutil.Field{Key: "ResponseRevision", Value: resp.Header.Revision}, + ) + } + trace.LogIfLong(rangeTraceThreshold, s.getLogger()) }(time.Now()) if !r.Serializable { @@ -564,9 +574,8 @@ func (s *EtcdServer) doSerialize(ctx context.Context, chk func(*auth.AuthInfo) e return err } - if trace, ok := ctx.Value("trace").(*traceutil.Trace); ok && trace != nil { - trace.Step("Authentication.") - } + trace := traceutil.Get(ctx) + trace.Step("Authentication.") // fetch response for serialized request get() // check for stale token revision in case the auth store was updated while diff --git a/mvcc/kv_test.go b/mvcc/kv_test.go index 673cfba74..6c72d0879 100644 --- a/mvcc/kv_test.go +++ b/mvcc/kv_test.go @@ -25,6 +25,7 @@ import ( "go.etcd.io/etcd/mvcc/backend" "go.etcd.io/etcd/mvcc/mvccpb" "go.etcd.io/etcd/pkg/testutil" + "go.etcd.io/etcd/pkg/traceutil" "github.com/prometheus/client_golang/prometheus" dto "github.com/prometheus/client_model/go" @@ -47,7 +48,7 @@ var ( return kv.Range(key, end, ro) } txnRangeFunc = func(kv KV, key, end []byte, ro RangeOptions) (*RangeResult, error) { - txn := kv.Read(nil) + txn := kv.Read(traceutil.TODO()) defer txn.End() return txn.Range(key, end, ro) } diff --git a/mvcc/kv_view.go b/mvcc/kv_view.go index 56070d18f..9750fd764 100644 --- a/mvcc/kv_view.go +++ b/mvcc/kv_view.go @@ -14,24 +14,27 @@ package mvcc -import "go.etcd.io/etcd/lease" +import ( + "go.etcd.io/etcd/lease" + "go.etcd.io/etcd/pkg/traceutil" +) type readView struct{ kv KV } func (rv *readView) FirstRev() int64 { - tr := rv.kv.Read(nil) + tr := rv.kv.Read(traceutil.TODO()) defer tr.End() return tr.FirstRev() } func (rv *readView) Rev() int64 { - tr := rv.kv.Read(nil) + tr := rv.kv.Read(traceutil.TODO()) defer tr.End() return tr.Rev() } func (rv *readView) Range(key, end []byte, ro RangeOptions) (r *RangeResult, err error) { - tr := rv.kv.Read(nil) + tr := rv.kv.Read(traceutil.TODO()) defer tr.End() return tr.Range(key, end, ro) } diff --git a/mvcc/kvstore_test.go b/mvcc/kvstore_test.go index cde1954de..c4180c963 100644 --- a/mvcc/kvstore_test.go +++ b/mvcc/kvstore_test.go @@ -34,6 +34,7 @@ import ( "go.etcd.io/etcd/mvcc/mvccpb" "go.etcd.io/etcd/pkg/schedule" "go.etcd.io/etcd/pkg/testutil" + "go.etcd.io/etcd/pkg/traceutil" "go.uber.org/zap" ) @@ -658,7 +659,7 @@ func TestConcurrentReadNotBlockingWrite(t *testing.T) { s.Put([]byte("foo"), []byte("bar"), lease.NoLease) // readTx simulates a long read request - readTx1 := s.Read(nil) + readTx1 := s.Read(traceutil.TODO()) // write should not be blocked by reads done := make(chan struct{}) @@ -673,7 +674,7 @@ func TestConcurrentReadNotBlockingWrite(t *testing.T) { } // readTx2 simulates a short read request - readTx2 := s.Read(nil) + readTx2 := s.Read(traceutil.TODO()) ro := RangeOptions{Limit: 1, Rev: 0, Count: false} ret, err := readTx2.Range([]byte("foo"), nil, ro) if err != nil { @@ -756,7 +757,7 @@ func TestConcurrentReadTxAndWrite(t *testing.T) { mu.Lock() wKVs := make(kvs, len(committedKVs)) copy(wKVs, committedKVs) - tx := s.Read(nil) + tx := s.Read(traceutil.TODO()) mu.Unlock() // get all keys in backend store, and compare with wKVs ret, err := tx.Range([]byte("\x00000000"), []byte("\xffffffff"), RangeOptions{}) diff --git a/mvcc/kvstore_txn.go b/mvcc/kvstore_txn.go index c5e5c973e..ee9651ff6 100644 --- a/mvcc/kvstore_txn.go +++ b/mvcc/kvstore_txn.go @@ -69,7 +69,7 @@ func (s *store) Write() TxnWrite { tx := s.b.BatchTx() tx.Lock() tw := &storeTxnWrite{ - storeTxnRead: storeTxnRead{s, tx, 0, 0, nil}, + storeTxnRead: storeTxnRead{s, tx, 0, 0, traceutil.TODO()}, tx: tx, beginRev: s.currentRev, changes: make([]mvccpb.KeyValue, 0, 4), @@ -127,9 +127,7 @@ func (tr *storeTxnRead) rangeKeys(key, end []byte, curRev int64, ro RangeOptions } revpairs := tr.s.kvindex.Revisions(key, end, rev) - if tr.trace != nil { - tr.trace.Step("Range keys from in-memory index tree.") - } + tr.trace.Step("Range keys from in-memory index tree.") if len(revpairs) == 0 { return &RangeResult{KVs: nil, Count: 0, Rev: curRev}, nil } @@ -169,9 +167,7 @@ func (tr *storeTxnRead) rangeKeys(key, end []byte, curRev int64, ro RangeOptions } } } - if tr.trace != nil { - tr.trace.Step("Range keys from bolt db.") - } + tr.trace.Step("Range keys from bolt db.") return &RangeResult{KVs: kvs, Count: len(revpairs), Rev: curRev}, nil } diff --git a/pkg/traceutil/trace.go b/pkg/traceutil/trace.go index e21f6ef09..1d2e26c42 100644 --- a/pkg/traceutil/trace.go +++ b/pkg/traceutil/trace.go @@ -2,7 +2,9 @@ package traceutil import ( "bytes" + "context" "fmt" + "math/rand" "time" "github.com/coreos/pkg/capnslog" @@ -13,48 +15,121 @@ var ( plog = capnslog.NewPackageLogger("go.etcd.io/etcd", "trace") ) +// Field is a kv pair to record additional details of the trace. +type Field struct { + Key string + Value interface{} +} + +func (f *Field) format() string { + return fmt.Sprintf("%s:%v; ", f.Key, f.Value) +} + +func writeFields(fields []Field) string { + if len(fields) == 0 { + return "" + } + var buf bytes.Buffer + buf.WriteString("{") + for _, f := range fields { + buf.WriteString(f.format()) + } + buf.WriteString("}") + return buf.String() +} + type Trace struct { operation string + fields []Field startTime time.Time steps []step } type step struct { - time time.Time - msg string + time time.Time + msg string + fields []Field } -func New(op string) *Trace { - return &Trace{operation: op, startTime: time.Now()} +func New(op string, fields ...Field) *Trace { + return &Trace{operation: op, startTime: time.Now(), fields: fields} } -func (t *Trace) Step(msg string) { - t.steps = append(t.steps, step{time: time.Now(), msg: msg}) +// traceutil.TODO() returns a non-nil, empty Trace +func TODO() *Trace { + return &Trace{} } -// Dump all steps in the Trace -func (t *Trace) Log(lg *zap.Logger) { - - var buf bytes.Buffer - - buf.WriteString(fmt.Sprintf("The tracing of %v request:\n", t.operation)) - - buf.WriteString("Request started at:") - buf.WriteString(t.startTime.Format("2006-01-02 15:04:05")) - buf.WriteString(fmt.Sprintf(".%06d", t.startTime.Nanosecond()/1000)) - buf.WriteString("\n") - lastStepTime := t.startTime - for i, step := range t.steps { - buf.WriteString(fmt.Sprintf("Step %d: %v Time cost: %v\n", i, step.msg, step.time.Sub(lastStepTime))) - //fmt.Println(step.msg, " costs: ", step.time.Sub(lastStepTime)) - lastStepTime = step.time +func Get(ctx context.Context) *Trace { + if trace, ok := ctx.Value("trace").(*Trace); ok && trace != nil { + return trace } - buf.WriteString("Trace End\n") + return TODO() +} - s := buf.String() +func GetOrCreate(ctx context.Context, op string, fields ...Field) (context.Context, *Trace) { + trace, ok := ctx.Value("trace").(*Trace) + if !ok || trace == nil { + trace = New(op) + trace.fields = fields + ctx = context.WithValue(ctx, "trace", trace) + } + return ctx, trace +} + +func (t *Trace) Step(msg string, fields ...Field) { + t.steps = append(t.steps, step{time: time.Now(), msg: msg, fields: fields}) +} + +func (t *Trace) AddField(fields ...Field) { + for _, f := range fields { + t.fields = append(t.fields, f) + } +} + +// Log dumps all steps in the Trace +func (t *Trace) Log(lg *zap.Logger) { + t.LogWithStepThreshold(0, lg) +} + +// LogIfLong dumps logs if the duration is longer than threshold +func (t *Trace) LogIfLong(threshold time.Duration, lg *zap.Logger) { + if time.Since(t.startTime) > threshold { + stepThreshold := threshold / time.Duration(len(t.steps)+1) + t.LogWithStepThreshold(stepThreshold, lg) + } +} + +// LogWithStepThreshold only dumps step whose duration is longer than step threshold +func (t *Trace) LogWithStepThreshold(threshold time.Duration, lg *zap.Logger) { + s := t.format(threshold) if lg != nil { lg.Info(s) } else { plog.Info(s) } } + +func (t *Trace) format(threshold time.Duration) string { + endTime := time.Now() + totalDuration := endTime.Sub(t.startTime) + var buf bytes.Buffer + traceNum := rand.Int31() + + buf.WriteString(fmt.Sprintf("Trace[%d] \"%v\" %s (duration: %v, start: %v)\n", + traceNum, t.operation, writeFields(t.fields), totalDuration, + t.startTime.Format("2006-01-02 15:04:05.000"))) + lastStepTime := t.startTime + for _, step := range t.steps { + stepDuration := step.time.Sub(lastStepTime) + if stepDuration > threshold { + buf.WriteString(fmt.Sprintf("Trace[%d] Step \"%v\" %s (duration: %v)\n", + traceNum, step.msg, writeFields(step.fields), stepDuration)) + } + lastStepTime = step.time + } + buf.WriteString(fmt.Sprintf("Trace[%d] End %v\n", traceNum, + endTime.Format("2006-01-02 15:04:05.000"))) + + return buf.String() +} diff --git a/pkg/traceutil/trace_test.go b/pkg/traceutil/trace_test.go index 2517c5463..3e6da09d5 100644 --- a/pkg/traceutil/trace_test.go +++ b/pkg/traceutil/trace_test.go @@ -1,28 +1,325 @@ package traceutil import ( + "bytes" + "context" + "fmt" + "io/ioutil" + "os" + "path/filepath" + "regexp" + "strings" "testing" + "time" + + "go.uber.org/zap" ) -func TestTrace(t *testing.T) { - var ( - op = "Test" - steps = []string{"Step1, Step2"} - ) - - trace := New(op) - if trace.operation != op { - t.Errorf("Expected %v, got %v\n", op, trace.operation) +func TestGet(t *testing.T) { + traceForTest := &Trace{operation: "test"} + tests := []struct { + name string + inputCtx context.Context + outputTrace *Trace + }{ + { + name: "When the context does not have trace", + inputCtx: context.TODO(), + outputTrace: TODO(), + }, + { + name: "When the context has trace", + inputCtx: context.WithValue(context.Background(), "trace", traceForTest), + outputTrace: traceForTest, + }, } - for _, v := range steps { - trace.Step(v) - trace.Step(v) + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + trace := Get(tt.inputCtx) + if trace == nil { + t.Errorf("Expected %v; Got nil\n", tt.outputTrace) + } + if trace.operation != tt.outputTrace.operation { + t.Errorf("Expected %v; Got %v\n", tt.outputTrace, trace) + } + }) + } +} + +func TestGetOrCreate(t *testing.T) { + tests := []struct { + name string + inputCtx context.Context + outputTraceOp string + }{ + { + name: "When the context does not have trace", + inputCtx: context.TODO(), + outputTraceOp: "test", + }, + { + name: "When the context has trace", + inputCtx: context.WithValue(context.Background(), "trace", &Trace{operation: "test"}), + outputTraceOp: "test", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + ctx, trace := GetOrCreate(tt.inputCtx, "test") + if trace == nil { + t.Errorf("Expected trace object; Got nil\n") + } else if trace.operation != tt.outputTraceOp { + t.Errorf("Expected %v; Got %v\n", tt.outputTraceOp, trace.operation) + } + if ctx.Value("trace") == nil { + t.Errorf("Expected context has attached trace; Got nil\n") + } + }) + } +} + +func TestCreate(t *testing.T) { + var ( + op = "Test" + steps = []string{"Step1, Step2"} + fields = []Field{ + {"traceKey1", "traceValue1"}, + {"traceKey2", "traceValue2"}, + } + stepFields = []Field{ + {"stepKey1", "stepValue2"}, + {"stepKey2", "stepValue2"}, + } + ) + + trace := New(op, fields[0], fields[1]) + if trace.operation != op { + t.Errorf("Expected %v; Got %v\n", op, trace.operation) + } + for i, f := range trace.fields { + if f.Key != fields[i].Key { + t.Errorf("Expected %v; Got %v\n", fields[i].Key, f.Key) + } + if f.Value != fields[i].Value { + t.Errorf("Expected %v; Got %v\n", fields[i].Value, f.Value) + } } for i, v := range steps { - if v != trace.steps[i].msg { - t.Errorf("Expected %v, got %v\n.", v, trace.steps[i].msg) + trace.Step(v, stepFields[i]) + } + + for i, v := range trace.steps { + if steps[i] != v.msg { + t.Errorf("Expected %v, got %v\n.", steps[i], v.msg) + } + if stepFields[i].Key != v.fields[0].Key { + t.Errorf("Expected %v; Got %v\n", stepFields[i].Key, v.fields[0].Key) + } + if stepFields[i].Value != v.fields[0].Value { + t.Errorf("Expected %v; Got %v\n", stepFields[i].Value, v.fields[0].Value) } } } + +func TestLog(t *testing.T) { + test := struct { + name string + trace *Trace + expectedMsg []string + }{ + name: "When dump all logs", + trace: &Trace{ + operation: "Test", + startTime: time.Now().Add(-100 * time.Millisecond), + steps: []step{ + {time: time.Now().Add(-80 * time.Millisecond), msg: "msg1"}, + {time: time.Now().Add(-50 * time.Millisecond), msg: "msg2"}, + }, + }, + expectedMsg: []string{ + "msg1", "msg2", + }, + } + + t.Run(test.name, func(t *testing.T) { + logPath := filepath.Join(os.TempDir(), fmt.Sprintf("test-log-%d", time.Now().UnixNano())) + defer os.RemoveAll(logPath) + + lcfg := zap.NewProductionConfig() + lcfg.OutputPaths = []string{logPath} + lcfg.ErrorOutputPaths = []string{logPath} + lg, _ := lcfg.Build() + + test.trace.Log(lg) + data, err := ioutil.ReadFile(logPath) + if err != nil { + t.Fatal(err) + } + + for _, msg := range test.expectedMsg { + if !bytes.Contains(data, []byte(msg)) { + t.Errorf("Expected to find %v in log.\n", msg) + } + } + }) +} + +func TestTraceFormat(t *testing.T) { + tests := []struct { + name string + trace *Trace + fields []Field + expectedMsg []string + }{ + { + name: "When trace has fields", + trace: &Trace{ + operation: "Test", + startTime: time.Now().Add(-100 * time.Millisecond), + steps: []step{ + { + time: time.Now().Add(-80 * time.Millisecond), + msg: "msg1", + fields: []Field{{"stepKey1", "stepValue1"}}, + }, + { + time: time.Now().Add(-50 * time.Millisecond), + msg: "msg2", + fields: []Field{{"stepKey2", "stepValue2"}}, + }, + }, + }, + fields: []Field{ + {"traceKey1", "traceValue1"}, + {"count", 1}, + }, + expectedMsg: []string{ + "Test", + "msg1", "msg2", + "traceKey1:traceValue1", "count:1", + "stepKey1:stepValue1", "stepKey2:stepValue2", + }, + }, + { + name: "When trace has no field", + trace: &Trace{ + operation: "Test", + startTime: time.Now().Add(-100 * time.Millisecond), + steps: []step{ + {time: time.Now().Add(-80 * time.Millisecond), msg: "msg1"}, + {time: time.Now().Add(-50 * time.Millisecond), msg: "msg2"}, + }, + }, + fields: []Field{}, + expectedMsg: []string{ + "Test", + "msg1", "msg2", + }, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + for _, f := range tt.fields { + tt.trace.AddField(f) + } + s := tt.trace.format(0) + var buf bytes.Buffer + buf.WriteString(`Trace\[(\d*)?\](.+)\(duration(.+)start(.+)\)\n`) + for range tt.trace.steps { + buf.WriteString(`Trace\[(\d*)?\](.+)Step(.+)\(duration(.+)\)\n`) + } + buf.WriteString(`Trace\[(\d*)?\](.+)End(.+)\n`) + pattern := buf.String() + + r, _ := regexp.Compile(pattern) + if !r.MatchString(s) { + t.Errorf("Wrong log format.\n") + } + for _, msg := range tt.expectedMsg { + if !strings.Contains(s, msg) { + t.Errorf("Expected to find %v in log.\n", msg) + } + } + }) + } +} + +func TestLogIfLong(t *testing.T) { + tests := []struct { + name string + threshold time.Duration + trace *Trace + expectedMsg []string + }{ + { + name: "When the duration is smaller than threshold", + threshold: time.Duration(200 * time.Millisecond), + trace: &Trace{ + operation: "Test", + startTime: time.Now().Add(-100 * time.Millisecond), + steps: []step{ + {time: time.Now().Add(-50 * time.Millisecond), msg: "msg1"}, + {time: time.Now(), msg: "msg2"}, + }, + }, + expectedMsg: []string{}, + }, + { + name: "When the duration is longer than threshold", + threshold: time.Duration(50 * time.Millisecond), + trace: &Trace{ + operation: "Test", + startTime: time.Now().Add(-100 * time.Millisecond), + steps: []step{ + {time: time.Now().Add(-50 * time.Millisecond), msg: "msg1"}, + {time: time.Now(), msg: "msg2"}, + }, + }, + expectedMsg: []string{ + "msg1", "msg2", + }, + }, + { + name: "When not all steps are longer than step threshold", + threshold: time.Duration(50 * time.Millisecond), + trace: &Trace{ + operation: "Test", + startTime: time.Now().Add(-100 * time.Millisecond), + steps: []step{ + {time: time.Now(), msg: "msg1"}, + {time: time.Now(), msg: "msg2"}, + }, + }, + expectedMsg: []string{ + "msg1", + }, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + logPath := filepath.Join(os.TempDir(), fmt.Sprintf("test-log-%d", time.Now().UnixNano())) + defer os.RemoveAll(logPath) + + lcfg := zap.NewProductionConfig() + lcfg.OutputPaths = []string{logPath} + lcfg.ErrorOutputPaths = []string{logPath} + lg, _ := lcfg.Build() + + tt.trace.LogIfLong(tt.threshold, lg) + data, err := ioutil.ReadFile(logPath) + if err != nil { + t.Fatal(err) + } + for _, msg := range tt.expectedMsg { + if !bytes.Contains(data, []byte(msg)) { + t.Errorf("Expected to find %v in log\n", msg) + } + } + }) + } +}