Merge #152367

152367: sql: log AST and plan gist for most sentry reports r=DrewKimball a=DrewKimball

#### sql: don't redact post-query type from errors

This commit fixes a minor oversight from when we introduced AFTER
triggers: the type of post-query (cascade vs trigger) is redacted in
error messages. This information is safe, so this commit marks the
action type as a `SafeString`.

Epic: None

Release note: None

#### sql: remove unnecessary param from helper functions

This commit removes an unused `ClientNoticeSender` parameter from
several functions related to formatting virtual table names.

Epic: None

Release note: None

#### 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

Co-authored-by: Drew Kimball <[email protected]>

Author: craig[bot]

pkg/sql/conn_executor.go

@@ -821,7 +821,7 @@ func (s *Server) getScrubbedStmtStats(
 		}
 
 		// Scrub the statement itself.
-		scrubbedQueryStr, ok := scrubStmtStatKey(s.cfg.VirtualSchemas, stat.Key.Query, nil)
+		scrubbedQueryStr, ok := scrubStmtStatKey(s.cfg.VirtualSchemas, stat.Key.Query)
 
 		// We don't want to report this stats if scrubbing has failed. We also don't
 		// wish to abort here because we want to try our best to report all the
@@ -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, nil)
 		}
 
-		// 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, nil /* ClientNoticeSender */)
-
-	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_factory_util.go

