pkg: use zap logger to format the structure log output.

etcdserver/apply.go

@@ -331,7 +331,7 @@ func (a *applierV3backend) Range(ctx context.Context, txn mvcc.TxnRead, r *pb.Ra
 		rr.KVs = rr.KVs[:r.Limit]
 		resp.More = true
 	}
-	trace.Step("Filter and sort the key-value pairs.")
+	trace.Step("filter and sort the key-value pairs")
 	resp.Header.Revision = rr.Rev
 	resp.Count = int64(rr.Count)
 	resp.Kvs = make([]*mvccpb.KeyValue, len(rr.KVs))
@@ -341,7 +341,7 @@ func (a *applierV3backend) Range(ctx context.Context, txn mvcc.TxnRead, r *pb.Ra
 		}
 		resp.Kvs[i] = &rr.KVs[i]
 	}
-	trace.Step("Assemble the response.")
+	trace.Step("assemble the response")
 	return resp, nil
 }
 

etcdserver/v3_server.go

@@ -86,28 +86,29 @@ type Authenticator interface {
 }
 
 func (s *EtcdServer) Range(ctx context.Context, r *pb.RangeRequest) (*pb.RangeResponse, error) {
-	trace := traceutil.New("Range",
-		traceutil.Field{Key: "RangeBegin", Value: string(r.Key)},
-		traceutil.Field{Key: "RangeEnd", Value: string(r.RangeEnd)},
+	trace := traceutil.New("range",
+		s.getLogger(),
+		traceutil.Field{Key: "range_begin", Value: string(r.Key)},
+		traceutil.Field{Key: "range_end", Value: string(r.RangeEnd)},
 	)
-	ctx = context.WithValue(ctx, "trace", trace)
+	ctx = context.WithValue(ctx, traceutil.CtxKey, trace)
 
 	var resp *pb.RangeResponse
 	var err error
 	defer func(start time.Time) {
 		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},
+				traceutil.Field{Key: "response_count", Value: len(resp.Kvs)},
+				traceutil.Field{Key: "response_revision", Value: resp.Header.Revision},
 			)
 		}
-		trace.LogIfLong(rangeTraceThreshold, s.getLogger())
+		trace.LogIfLong(rangeTraceThreshold)
 	}(time.Now())
 
 	if !r.Serializable {
 		err = s.linearizableReadNotify(ctx)
-		trace.Step("Agreement among raft nodes before linearized reading.")
+		trace.Step("agreement among raft nodes before linearized reading")
 		if err != nil {
 			return nil, err
 		}
@@ -562,6 +563,7 @@ func (s *EtcdServer) raftRequest(ctx context.Context, r pb.InternalRaftRequest)
 
 // doSerialize handles the auth logic, with permissions checked by "chk", for a serialized request "get". Returns a non-nil error on authentication failure.
 func (s *EtcdServer) doSerialize(ctx context.Context, chk func(*auth.AuthInfo) error, get func()) error {
+	trace := traceutil.Get(ctx)
 	ai, err := s.AuthInfoFromCtx(ctx)
 	if err != nil {
 		return err
@@ -573,9 +575,7 @@ func (s *EtcdServer) doSerialize(ctx context.Context, chk func(*auth.AuthInfo) e
 	if err = chk(ai); err != nil {
 		return err
 	}
-
-	trace := traceutil.Get(ctx)
-	trace.Step("Authentication.")
+	trace.Step("get authentication metadata")
 	// fetch response for serialized request
 	get()
 	// check for stale token revision in case the auth store was updated while

mvcc/kvstore_txn.go

@@ -127,7 +127,7 @@ func (tr *storeTxnRead) rangeKeys(key, end []byte, curRev int64, ro RangeOptions
 	}
 
 	revpairs := tr.s.kvindex.Revisions(key, end, rev)
-	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
 	}
@@ -167,7 +167,7 @@ func (tr *storeTxnRead) rangeKeys(key, end []byte, curRev int64, ro RangeOptions
 			}
 		}
 	}
-	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
 }
 

pkg/traceutil/trace.go

@@ -1,3 +1,18 @@
+// Copyright 2019 The etcd Authors
+//
+// 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,
+// 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 traceutil implements tracing utilities using "context".
 package traceutil
 
 import (
@@ -7,13 +22,10 @@ import (
 	"math/rand"
 	"time"
 
-	"github.com/coreos/pkg/capnslog"
 	"go.uber.org/zap"
 )
 
-var (
-	plog = capnslog.NewPackageLogger("go.etcd.io/etcd", "trace")
-)
+const CtxKey = "trace"
 
 // Field is a kv pair to record additional details of the trace.
 type Field struct {
@@ -40,6 +52,7 @@ func writeFields(fields []Field) string {
 
 type Trace struct {
 	operation string
+	lg        *zap.Logger
 	fields    []Field
 	startTime time.Time
 	steps     []step
@@ -51,32 +64,22 @@ type step struct {
 	fields []Field
 }
 
-func New(op string, fields ...Field) *Trace {
-	return &Trace{operation: op, startTime: time.Now(), fields: fields}
+func New(op string, lg *zap.Logger, fields ...Field) *Trace {
+	return &Trace{operation: op, lg: lg, startTime: time.Now(), fields: fields}
 }
 
-// traceutil.TODO() returns a non-nil, empty Trace
+// TODO returns a non-nil, empty Trace
 func TODO() *Trace {
 	return &Trace{}
 }
 
 func Get(ctx context.Context) *Trace {
-	if trace, ok := ctx.Value("trace").(*Trace); ok && trace != nil {
+	if trace, ok := ctx.Value(CtxKey).(*Trace); ok && trace != nil {
 		return trace
 	}
 	return TODO()
 }
 
-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})
 }
@@ -88,48 +91,47 @@ func (t *Trace) AddField(fields ...Field) {
 }
 
 // Log dumps all steps in the Trace
-func (t *Trace) Log(lg *zap.Logger) {
-	t.LogWithStepThreshold(0, lg)
+func (t *Trace) Log() {
+	t.LogWithStepThreshold(0)
 }
 
 // LogIfLong dumps logs if the duration is longer than threshold
-func (t *Trace) LogIfLong(threshold time.Duration, lg *zap.Logger) {
+func (t *Trace) LogIfLong(threshold time.Duration) {
 	if time.Since(t.startTime) > threshold {
 		stepThreshold := threshold / time.Duration(len(t.steps)+1)
-		t.LogWithStepThreshold(stepThreshold, lg)
+		t.LogWithStepThreshold(stepThreshold)
 	}
 }
 
 // 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) LogWithStepThreshold(threshold time.Duration) {
+	msg, fs := t.logInfo(threshold)
+	if t.lg != nil {
+		t.lg.Info(msg, fs...)
 	}
 }
 
-func (t *Trace) format(threshold time.Duration) string {
+func (t *Trace) logInfo(threshold time.Duration) (string, []zap.Field) {
 	endTime := time.Now()
 	totalDuration := endTime.Sub(t.startTime)
-	var buf bytes.Buffer
 	traceNum := rand.Int31()
+	msg := fmt.Sprintf("trace[%d] %s", traceNum, t.operation)
 
-	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")))
+	var steps []string
 	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",
+			steps = append(steps, fmt.Sprintf("trace[%d] step '%v' %s (duration: %v)",
 				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()
+	fs := []zap.Field{zap.String("detail", writeFields(t.fields)),
+		zap.Duration("duration", totalDuration),
+		zap.Time("start", t.startTime),
+		zap.Time("end", endTime),
+		zap.Strings("steps", steps)}
+	return msg, fs
 }