sql: enhance the handling of internal errors, add sentry reporting by knz · Pull Request #35820 · cockroachdb/cockroach

knz · 2019-03-16T12:22:35Z

Subsumes #35826.
Subsumes #35823.

This PR achieves the following:

(jordan) removes the stack trace from the telemetry counters
(roadmap) encloses a stack trace in pgerror.Error objects
(roadmap) reports the details of pgerrors with CodeInternalError to sentry
(radu) shows these details when an internal error is encountered in logic tests
(radu) shows these details when a pgerror is printed somewhere else with printf("%+v", err)
(bug fix) fixes the crash reporting enable flag (detection was broken)

cockroach-teamcity · 2019-03-16T12:22:49Z

This change is

Before: ``` testdata/logic_test/assertion_error:4: expected success, but found crdb_internal.force_assertion_error(): internal error: woo ``` After (for example, after cockroachdb#35820 is separately applied): ``` testdata/logic_test/assertion_error:4: expected success, but found (XX000) crdb_internal.force_assertion_error(): internal error: woo sql/sem/builtins/builtins.go:2815: in func211() DETAIL: stack trace: github.com/cockroachdb/cockroach/pkg/sql/sem/builtins/builtins.go:2815: in func211() github.com/cockroachdb/cockroach/pkg/sql/sem/tree/eval.go:3651: in Eval() github.com/cockroachdb/cockroach/pkg/sql/distsqlrun/expr.go:196: in eval() github.com/cockroachdb/cockroach/pkg/sql/distsqlrun/processors.go:375: in ProcessRow() github.com/cockroachdb/cockroach/pkg/sql/distsqlrun/processors.go:778: in ProcessRowHelper() github.com/cockroachdb/cockroach/pkg/sql/distsqlrun/values.go:126: in Next() github.com/cockroachdb/cockroach/pkg/sql/distsqlrun/base.go:174: in Run() github.com/cockroachdb/cockroach/pkg/sql/distsqlrun/processors.go:801: in Run() github.com/cockroachdb/cockroach/pkg/sql/distsqlrun/flow.go:627: in Run() github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:252: in Run() github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:839: in PlanAndRun() github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1112: in execWithDistSQLEngine() github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:948: in dispatchToExecutionEngine() github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:456: in execStmtInOpenState() github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:102: in execStmt() github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1178: in run() github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:429: in ServeConn() github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:337: in func4() NOTE: internal errors may have more details in log. Use -show-logs. ``` Release note: None

35827: sql/logictest: reveal error details if present r=knz a=knz Before: ``` testdata/logic_test/assertion_error:4: expected success, but found crdb_internal.force_assertion_error(): internal error: woo ``` After (for example, after #35820 is separately applied): ``` testdata/logic_test/assertion_error:4: expected success, but found (XX000) crdb_internal.force_assertion_error(): internal error: woo sql/sem/builtins/builtins.go:2815: in func211() DETAIL: stack trace: github.com/cockroachdb/cockroach/pkg/sql/sem/builtins/builtins.go:2815: in func211() github.com/cockroachdb/cockroach/pkg/sql/sem/tree/eval.go:3651: in Eval() github.com/cockroachdb/cockroach/pkg/sql/distsqlrun/expr.go:196: in eval() github.com/cockroachdb/cockroach/pkg/sql/distsqlrun/processors.go:375: in ProcessRow() github.com/cockroachdb/cockroach/pkg/sql/distsqlrun/processors.go:778: in ProcessRowHelper() github.com/cockroachdb/cockroach/pkg/sql/distsqlrun/values.go:126: in Next() github.com/cockroachdb/cockroach/pkg/sql/distsqlrun/base.go:174: in Run() github.com/cockroachdb/cockroach/pkg/sql/distsqlrun/processors.go:801: in Run() github.com/cockroachdb/cockroach/pkg/sql/distsqlrun/flow.go:627: in Run() github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:252: in Run() github.com/cockroachdb/cockroach/pkg/sql/distsql_running.go:839: in PlanAndRun() github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:1112: in execWithDistSQLEngine() github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:948: in dispatchToExecutionEngine() github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:456: in execStmtInOpenState() github.com/cockroachdb/cockroach/pkg/sql/conn_executor_exec.go:102: in execStmt() github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:1178: in run() github.com/cockroachdb/cockroach/pkg/sql/conn_executor.go:429: in ServeConn() github.com/cockroachdb/cockroach/pkg/sql/pgwire/conn.go:337: in func4() NOTE: internal errors may have more details in log. Use -show-logs. ``` Release note: None Co-authored-by: Raphael 'kena' Poss <knz@cockroachlabs.com>

35822: sql: add a missing comment r=knz a=knz This goes alongside #35820. Release note: None Co-authored-by: Raphael 'kena' Poss <knz@cockroachlabs.com>

... like it had always been intended. Release note: None

RaduBerinde

Very nice work, thank you! This gets us all the benefits we had with panics but without actually crashing!

Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @jordanlewis, @knz, and @RaduBerinde)

pkg/sql/pgwire/pgerror/errors.go, line 295 at r5 (raw file):

}