@@ -259,7 +259,7 @@ func constructVirtualScan(
 	delayedNodeCallback func(*delayedNode) (exec.Node, error),
 ) (exec.Node, error) {
 	tn := &table.(*optVirtualTable).name
-	virtual, err := p.getVirtualTabler().getVirtualTableEntry(tn, p)
+	virtual, err := p.getVirtualTabler().getVirtualTableEntry(tn)
 	if err != nil {
 		return nil, err
 	}

pkg/sql/exec_util.go

@@ -2780,11 +2780,9 @@ func truncateStatementStringForTelemetry(stmt string) string {
 // hideNonVirtualTableNameFunc returns a function that can be used with
 // FmtCtx.SetReformatTableNames. It hides all table names that are not virtual
 // tables.
-func hideNonVirtualTableNameFunc(
-	vt VirtualTabler, ns eval.ClientNoticeSender,
-) func(ctx *tree.FmtCtx, name *tree.TableName) {
+func hideNonVirtualTableNameFunc(vt VirtualTabler) func(ctx *tree.FmtCtx, name *tree.TableName) {
 	reformatFn := func(ctx *tree.FmtCtx, tn *tree.TableName) {
-		virtual, err := vt.getVirtualTableEntry(tn, ns)
+		virtual, err := vt.getVirtualTableEntry(tn)
 
 		if err != nil || virtual == nil {
 			// Current table is non-virtual and therefore needs to be scrubbed (for statement stats) or redacted (for logs).
@@ -2828,16 +2826,14 @@ func hideNonVirtualTableNameFunc(
 	return reformatFn
 }
 
-func anonymizeStmtAndConstants(
-	stmt tree.Statement, vt VirtualTabler, ns eval.ClientNoticeSender,
-) string {
+func anonymizeStmtAndConstants(stmt tree.Statement, vt VirtualTabler) string {
 	// Re-format to remove most names.
 	fmtFlags := tree.FmtAnonymize | tree.FmtHideConstants
 	var f *tree.FmtCtx
 	if vt != nil {
 		f = tree.NewFmtCtx(
 			fmtFlags,
-			tree.FmtReformatTableNames(hideNonVirtualTableNameFunc(vt, ns)),
+			tree.FmtReformatTableNames(hideNonVirtualTableNameFunc(vt)),
 		)
 	} else {
 		f = tree.NewFmtCtx(fmtFlags)
@@ -2846,17 +2842,6 @@ func anonymizeStmtAndConstants(
 	return f.CloseAndGetString()
 }
 
-// WithAnonymizedStatement attaches the anonymized form of a statement
-// to an error object.
-func WithAnonymizedStatement(
-	err error, stmt tree.Statement, vt VirtualTabler, ns eval.ClientNoticeSender,
-) error {
-	anonStmtStr := anonymizeStmtAndConstants(stmt, vt, ns)
-	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
@@ -4469,7 +4454,7 @@ func quantizeCounts(d *appstatspb.StatementStatistics) {
 	d.FirstAttemptCount = int64((float64(d.FirstAttemptCount) / float64(oldCount)) * float64(newCount))
 }
 
-func scrubStmtStatKey(vt VirtualTabler, key string, ns eval.ClientNoticeSender) (string, bool) {
+func scrubStmtStatKey(vt VirtualTabler, key string) (string, bool) {
 	// Re-parse the statement to obtain its AST.
 	stmt, err := parser.ParseOne(key)
 	if err != nil {
@@ -4479,7 +4464,7 @@ func scrubStmtStatKey(vt VirtualTabler, key string, ns eval.ClientNoticeSender)
 	// Re-format to remove most names.
 	f := tree.NewFmtCtx(
 		tree.FmtAnonymize,
-		tree.FmtReformatTableNames(hideNonVirtualTableNameFunc(vt, ns)),
+		tree.FmtReformatTableNames(hideNonVirtualTableNameFunc(vt)),
 	)
 	f.FormatNode(stmt.AST)
 	return f.CloseAndGetString(), true

pkg/sql/exec_util_test.go

@@ -27,7 +27,7 @@ func TestHideNonVirtualTableNameFunc(t *testing.T) {
 	if err != nil {
 		t.Fatal(err)
 	}
-	tableNameFunc := hideNonVirtualTableNameFunc(vt, nil)
+	tableNameFunc := hideNonVirtualTableNameFunc(vt)
 
 	testData := []struct {
 		stmt     string

pkg/sql/opt/exec/execbuilder/post_queries.go

@@ -17,6 +17,7 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/sql/sem/eval"
 	"github.com/cockroachdb/cockroach/pkg/sql/sem/tree"
 	"github.com/cockroachdb/errors"
+	"github.com/cockroachdb/redact"
 )
 
 // postQueryBuilder is a helper that fills in exec.PostQuery metadata; it
@@ -162,7 +163,7 @@ func (cb *postQueryBuilder) setupCascade(cascade *memo.FKCascade) exec.PostQuery
 			numBufferedRows int,
 			allowAutoCommit bool,
 		) (exec.Plan, error) {
-			const actionName = "cascade"
+			const actionName redact.SafeString = "cascade"
 			return cb.planPostQuery(
 				ctx, semaCtx, evalCtx, execFactory, bufferRef, numBufferedRows, allowAutoCommit,
 				cascade.Builder, actionName,
@@ -185,7 +186,7 @@ func (cb *postQueryBuilder) setupTriggers(triggers *memo.AfterTriggers) exec.Pos
 			numBufferedRows int,
 			allowAutoCommit bool,
 		) (exec.Plan, error) {
-			const actionName = "trigger"
+			const actionName redact.SafeString = "trigger"
 			return cb.planPostQuery(
 				ctx, semaCtx, evalCtx, execFactory, bufferRef, numBufferedRows, allowAutoCommit,
 				triggers.Builder, actionName,
@@ -209,7 +210,7 @@ func (cb *postQueryBuilder) planPostQuery(
 	numBufferedRows int,
 	allowAutoCommit bool,
 	builder memo.PostQueryBuilder,
-	actionName string,
+	actionName redact.SafeString,
 ) (exec.Plan, error) {
 	// 1. Set up a brand new memo in which to plan the cascading query.
 	var err error

pkg/sql/opt_exec_factory.go

@@ -808,7 +808,7 @@ func constructVirtualTableLookupJoin(
 	onCond tree.TypedExpr,
 ) (planNode, error) {
 	tn := &table.(*optVirtualTable).name
-	virtual, err := p.getVirtualTabler().getVirtualTableEntry(tn, p)
+	virtual, err := p.getVirtualTabler().getVirtualTableEntry(tn)
 	if err != nil {
 		return nil, err
 	}