sql: log AST and plan gist for most sentry reports

This commit adds a method to the `connExecutor` that annotates an
error with the currently-executing statement's AST and plan gist, if
available (saved on the `connExecutor`). This method is now called
before an error is used to build a sentry report in most cases
(i.e. any time an error or panic is propagated up to the `connExecutor`).

Fixes #93285

Release note: None

Author: DrewKimball

pkg/sql/conn_executor.go

@@ -1327,22 +1327,17 @@ func (ex *connExecutor) closeWrapper(ctx context.Context, recovered interface{})
 	if recovered != nil {
 		panicErr := logcrash.PanicAsError(1, recovered)
 
-		// If there's a statement currently being executed, we'll report
-		// on it.
 		if ex.curStmtAST != nil {
 			// A warning header guaranteed to go to stderr.
 			log.SqlExec.Shoutf(ctx, severity.ERROR,
 				"a SQL panic has occurred while executing the following statement:\n%s",
 				// For the log message, the statement is not anonymized.
 				truncateStatementStringForTelemetry(ex.curStmtAST.String()))
-
-			// Embed the statement in the error object for the telemetry
-			// report below. The statement gets anonymized.
-			vt := ex.planner.extendedEvalCtx.VirtualSchemas
-			panicErr = WithAnonymizedStatement(panicErr, ex.curStmtAST, vt)
 		}
 
-		// Report the panic to telemetry in any case.
+		// Report the panic to telemetry, annotating the error with the (anonymized)
+		// currently executed statement and its plan gist, if available.
+		panicErr = ex.WithAnonymizedStatementAndGist(panicErr)
 		logcrash.ReportPanic(ctx, &ex.server.cfg.Settings.SV, panicErr, 1 /* depth */)
 
 		// Close the executor before propagating the panic further.
@@ -1846,9 +1841,13 @@ type connExecutor struct {
 	}
 
 	// curStmtAST is the statement that's currently being prepared or executed, if
-	// any. This is printed by high-level panic recovery.
+	// any. This is printed by high-level panic recovery and sentry reports.
 	curStmtAST tree.Statement
 
+	// curStmtPlanGist is the plan gist of the statement that's currently being
+	// prepared or executed, if any. This is included in sentry reports.
+	curStmtPlanGist redact.SafeString
+
 	// queryCancelKey is a 64-bit identifier for the session used by the
 	// pgwire cancellation protocol.
 	queryCancelKey pgwirecancel.BackendKeyData
@@ -2279,6 +2278,7 @@ func (ex *connExecutor) run(
 
 	for {
 		ex.curStmtAST = nil
+		ex.curStmtPlanGist = ""
 		if err := ctx.Err(); err != nil {
 			return err
 		}
@@ -2670,9 +2670,17 @@ func (ex *connExecutor) execCmd() (retErr error) {
 		if ok {
 			ex.sessionEventf(ctx, "execution error: %s", pe.errorCause())
 			if resErr == nil {
-				res.SetError(pe.errorCause())
+				resErr = pe.errorCause()
+				res.SetError(resErr)
 			}
 		}
+		if resErr != nil &&
+			(pgerror.GetPGCode(resErr) == pgcode.Internal || errors.HasAssertionFailure(resErr)) {
+			// This is an assertion failure / crash that will lead to a sentry report.
+			// Attempt to annotate the error with the currently executing statement
+			// and its plan gist.
+			res.SetError(ex.WithAnonymizedStatementAndGist(resErr))
+		}
 		// For a pausable portal, we don't log the affected rows until we close the
 		// portal. However, we update the result for each execution. Thus, we need
 		// to accumulate the number of affected rows before closing the result.
@@ -4091,7 +4099,8 @@ func (ex *connExecutor) txnStateTransitionsApplyWrapper(
 				errors.Safe(advInfo.txnEvent.eventType.String()),
 				res.Err())
 			log.Dev.Errorf(ex.Ctx(), "%v", err)
-			sentryutil.SendReport(ex.Ctx(), &ex.server.cfg.Settings.SV, err)
+			sentryErr := ex.WithAnonymizedStatementAndGist(err)
+			sentryutil.SendReport(ex.Ctx(), &ex.server.cfg.Settings.SV, sentryErr)
 			return advanceInfo{}, err
 		}
 
@@ -4889,6 +4898,22 @@ func (ps connExPrepStmtsAccessor) DeleteAll(ctx context.Context) {
 	)
 }
 
+// WithAnonymizedStatementAndGist attaches the anonymized form of the currently
+// executing statement and its query plan gist to an error object, if available.
+// It can only be called from the same thread that runs the connExecutor.
+func (ex *connExecutor) WithAnonymizedStatementAndGist(err error) error {
+	if ex.curStmtAST != nil {
+		vt := ex.planner.extendedEvalCtx.VirtualSchemas
+		anonStmtStr := anonymizeStmtAndConstants(ex.curStmtAST, vt)
+		anonStmtStr = truncateStatementStringForTelemetry(anonStmtStr)
+		err = errors.WithSafeDetails(err, "while executing: %s", errors.Safe(anonStmtStr))
+	}
+	if ex.curStmtPlanGist != "" {
+		err = errors.WithSafeDetails(err, "plan gist: %s", ex.curStmtPlanGist)
+	}
+	return err
+}
+
 var contextPlanGistKey = ctxutil.RegisterFastValueKey()
 
 func withPlanGist(ctx context.Context, gist string) context.Context {

pkg/sql/conn_executor_exec.go

@@ -3235,6 +3235,7 @@ func (ex *connExecutor) makeExecPlan(
 
 	// Include gist in error reports.
 	ih := &planner.instrumentation
+	ex.curStmtPlanGist = redact.SafeString(ih.planGist.String())
 	ctx = withPlanGist(ctx, ih.planGist.String())
 	if buildutil.CrdbTestBuild && ih.planGist.String() != "" {
 		// Ensure that the gist can be decoded in test builds.

pkg/sql/conn_executor_internal_test.go

@@ -6,6 +6,7 @@ package sql
 
 import (
 	"context"
+	"strings"
 	"testing"
 	"time"
 
@@ -41,6 +42,9 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/util/stop"
 	"github.com/cockroachdb/cockroach/pkg/util/timeutil"
 	"github.com/cockroachdb/cockroach/pkg/util/uuid"
+	"github.com/cockroachdb/errors"
+	"github.com/cockroachdb/redact"
+	"github.com/pmezard/go-difflib/difflib"
 	"github.com/stretchr/testify/require"
 )
 
@@ -459,3 +463,56 @@ CREATE TEMPORARY TABLE foo();
 		require.NoError(t, err)
 	}
 }
+
+func TestAnonymizeStatementAndGistForReporting(t *testing.T) {
+	defer leaktest.AfterTest(t)()
+	defer log.Scope(t).Close(t)
+
+	s := cluster.MakeTestingClusterSettings()
+	vt, err := NewVirtualSchemaHolder(context.Background(), s)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	const stmt1s = `
+INSERT INTO sensitive(super, sensible) VALUES('that', 'nobody', 'must', 'see')
+`
+	stmt1, err := parser.ParseOne(stmt1s)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	// Make a dummy connExecutor.
+	var ex connExecutor
+	ex.curStmtAST = stmt1.AST
+	ex.curStmtPlanGist = "foobargist"
+	ex.planner.extendedEvalCtx.VirtualSchemas = vt
+
+	rUnsafe := errors.New("some error")
+	safeErr := ex.WithAnonymizedStatementAndGist(rUnsafe)
+
+	const expMessage = "some error"
+	actMessage := safeErr.Error()
+	if actMessage != expMessage {
+		t.Errorf("wanted: %s\ngot: %s", expMessage, actMessage)
+	}
+
+	const expSafeRedactedMsgPrefix = `some error
+(1) plan gist: foobargist
+Wraps: (2) while executing: INSERT INTO _(_, _) VALUES ('_', '_', __more1_10__)`
+
+	actSafeRedactedMessage := string(redact.Sprintf("%+v", safeErr))
+
+	if !strings.HasPrefix(actSafeRedactedMessage, expSafeRedactedMsgPrefix) {
+		diff, _ := difflib.GetUnifiedDiffString(difflib.UnifiedDiff{
+			A:        difflib.SplitLines(expSafeRedactedMsgPrefix),
+			B:        difflib.SplitLines(actSafeRedactedMessage[:len(expSafeRedactedMsgPrefix)]),
+			FromFile: "Expected Message Prefix",
+			FromDate: "",
+			ToFile:   "Actual Message Prefix",
+			ToDate:   "",
+			Context:  1,
+		})
+		t.Errorf("Diff:\n%s", diff)
+	}
+}

pkg/sql/conn_executor_test.go

@@ -36,7 +36,6 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/sql/catalog/descpb"
 	"github.com/cockroachdb/cockroach/pkg/sql/execinfra"
 	"github.com/cockroachdb/cockroach/pkg/sql/mutations"
-	"github.com/cockroachdb/cockroach/pkg/sql/parser"
 	"github.com/cockroachdb/cockroach/pkg/sql/pgwire/pgcode"
 	"github.com/cockroachdb/cockroach/pkg/sql/rowexec"
 	"github.com/cockroachdb/cockroach/pkg/sql/sem/catconstants"
@@ -62,60 +61,12 @@ import (
 	"github.com/cockroachdb/datadriven"
 	"github.com/cockroachdb/errors"
 	"github.com/cockroachdb/logtags"
-	"github.com/cockroachdb/redact"
 	"github.com/jackc/pgx/v5"
 	"github.com/jackc/pgx/v5/pgconn"
 	"github.com/lib/pq"
-	"github.com/pmezard/go-difflib/difflib"
 	"github.com/stretchr/testify/require"
 )
 
-func TestAnonymizeStatementsForReporting(t *testing.T) {
-	defer leaktest.AfterTest(t)()
-	defer log.Scope(t).Close(t)
-
-	s := cluster.MakeTestingClusterSettings()
-	vt, err := sql.NewVirtualSchemaHolder(context.Background(), s)
-	if err != nil {
-		t.Fatal(err)
-	}
-
-	const stmt1s = `
-INSERT INTO sensitive(super, sensible) VALUES('that', 'nobody', 'must', 'see')
-`
-	stmt1, err := parser.ParseOne(stmt1s)
-	if err != nil {
-		t.Fatal(err)
-	}
-
-	rUnsafe := errors.New("some error")
-	safeErr := sql.WithAnonymizedStatement(rUnsafe, stmt1.AST, vt)
-
-	const expMessage = "some error"
-	actMessage := safeErr.Error()
-	if actMessage != expMessage {
-		t.Errorf("wanted: %s\ngot: %s", expMessage, actMessage)
-	}
-
-	const expSafeRedactedMsgPrefix = `some error
-(1) while executing: INSERT INTO _(_, _) VALUES ('_', '_', __more1_10__)`
-
-	actSafeRedactedMessage := string(redact.Sprintf("%+v", safeErr))
-
-	if !strings.HasPrefix(actSafeRedactedMessage, expSafeRedactedMsgPrefix) {
-		diff, _ := difflib.GetUnifiedDiffString(difflib.UnifiedDiff{
-			A:        difflib.SplitLines(expSafeRedactedMsgPrefix),
-			B:        difflib.SplitLines(actSafeRedactedMessage[:len(expSafeRedactedMsgPrefix)]),
-			FromFile: "Expected Message Prefix",
-			FromDate: "",
-			ToFile:   "Actual Message Prefix",
-			ToDate:   "",
-			Context:  1,
-		})
-		t.Errorf("Diff:\n%s", diff)
-	}
-}
-
 // Test that a connection closed abruptly while a SQL txn is in progress results
 // in that txn being rolled back.
 //

pkg/sql/exec_util.go

@@ -2842,15 +2842,6 @@ func anonymizeStmtAndConstants(stmt tree.Statement, vt VirtualTabler) string {
 	return f.CloseAndGetString()
 }
 
-// WithAnonymizedStatement attaches the anonymized form of a statement
-// to an error object.
-func WithAnonymizedStatement(err error, stmt tree.Statement, vt VirtualTabler) error {
-	anonStmtStr := anonymizeStmtAndConstants(stmt, vt)
-	anonStmtStr = truncateStatementStringForTelemetry(anonStmtStr)
-	return errors.WithSafeDetails(err,
-		"while executing: %s", errors.Safe(anonStmtStr))
-}
-
 // SessionTracing holds the state used by SET TRACING statements in the context
 // of one SQL session.
 // It holds the current trace being collected (or the last trace collected, if

pkg/util/log/logcrash/crash_reporting_packet_test.go

@@ -247,7 +247,9 @@ func TestInternalErrorReporting(t *testing.T) {
 		assert.Equal(t, "github.com/cockroachdb/errors/errutil/*errutil.leafError (*::)\n"+
 			"github.com/cockroachdb/errors/withstack/*withstack.withStack (*::)\n"+
 			"github.com/cockroachdb/errors/assert/*assert.withAssertionFailure (*::)\n"+
-			"github.com/cockroachdb/cockroach/pkg/sql/colexecerror/*colexecerror.notInternalError (*::)\n",
+			"github.com/cockroachdb/cockroach/pkg/sql/colexecerror/*colexecerror.notInternalError (*::)\n"+
+			"github.com/cockroachdb/errors/safedetails/*safedetails.withSafeDetails (*::)\n"+
+			"github.com/cockroachdb/errors/safedetails/*safedetails.withSafeDetails (*::)\n",
 			extra)
 	}