Be consistent with span logging, set error=true and use otlog.Error (#2970)

* Make use of spanlogger when functions that generate spans result in an
error, this is so we consistently have the error=true tag set.

Signed-off-by: Callum Styan <[email protected]>

* Add spanlogger Error to errcheck exclude

Signed-off-by: Callum Styan <[email protected]>

* Review cleanup.

Signed-off-by: Callum Styan <[email protected]>

* Address more review feedback.

Signed-off-by: Callum Styan <[email protected]>

* We need nolint comments on these lines if we want to assign the ctx in
attempt to avoid use of the incorrect ctx in the future.

Signed-off-by: Callum Styan <[email protected]>

* Globally exclude SpanLogger.Error() errcheck

Signed-off-by: Marco Pracucci <[email protected]>

Co-authored-by: Marco Pracucci <[email protected]>

Author: cstyan

.errcheck-exclude

@@ -2,4 +2,5 @@ io/ioutil.WriteFile
 io/ioutil.ReadFile
 (github.com/go-kit/kit/log.Logger).Log
 io.Copy
-(github.com/opentracing/opentracing-go.Tracer).Inject
+(github.com/opentracing/opentracing-go.Tracer).Inject
+(*github.com/cortexproject/cortex/pkg/util/spanlogger.SpanLogger).Error

pkg/chunk/cache/memcached.go

@@ -11,13 +11,13 @@ import (
 	"github.com/bradfitz/gomemcache/memcache"
 	"github.com/go-kit/kit/log"
 	"github.com/go-kit/kit/log/level"
-	opentracing "github.com/opentracing/opentracing-go"
 	otlog "github.com/opentracing/opentracing-go/log"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promauto"
 	instr "github.com/weaveworks/common/instrument"
 
 	"github.com/cortexproject/cortex/pkg/util"
+	"github.com/cortexproject/cortex/pkg/util/spanlogger"
 )
 
 type observableVecCollector struct {
@@ -146,19 +146,20 @@ func (c *Memcached) Fetch(ctx context.Context, keys []string) (found []string, b
 
 func (c *Memcached) fetch(ctx context.Context, keys []string) (found []string, bufs [][]byte, missed []string) {
 	var items map[string]*memcache.Item
-	err := instr.CollectedRequest(ctx, "Memcache.GetMulti", c.requestDuration, memcacheStatusCode, func(innerCtx context.Context) error {
-		sp := opentracing.SpanFromContext(innerCtx)
-		sp.LogFields(otlog.Int("keys requested", len(keys)))
+	const method = "Memcache.GetMulti"
+	err := instr.CollectedRequest(ctx, method, c.requestDuration, memcacheStatusCode, func(innerCtx context.Context) error {
+		log, _ := spanlogger.New(innerCtx, method)
+		log.LogFields(otlog.Int("keys requested", len(keys)))
 
 		var err error
 		items, err = c.memcache.GetMulti(keys)
 
-		sp.LogFields(otlog.Int("keys found", len(items)))
+		log.LogFields(otlog.Int("keys found", len(items)))
 
 		// Memcached returns partial results even on error.
 		if err != nil {
-			sp.LogFields(otlog.Error(err))
-			level.Error(c.logger).Log("msg", "Failed to get keys from memcached", "err", err)
+			log.Error(err)
+			level.Error(log).Log("msg", "Failed to get keys from memcached", "err", err)
 		}
 		return err
 	})

pkg/chunk/gcp/bigtable_index_client.go

@@ -13,13 +13,13 @@ import (
 	"cloud.google.com/go/bigtable"
 	"github.com/go-kit/kit/log"
 	ot "github.com/opentracing/opentracing-go"
-	otlog "github.com/opentracing/opentracing-go/log"
 	"github.com/pkg/errors"
 
 	"github.com/cortexproject/cortex/pkg/chunk"
 	chunk_util "github.com/cortexproject/cortex/pkg/chunk/util"
 	"github.com/cortexproject/cortex/pkg/util"
 	"github.com/cortexproject/cortex/pkg/util/grpcclient"
+	"github.com/cortexproject/cortex/pkg/util/spanlogger"
 )
 
 const (
@@ -324,8 +324,8 @@ func (s *storageClientV1) QueryPages(ctx context.Context, queries []chunk.IndexQ
 func (s *storageClientV1) query(ctx context.Context, query chunk.IndexQuery, callback chunk_util.Callback) error {
 	const null = string('\xff')
 
-	sp, ctx := ot.StartSpanFromContext(ctx, "QueryPages", ot.Tag{Key: "tableName", Value: query.TableName}, ot.Tag{Key: "hashValue", Value: query.HashValue})
-	defer sp.Finish()
+	log, ctx := spanlogger.New(ctx, "QueryPages", ot.Tag{Key: "tableName", Value: query.TableName}, ot.Tag{Key: "hashValue", Value: query.HashValue})
+	defer log.Finish()
 
 	table := s.client.Open(query.TableName)
 
@@ -358,7 +358,7 @@ func (s *storageClientV1) query(ctx context.Context, query chunk.IndexQuery, cal
 		return true
 	})
 	if err != nil {
-		sp.LogFields(otlog.String("error", err.Error()))
+		log.Error(err)
 		return errors.WithStack(err)
 	}
 	return nil

pkg/chunk/util/parallel_chunk_fetch.go

@@ -4,10 +4,10 @@ import (
 	"context"
 	"sync"
 
-	ot "github.com/opentracing/opentracing-go"
 	otlog "github.com/opentracing/opentracing-go/log"
 
 	"github.com/cortexproject/cortex/pkg/chunk"
+	"github.com/cortexproject/cortex/pkg/util/spanlogger"
 )
 
 const maxParallel = 1000
@@ -20,9 +20,9 @@ var decodeContextPool = sync.Pool{
 
 // GetParallelChunks fetches chunks in parallel (up to maxParallel).
 func GetParallelChunks(ctx context.Context, chunks []chunk.Chunk, f func(context.Context, *chunk.DecodeContext, chunk.Chunk) (chunk.Chunk, error)) ([]chunk.Chunk, error) {
-	sp, ctx := ot.StartSpanFromContext(ctx, "GetParallelChunks")
-	defer sp.Finish()
-	sp.LogFields(otlog.Int("chunks requested", len(chunks)))
+	log, ctx := spanlogger.New(ctx, "GetParallelChunks")
+	defer log.Finish()
+	log.LogFields(otlog.Int("chunks requested", len(chunks)))
 
 	queuedChunks := make(chan chunk.Chunk)
 
@@ -62,9 +62,9 @@ func GetParallelChunks(ctx context.Context, chunks []chunk.Chunk, f func(context
 		}
 	}
 
-	sp.LogFields(otlog.Int("chunks fetched", len(result)))
+	log.LogFields(otlog.Int("chunks fetched", len(result)))
 	if lastErr != nil {
-		sp.LogFields(otlog.Error(lastErr))
+		log.Error(lastErr)
 	}
 
 	// Return any chunks we did receive: a partial result may be useful

pkg/querier/queryrange/query_range.go

@@ -21,6 +21,7 @@ import (
 
 	"github.com/cortexproject/cortex/pkg/ingester/client"
 	"github.com/cortexproject/cortex/pkg/util"
+	"github.com/cortexproject/cortex/pkg/util/spanlogger"
 )
 
 // StatusSuccess Prometheus success result.
@@ -238,17 +239,16 @@ func (prometheusCodec) DecodeResponse(ctx context.Context, r *http.Response, _ R
 		body, _ := ioutil.ReadAll(r.Body)
 		return nil, httpgrpc.Errorf(r.StatusCode, string(body))
 	}
-
-	sp, _ := opentracing.StartSpanFromContext(ctx, "ParseQueryRangeResponse")
-	defer sp.Finish()
+	log, ctx := spanlogger.New(ctx, "ParseQueryRangeResponse") //nolint:ineffassign,staticcheck
+	defer log.Finish()
 
 	buf, err := ioutil.ReadAll(r.Body)
 	if err != nil {
-		sp.LogFields(otlog.Error(err))
+		log.Error(err)
 		return nil, httpgrpc.Errorf(http.StatusInternalServerError, "error decoding response: %v", err)
 	}
 
-	sp.LogFields(otlog.Int("bytes", len(buf)))
+	log.LogFields(otlog.Int("bytes", len(buf)))
 
 	var resp PrometheusResponse
 	if err := json.Unmarshal(buf, &resp); err != nil {

pkg/querier/queryrange/results_cache.go

@@ -450,14 +450,14 @@ func (s resultsCache) get(ctx context.Context, key string) ([]Extent, bool) {
 	}
 
 	var resp CachedResponse
-	sp, _ := opentracing.StartSpanFromContext(ctx, "unmarshal-extent")
-	defer sp.Finish()
+	log, ctx := spanlogger.New(ctx, "unmarshal-extent") //nolint:ineffassign,staticcheck
+	defer log.Finish()
 
-	sp.LogFields(otlog.Int("bytes", len(bufs[0])))
+	log.LogFields(otlog.Int("bytes", len(bufs[0])))
 
 	if err := proto.Unmarshal(bufs[0], &resp); err != nil {
-		level.Error(s.logger).Log("msg", "error unmarshalling cached value", "err", err)
-		sp.LogFields(otlog.Error(err))
+		level.Error(log).Log("msg", "error unmarshalling cached value", "err", err)
+		log.Error(err)
 		return nil, false
 	}
 

pkg/testexporter/correctness/simple.go

@@ -9,7 +9,6 @@ import (
 	"time"
 
 	"github.com/go-kit/kit/log/level"
-	otlog "github.com/opentracing/opentracing-go/log"
 	v1 "github.com/prometheus/client_golang/api/prometheus/v1"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promauto"
@@ -161,7 +160,7 @@ func verifySamples(log *spanlogger.SpanLogger, tc Case, pairs []model.SamplePair
 		} else {
 			sampleResult.WithLabelValues(tc.Name(), fail).Inc()
 			level.Error(log).Log("msg", "wrong value", "at", pair.Timestamp, "expected", tc.ExpectedValueAt(pair.Timestamp.Time()), "actual", pair.Value)
-			log.LogFields(otlog.Error(fmt.Errorf("wrong value")))
+			log.Error(fmt.Errorf("wrong value"))
 			return false
 		}
 	}
@@ -171,14 +170,14 @@ func verifySamples(log *spanlogger.SpanLogger, tc Case, pairs []model.SamplePair
 		expectedNumSamples := int(duration / cfg.ScrapeInterval)
 		if !epsilonCorrect(float64(len(pairs)), float64(expectedNumSamples), cfg.samplesEpsilon) {
 			level.Error(log).Log("msg", "wrong number of samples", "expected", expectedNumSamples, "actual", len(pairs))
-			log.LogFields(otlog.Error(fmt.Errorf("wrong number of samples")))
+			log.Error(fmt.Errorf("wrong number of samples"))
 			return false
 		}
 	} else {
 		expectedNumSamples := int(duration / cfg.ScrapeInterval)
 		if math.Abs(float64(expectedNumSamples-len(pairs))) > 2 {
 			level.Error(log).Log("msg", "wrong number of samples", "expected", expectedNumSamples, "actual", len(pairs))
-			log.LogFields(otlog.Error(fmt.Errorf("wrong number of samples")))
+			log.Error(fmt.Errorf("wrong number of samples"))
 			return false
 		}
 	}

pkg/util/spanlogger/spanlogger.go

@@ -59,7 +59,7 @@ func (s *SpanLogger) Log(kvps ...interface{}) error {
 	return nil
 }
 
-// Error sets error flag and logs the error, if non-nil.  Returns the err passed in.
+// Error sets error flag and logs the error on the span, if non-nil.  Returns the err passed in.
 func (s *SpanLogger) Error(err error) error {
 	if err == nil {
 		return nil