From 21114c080ee85b7fac30f9bc0dedfadc1e602346 Mon Sep 17 00:00:00 2001 From: ChinYing-Li Date: Sat, 20 Mar 2021 14:23:15 +0800 Subject: [PATCH 1/2] Flag a span with error if its log level is set to Error (#3995) Signed-off-by: ChinYing-Li --- CHANGELOG.md | 1 + pkg/chunk/cache/memcached.go | 1 - pkg/querier/queryrange/results_cache.go | 1 - pkg/testexporter/correctness/simple.go | 3 +- pkg/util/spanlogger/spanlogger.go | 37 +++++++++++++++++-------- pkg/util/spanlogger/spanlogger_test.go | 5 ++-- 6 files changed, 30 insertions(+), 18 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 515a909b2e0..56f3d8391a3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -17,6 +17,7 @@ * `cortex_ruler_client_request_duration_seconds` * [ENHANCEMENT] Query-frontend/scheduler: added querier forget delay (`-query-frontend.querier-forget-delay` and `-query-scheduler.querier-forget-delay`) to mitigate the blast radius in the event queriers crash because of a repeatedly sent "query of death" when shuffle-sharding is enabled. #3901 * [ENHANCEMENT] Ingester: reduce CPU and memory when an high number of errors are returned by the ingester on the write path with the blocks storage. #3969 #3971 #3973 +* [ENHANCEMENT] Tracing: flag a span with error if its log level is set to Error. #3995 * [BUGFIX] Distributor: reverted changes done to rate limiting in #3825. #3948 * [BUGFIX] Ingester: Fix race condition when opening and closing tsdb concurrently. #3959 * [BUGFIX] Querier: streamline tracing spans. #3924 diff --git a/pkg/chunk/cache/memcached.go b/pkg/chunk/cache/memcached.go index c60d624e407..565958f0cac 100644 --- a/pkg/chunk/cache/memcached.go +++ b/pkg/chunk/cache/memcached.go @@ -158,7 +158,6 @@ func (c *Memcached) fetch(ctx context.Context, keys []string) (found []string, b // Memcached returns partial results even on error. if err != nil { - log.Error(err) level.Error(log).Log("msg", "Failed to get keys from memcached", "err", err) } return err diff --git a/pkg/querier/queryrange/results_cache.go b/pkg/querier/queryrange/results_cache.go index 2f0e9912cd8..bbff7083b04 100644 --- a/pkg/querier/queryrange/results_cache.go +++ b/pkg/querier/queryrange/results_cache.go @@ -558,7 +558,6 @@ func (s resultsCache) get(ctx context.Context, key string) ([]Extent, bool) { if err := proto.Unmarshal(bufs[0], &resp); err != nil { level.Error(log).Log("msg", "error unmarshalling cached value", "err", err) - log.Error(err) return nil, false } diff --git a/pkg/testexporter/correctness/simple.go b/pkg/testexporter/correctness/simple.go index 6018d35b4c3..a052eb30a50 100644 --- a/pkg/testexporter/correctness/simple.go +++ b/pkg/testexporter/correctness/simple.go @@ -176,8 +176,7 @@ func verifySamples(log *spanlogger.SpanLogger, tc Case, pairs []model.SamplePair } 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.Error(fmt.Errorf("wrong number of samples")) + level.Error(log).Log("msg", "wrong number of samples", "expected", expectedNumSamples, "actual", len(pairs), "err", fmt.Errorf("wrong number of samples")) return false } } diff --git a/pkg/util/spanlogger/spanlogger.go b/pkg/util/spanlogger/spanlogger.go index 4b6131d45c6..94b28481797 100644 --- a/pkg/util/spanlogger/spanlogger.go +++ b/pkg/util/spanlogger/spanlogger.go @@ -2,7 +2,7 @@ package spanlogger import ( "context" - + "github.com/go-kit/kit/log" "github.com/go-kit/kit/log/level" opentracing "github.com/opentracing/opentracing-go" @@ -77,6 +77,31 @@ func FromContextWithFallback(ctx context.Context, fallback log.Logger) *SpanLogg // also puts the on the spans. func (s *SpanLogger) Log(kvps ...interface{}) error { s.Logger.Log(kvps...) + + var logAsError = false + errorIndex := -1 + for i := 0; i < len(kvps) - 1; i += 2 { + // Find out whether to log as error + if kvps[i] == level.Key() { + logAsError = kvps[i+1] == level.ErrorValue() + if !logAsError { + break + } + ext.Error.Set(s.Span, true) + } else if errorIndex == -1 { + // Check if this is the error we want to log + if _, ok := kvps[i+1].(error); ok && (kvps[i] == "err" || kvps[i] == "error") { + errorIndex = i + } + } + if logAsError && errorIndex != -1 { + s.Span.LogFields(otlog.Error(kvps[i+1].(error))) + // Remove the already logged error + kvps = append(kvps[:i], kvps[i+2:]...) + break + } + } + fields, err := otlog.InterleavedKVToFields(kvps...) if err != nil { return err @@ -84,13 +109,3 @@ func (s *SpanLogger) Log(kvps ...interface{}) error { s.Span.LogFields(fields...) return nil } - -// 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 - } - ext.Error.Set(s.Span, true) - s.Span.LogFields(otlog.Error(err)) - return err -} diff --git a/pkg/util/spanlogger/spanlogger_test.go b/pkg/util/spanlogger/spanlogger_test.go index fbea0cb2633..b155072dc8e 100644 --- a/pkg/util/spanlogger/spanlogger_test.go +++ b/pkg/util/spanlogger/spanlogger_test.go @@ -14,11 +14,10 @@ func TestSpanLogger_Log(t *testing.T) { _ = span.Log("foo") newSpan := FromContext(ctx) require.Equal(t, span.Span, newSpan.Span) - _ = newSpan.Log("bar") + require.Error(t, newSpan.Log("bar", "err", errors.New("err"), "metric2", 2)) noSpan := FromContext(context.Background()) _ = noSpan.Log("foo") - require.Error(t, noSpan.Error(errors.New("err"))) - require.NoError(t, noSpan.Error(nil)) + require.NoError(t, noSpan.Log("metric1", 1, "err", errors.New("err"), "metric2", 2)) } func TestSpanLogger_CustomLogger(t *testing.T) { From 7d8844160981815e35b7ebb57a6a4733033f94f3 Mon Sep 17 00:00:00 2001 From: ChinYing-Li Date: Wed, 28 Apr 2021 14:10:21 -0400 Subject: [PATCH 2/2] Restore SpanLogger.Error as it is still used Signed-off-by: ChinYing-Li --- pkg/util/spanlogger/spanlogger.go | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/pkg/util/spanlogger/spanlogger.go b/pkg/util/spanlogger/spanlogger.go index 94b28481797..8a032fc9e36 100644 --- a/pkg/util/spanlogger/spanlogger.go +++ b/pkg/util/spanlogger/spanlogger.go @@ -2,7 +2,7 @@ package spanlogger import ( "context" - + "github.com/go-kit/kit/log" "github.com/go-kit/kit/log/level" opentracing "github.com/opentracing/opentracing-go" @@ -80,7 +80,7 @@ func (s *SpanLogger) Log(kvps ...interface{}) error { var logAsError = false errorIndex := -1 - for i := 0; i < len(kvps) - 1; i += 2 { + for i := 0; i < len(kvps)-1; i += 2 { // Find out whether to log as error if kvps[i] == level.Key() { logAsError = kvps[i+1] == level.ErrorValue() @@ -109,3 +109,13 @@ func (s *SpanLogger) Log(kvps ...interface{}) error { s.Span.LogFields(fields...) return nil } + +// 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 + } + ext.Error.Set(s.Span, true) + s.Span.LogFields(otlog.Error(err)) + return err +}