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

cstyan · 2020-07-31T19:06:23Z

It's very confusing to look at a trace UI for two traces that seemed to have failed for the same reason, yet one has error ! icons and the other doesn't. This seems to be a side effect of not setting error=true on all error cases, and one case where we had error="a string".

There's also a change required in upstream weaveworks/common to add another error=true

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

cc @gouthamve @gotjosh @joe-elliott

Checklist

Tests updated
Documentation added
CHANGELOG.md updated - the order of entries should be [CHANGE], [FEATURE], [ENHANCEMENT], [BUGFIX]

pstibrany · 2020-07-31T20:05:09Z

Isn’t this better solved by consistently using spanlogger that we use elsewhere?

cstyan · 2020-07-31T20:10:21Z

Good point, looks like spanlogger Error via opentracings ext.Error.Set(s.Span, true) should solve most of this for us.

pracucci

@cstyan Thanks for fixing this. I left few comments.

Could you fix the linter, please? For the error Error return value of log.Error is not checked (errcheck) you could just add it to the ignore list defined in .errcheck-exclude (we don't want to check errors from logger)

pkg/chunk/cache/memcached.go

pkg/chunk/gcp/bigtable_index_client.go

pkg/chunk/cache/memcached.go

pracucci · 2020-08-03T06:42:04Z

pkg/querier/queryrange/query_range.go

-
-	sp, _ := opentracing.StartSpanFromContext(ctx, "ParseQueryRangeResponse")
-	defer sp.Finish()
+	log, _ := spanlogger.New(ctx, "ParseQueryRangeResponse")


New span here. Should replace the context, no?

I'm basing this off how we used the ot library sp, _ := opentracing.StartSpanFromContext(ctx, "ParseQueryRangeResponse"), where we ignored the returned context. I don't know the historical reason behind doing it that way, so if you think it should change here with the introduction of spanlogger that's fine by me.

I think the reason is that ctx is not used below within this function. I believe replacing it is more future proof to avoid mistakes (we should do it once we'll start using ctx below and it's easy to forget to do it).

pkg/querier/queryrange/results_cache.go

pracucci · 2020-08-03T06:43:29Z

pkg/testexporter/correctness/simple.go

@@ -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 value"))


Isn't the previous message "wrong number of samples" more correct? It's also what we log.

pracucci · 2020-08-03T06:43:44Z

pkg/testexporter/correctness/simple.go

 			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 value"))


Same comment here

cstyan · 2020-08-05T03:36:28Z

Thanks for the review @pracucci, I've replied to the comments that are still open, let me know what you think.

cstyan · 2020-08-10T05:51:58Z

@pracucci can you let me know your preferences re: my replies to your comments?

pracucci

Thanks @cstyan for patiently addressing my feedback 🙏 Your comment about logging is right. I left few minor comments and then we should be good to go.

pracucci · 2020-08-10T08:27:38Z

pkg/chunk/cache/memcached.go


 		// 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) //nolint:errcheck


I believe we shouldn't repeat this nolint comment wherever we use log.Error() but add it to .errcheck-exclude. What do you think?

I couldn't get that to work properly, for various variations of (import path.Struct).Function. If you have a suggestion for what to use as the entry in that file let me know.

Please see the latest commit as well, if we want to have the ctx assignment in the bigtable index client for example, we need nolint comments again.

I think (*github.com/cortexproject/cortex/pkg/util/spanlogger.SpanLogger).Error should work (it does with standalone errcheck utility). When I update golangci-lint in the build image to 1.30.0, I no longer see this warning, even without changing .errcheck-exclude. 😕

We could also remove error return value from this method, since no production code uses it.

pkg/testexporter/correctness/simple.go

pkg/chunk/cache/memcached.go

pkg/chunk/gcp/bigtable_index_client.go

pracucci · 2020-08-10T09:09:21Z

pkg/querier/queryrange/query_range.go

-
-	sp, _ := opentracing.StartSpanFromContext(ctx, "ParseQueryRangeResponse")
-	defer sp.Finish()
+	log, _ := spanlogger.New(ctx, "ParseQueryRangeResponse")


I think the reason is that ctx is not used below within this function. I believe replacing it is more future proof to avoid mistakes (we should do it once we'll start using ctx below and it's easy to forget to do it).

pkg/querier/queryrange/results_cache.go

pstibrany · 2020-08-10T11:07:06Z

While doing this change, would it make sense to move error-marking to Log method? If passed level is error, we would mark span with error flag, and if there is any error object passed, we would wrap first one into otlog.Error.

This would also make (*SpanLogger).Error(error) method unnecessary.

(I thought it already works this way when making my earlier suggestion, but that doesn't seem to be the case)

cstyan · 2020-08-10T18:45:06Z

Thanks for the review again @pracucci I think everything is updated correctly now. There's just the lint exclusion left, I was not able to get an entry into the file that worked locally, which is why I went with the nolint comments.

@pstibrany are you referring to the spanloggers Log function? That's just a wrapper for go-kit/log's Log, which has no notion of log level since that's done via the go-kit/log/levels wrappers. So there isn't actually any Log(msg, level) that could take error and log to error level and add the correct error tag to the span. Think we should just stick with compatibility with the logger we use.

pkg/chunk/gcp/bigtable_index_client.go

error, this is so we consistently have the error=true tag set. Signed-off-by: Callum Styan <[email protected]>

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

pstibrany · 2020-08-10T19:09:19Z

@pstibrany are you referring to the spanloggers Log function? That's just a wrapper for go-kit/log's Log, which has no notion of log level since that's done via the go-kit/log/levels wrappers. So there isn't actually any Log(msg, level) that could take error and log to error level and add the correct error tag to the span. Think we should just stick with compatibility with the logger we use.

Yes, I'm referring to Log function. Log level is passed as just another key-value pair to that method (key being level.Key() and value being level.ErrorValue() for errors), and Log method is already processing all key-value pairs inside, so it can as well understand this special combination. I think it's worth exploring.

attempt to avoid use of the incorrect ctx in the future. Signed-off-by: Callum Styan <[email protected]>

cstyan · 2020-08-10T23:27:36Z

Yes, I'm referring to Log function. Log level is passed as just another key-value pair to that method (key being level.Key() and value being level.ErrorValue() for errors), and Log method is already processing all key-value pairs inside, so it can as well understand this special combination. I think it's worth exploring.

Oh interesting, TIL. Good find, yeah we could then check kvps for a level=error combination and set the tag on the span. The question would be whether we want to assign all kvps as fields on the span as tags or log messages, or just look for a second field err or error.

Are you okay if I just open a new issue to look into this, instead of doing it as part of this PR? Having the error tags in general is going to help with debugging the ruler already, which is what prompted me to make this change.

pstibrany

Oh interesting, TIL. Good find, yeah we could then check kvps for a level=error combination and set the tag on the span. The question would be whether we want to assign all kvps as fields on the span as tags or log messages, or just look for a second field err or error.

Log method already adds all kvps as fields to the span, but doesn't mark span with error flag, and doesn't use correct key for error value.

Are you okay if I just open a new issue to look into this, instead of doing it as part of this PR? Having the error tags in general is going to help with debugging the ruler already, which is what prompted me to make this change.

👍

pkg/chunk/gcp/bigtable_index_client.go

pstibrany · 2020-08-11T11:40:19Z

pkg/chunk/cache/memcached.go


 		// 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) //nolint:errcheck


I think (*github.com/cortexproject/cortex/pkg/util/spanlogger.SpanLogger).Error should work (it does with standalone errcheck utility). When I update golangci-lint in the build image to 1.30.0, I no longer see this warning, even without changing .errcheck-exclude. 😕

We could also remove error return value from this method, since no production code uses it.

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

pracucci · 2020-08-11T16:11:07Z

@cstyan I've pushed a commit to try to globally exclude SpanLogger.Error() from errcheck (it works on my local machine, let's see what CI says...).

pracucci

LGTM! @pstibrany do you have any other comment?

pull-request-size bot added the size/S label Jul 31, 2020

gotjosh approved these changes Jul 31, 2020

View reviewed changes

pull-request-size bot added size/M and removed size/S labels Jul 31, 2020

pracucci reviewed Aug 3, 2020

View reviewed changes

pracucci reviewed Aug 10, 2020

View reviewed changes

cstyan commented Aug 10, 2020

View reviewed changes

pkg/chunk/gcp/bigtable_index_client.go Show resolved Hide resolved

cstyan added 4 commits August 10, 2020 11:48

Make use of spanlogger when functions that generate spans result in an

706985c

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

2935b45

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

Review cleanup.

b51ed19

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

Address more review feedback.

b5a91b6

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

We need nolint comments on these lines if we want to assign the ctx in

075f07c

attempt to avoid use of the incorrect ctx in the future. Signed-off-by: Callum Styan <[email protected]>

pstibrany reviewed Aug 11, 2020

View reviewed changes

Globally exclude SpanLogger.Error() errcheck

f2d02ea

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

pracucci approved these changes Aug 11, 2020

View reviewed changes

pstibrany approved these changes Aug 11, 2020

View reviewed changes

cstyan mentioned this pull request Aug 11, 2020

spanlogger Log should call Error if log level is error #3016

Open

pracucci merged commit 03165e8 into cortexproject:master Aug 12, 2020

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

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

Uh oh!

Conversation

cstyan commented Jul 31, 2020

Uh oh!

pstibrany commented Jul 31, 2020

Uh oh!

cstyan commented Jul 31, 2020

Uh oh!

pracucci left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

cstyan commented Aug 5, 2020

Uh oh!

cstyan commented Aug 10, 2020

Uh oh!

pracucci left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

pstibrany commented Aug 10, 2020

Uh oh!

cstyan commented Aug 10, 2020

Uh oh!

Uh oh!

pstibrany commented Aug 10, 2020

Uh oh!

cstyan commented Aug 10, 2020

Uh oh!

pstibrany left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

pracucci commented Aug 11, 2020

Uh oh!

pracucci left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!