// Format implements the fmt.Formatter interface.

[nit] Add to this comment and explain the three variations v, +v, s. It's important because it's not common for %sand%v` to be different.

pkg/sql/pgwire/pgerror/errors.go, line 299 at r5 (raw file):

	switch verb {
	case 'v':
		switch {

[nit] switch with a single case should be if. Or just put them all in a big switch with

case verb == 'v' && s.Flag('+'):
case verb == 'v':
case verb == 's':

pkg/sql/pgwire/pgerror/errors.go, line 318 at r5 (raw file):

	case 's':
		fmt.Fprintf(s, "%s", pg.Message)
	}

What is this supposed to return if the verb is bad? Unfortunately this interface is poorly documented in fmt.

pkg/sql/pgwire/pgerror/errors.proto, line 50 at r5 (raw file):

  }

  // complement to the detail field that can be reported

[nit] explicitly mention that all info is scrubbed

Release note: None

The `depth` argument wasn't incremented properly, causing one level to be lost. Release note: None

We wish to embed stack traces in Sentry reports for internal errors. However, since internal errors flow through RPCs as protobufs and raven.Stacktrace objects (used for Sentry reports) do not have a protobuf encoding, we want another serialization format. This patch provides this by means of an encapsulation of `raven.Stacktrace` as `log.StackTrace`, with working `Encode`/`Decode` methods. Release note: None

This patch splits `log.SendCrashReport` into the following pieces: - `log.ShouldSendReport` tests whether a report should be assembled+sent; - `log.SendReport` sends a report from a message and zero or more reportalbe objects. - `log.ReportableObject` aliases `raven.Interface` and is instantiated by: - `log.NewReportableMessage()` for simple strings. - `log.NewException()` for string + stack trace. Release note: None

knz

Reviewable status: complete! 0 of 0 LGTMs obtained (and 1 stale) (waiting on @jordanlewis and @RaduBerinde)

pkg/sql/pgwire/pgerror/errors.go, line 295 at r5 (raw file):

Previously, RaduBerinde wrote…

[nit] Add to this comment and explain the three variations v, +v, s. It's important because it's not common for %sand%v` to be different.

I changed it back - it was breaking otherwise.

pkg/sql/pgwire/pgerror/errors.go, line 299 at r5 (raw file):

Previously, RaduBerinde wrote…

[nit] switch with a single case should be if. Or just put them all in a big switch with
case verb == 'v' && s.Flag('+'):
case verb == 'v':
case verb == 's':

Done.

pkg/sql/pgwire/pgerror/errors.go, line 318 at r5 (raw file):

Previously, RaduBerinde wrote…

What is this supposed to return if the verb is bad? Unfortunately this interface is poorly documented in fmt.

Then nothing is printed. That's the way the errors package does it, so I'm not asking further questions.

pkg/sql/pgwire/pgerror/errors.proto, line 50 at r5 (raw file):

Previously, RaduBerinde wrote…

[nit] explicitly mention that all info is scrubbed

Done.

RaduBerinde · 2019-03-17T11:37:43Z

pkg/sql/pgwire/pgerror/errors.go, line 295 at r5 (raw file):

Previously, knz (kena) wrote…

I changed it back - it was breaking otherwise.

Ok, great. I actually hit this in a test where I had to change %s to %v which felt strange.

Still worth a comment mentioning that %s / %v show the error message and %+v shows details as well (+v is not particularly well documented in fmt, it just says "when printing structs, the plus flag (%+v) adds field names").

knz

Reviewable status: complete! 0 of 0 LGTMs obtained (and 1 stale) (waiting on @jordanlewis and @RaduBerinde)

pkg/sql/pgwire/pgerror/errors.go, line 295 at r5 (raw file):

Previously, RaduBerinde wrote…

Ok, great. I actually hit this in a test where I had to change %s to %v which felt strange.

Still worth a comment mentioning that %s / %v show the error message and %+v shows details as well (+v is not particularly well documented in fmt, it just says "when printing structs, the plus flag (%+v) adds field names").

Added the comment.

knz · 2019-03-17T12:00:47Z

This PR is more or less complete, but I want to get a green build on #35821 to verify that the API changes here are good.

knz · 2019-03-17T22:53:07Z

It was a good idea to iterate on the other PR before merging this one. I discovered that the pgerror.Wrap functions were not well defined:

they should return nil if given a nil err as input (that's how errors.Wrap is used in many places)
because they must return a nil interface reference, they can't return *Error -- a nil *Error is turned into a non-nil error, and that breaks things badly.

Adjusted the PR accordingly, with an explanatory comment.

knz · 2019-03-18T00:24:54Z

Another "oops" caught by the other PR: the result message for
pgerror.Wrap(errors.Wrap(pgerror.NewError("x", "a"), "b"), "c")

should be c: b: a, not c: a.

Fixed (also added a test).

knz · 2019-03-18T00:36:22Z

Yet another "oops" caught in tests:

pgerror.Wrapf(err, CodeDataExceptionError, ...) is meant to add the pg code if err didn't have one already.

However if err is a non-pg retry error, we want the retry error code to prevail over the one provided to Wrapf.

I modified the logic accordingly to preserve retry errors + ambiguity errors.

This patch achieves the following: - it extends the pgerror.Error object with a new field `SafeDetail`, aimed to contain non-PII details and thuis suitable for inclusion in reporting. - it populates the scrubbed format + safe arguments of error messages in `SafeDetail` using the same logic as `log.ReportablesToSafeError`. - it captures the stack trace in `SafeDetail` but also `Detail` so that a human user seeing the error can report the stack trace with a manually created issue. - it extends `pgerror.Wrapf()` so as to combine details in an existing error with the details of the point that calls `pgerror.Wrapf()`. - it provides a custom `fmt.Formatter` for `pgerror.Error`, so that: - `%#v` will now print the pg error code in addition to the message; - `%+v` will now print the source, code, message and stored `SafeDetail`. Release note: None

This patch ensures that a sentry report is created when a pg error with CodeInternalError flows out of the execution layers. Release note: None

35821: sql,*: error handling improvements r=knz a=knz Subsumes #35825. Subsumes #35820. This PR replaces uses of `errors.New`, `errors.Errorf` and `errors.Wrap` by their `pgerror` equivalents. It also embeds the subsumed PRs; see those PR's discussion for details. Co-authored-by: Raphael 'kena' Poss <knz@cockroachlabs.com>

RaduBerinde · 2019-03-18T12:34:26Z

pkg/sql/pgwire/pgerror/wrap.go, line 82 at r12 (raw file):

		// We'll want to report what we can from the provided context.
		st := log.NewStackTrace(depth + 1)

If the error already was CodeInternalError and had a stack trace, do we need to embed another stack trace every time we wrap it?

knz · 2019-03-18T13:10:50Z

If the error already was CodeInternalError and had a stack trace, do we need to embed another stack trace every time we wrap it?

knz · 2019-03-18T13:13:58Z

If the error already was CodeInternalError and had a stack trace, do we need to embed another stack trace every time we wrap it?

As I was debugging a couple of things I discovered that error objects do not simply flow on return paths, they also move horizontally in code (i.e. passed "down" to function calls) and also across the network (distsql).

capturing the wrap stack traces gives a better idea of the paths taken through the code by an error.

knz requested review from a team, RaduBerinde and jordanlewis March 16, 2019 12:22

knz requested a review from a team as a code owner March 16, 2019 12:22

knz requested review from a team March 16, 2019 12:22

knz force-pushed the 20190315-int-errs branch from eb7ea5f to d6370a9 Compare March 16, 2019 12:24

knz force-pushed the 20190315-int-errs branch from 9426d64 to 076ea94 Compare March 16, 2019 13:07

knz mentioned this pull request Mar 16, 2019

sql/logictest: reveal error details if present #35827

Merged

knz force-pushed the 20190315-int-errs branch from 076ea94 to e0f9b64 Compare March 16, 2019 13:14

knz force-pushed the 20190315-int-errs branch from e0f9b64 to 4fac91d Compare March 16, 2019 13:36

craig bot pushed a commit that referenced this pull request Mar 16, 2019

Merge #35822

6d30e71

35822: sql: add a missing comment r=knz a=knz This goes alongside #35820. Release note: None Co-authored-by: Raphael 'kena' Poss <knz@cockroachlabs.com>

pgwire: rename Error.InternalCommand to TelemetryKey

208075d

... like it had always been intended. Release note: None

RaduBerinde approved these changes Mar 16, 2019

View reviewed changes

knz force-pushed the 20190315-int-errs branch from 4fac91d to 19a5391 Compare March 17, 2019 00:46

knz added 4 commits March 17, 2019 10:11

util/log: properly detect when crash reporting is disabled

dc78949

Release note: None

util/log: ensure that ReportablesToSafeError capture the caller

0514943

The `depth` argument wasn't incremented properly, causing one level to be lost. Release note: None

knz force-pushed the 20190315-int-errs branch 2 times, most recently from e5c55f1 to 7810506 Compare March 17, 2019 11:02

knz commented Mar 17, 2019

View reviewed changes

knz force-pushed the 20190315-int-errs branch from 7810506 to b72f746 Compare March 17, 2019 11:59

knz force-pushed the 20190315-int-errs branch 2 times, most recently from e87789c to 2779d6f Compare March 17, 2019 22:50

knz force-pushed the 20190315-int-errs branch from 2779d6f to b9d9e67 Compare March 18, 2019 00:23

knz force-pushed the 20190315-int-errs branch from b9d9e67 to ccb7ead Compare March 18, 2019 00:34

knz added 2 commits March 18, 2019 01:55

sql: report internal errors to sentry

a6ef12c

This patch ensures that a sentry report is created when a pg error with CodeInternalError flows out of the execution layers. Release note: None

knz force-pushed the 20190315-int-errs branch from ccb7ead to a6ef12c Compare March 18, 2019 00:55

craig bot merged commit a6ef12c into cockroachdb:master Mar 18, 2019

knz deleted the 20190315-int-errs branch March 18, 2019 07:10

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

sql: enhance the handling of internal errors, add sentry reporting#35820

sql: enhance the handling of internal errors, add sentry reporting#35820
craig[bot] merged 7 commits intocockroachdb:masterfrom
knz:20190315-int-errs

knz commented Mar 16, 2019 •

edited

Loading

Uh oh!

cockroach-teamcity commented Mar 16, 2019

Uh oh!

RaduBerinde left a comment

Uh oh!

knz left a comment

Uh oh!

RaduBerinde commented Mar 17, 2019

Uh oh!

knz left a comment

Uh oh!

knz commented Mar 17, 2019

Uh oh!

knz commented Mar 17, 2019

Uh oh!

knz commented Mar 18, 2019 •

edited

Loading

Uh oh!

knz commented Mar 18, 2019 •

edited

Loading

Uh oh!

RaduBerinde commented Mar 18, 2019

Uh oh!

knz commented Mar 18, 2019

Uh oh!

knz commented Mar 18, 2019

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Conversation

knz commented Mar 16, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

cockroach-teamcity commented Mar 16, 2019

Uh oh!

RaduBerinde left a comment

Choose a reason for hiding this comment

Uh oh!

knz left a comment

Choose a reason for hiding this comment

Uh oh!

RaduBerinde commented Mar 17, 2019

Uh oh!

knz left a comment

Choose a reason for hiding this comment

Uh oh!

knz commented Mar 17, 2019

Uh oh!

knz commented Mar 17, 2019

Uh oh!

knz commented Mar 18, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

knz commented Mar 18, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

RaduBerinde commented Mar 18, 2019

Uh oh!

knz commented Mar 18, 2019

Uh oh!

knz commented Mar 18, 2019

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

knz commented Mar 16, 2019 •

edited

Loading

knz commented Mar 18, 2019 •

edited

Loading

knz commented Mar 18, 2019 •

edited

Loading