sql, telemetry: show correctly redacted error message

Previously, the error string from an executed SQL statement was treated as a `string` type which would get fully redacted on its way out to the telemetry log. This change writes the `error` type into a `RedactableString` which preserves the redaction in the error as intended. This will preserve the template string which we consider safe by default, for instance. The `CommonSQLExecDetails` type in `sql_audit_events.proto` has been modified to have the `error_text` field represented as a `RedactableString` which helps us maintain the preservation of redaction markers. Resolves: #78353 Release note (ops change): Telemetry logs will now display more finely redacted error messages from sql execution. Previously, the entire error string was fully redacted.
cockroachdb · Jul 4, 2022 · 2112453 · 2112453
1 parent 4e81340
commit 2112453
Show file tree

Hide file tree

Showing 5 changed files with 35 additions and 13 deletions.
diff --git a/docs/generated/eventlog.md b/docs/generated/eventlog.md
@@ -389,7 +389,7 @@ is directly or indirectly a member of the admin role) executes a query.
 | `ExecMode` | How the statement was being executed (exec/prepare, etc.) | no |
 | `NumRows` | Number of rows returned. For mutation statements (INSERT, etc) that do not produce result rows, this field reports the number of rows affected. | no |
 | `SQLSTATE` | The SQLSTATE code for the error, if an error was encountered. Empty/omitted if no error. | no |
-| `ErrorText` | The text of the error if any. | yes |
+| `ErrorText` | The text of the error if any. | partially |
 | `Age` | Age of the query in milliseconds. | no |
 | `NumRetries` | Number of retries, when the txn was reretried automatically by the server. | no |
 | `FullTableScan` | Whether the query contains a full table scan. | no |
@@ -423,7 +423,7 @@ a table marked as audited.
 | `ExecMode` | How the statement was being executed (exec/prepare, etc.) | no |
 | `NumRows` | Number of rows returned. For mutation statements (INSERT, etc) that do not produce result rows, this field reports the number of rows affected. | no |
 | `SQLSTATE` | The SQLSTATE code for the error, if an error was encountered. Empty/omitted if no error. | no |
-| `ErrorText` | The text of the error if any. | yes |
+| `ErrorText` | The text of the error if any. | partially |
 | `Age` | Age of the query in milliseconds. | no |
 | `NumRetries` | Number of retries, when the txn was reretried automatically by the server. | no |
 | `FullTableScan` | Whether the query contains a full table scan. | no |
@@ -464,7 +464,7 @@ and the cluster setting `sql.trace.log_statement_execute` is set.
 | `ExecMode` | How the statement was being executed (exec/prepare, etc.) | no |
 | `NumRows` | Number of rows returned. For mutation statements (INSERT, etc) that do not produce result rows, this field reports the number of rows affected. | no |
 | `SQLSTATE` | The SQLSTATE code for the error, if an error was encountered. Empty/omitted if no error. | no |
-| `ErrorText` | The text of the error if any. | yes |
+| `ErrorText` | The text of the error if any. | partially |
 | `Age` | Age of the query in milliseconds. | no |
 | `NumRetries` | Number of retries, when the txn was reretried automatically by the server. | no |
 | `FullTableScan` | Whether the query contains a full table scan. | no |
@@ -2064,7 +2064,7 @@ set to a non-zero value, AND
 | `ExecMode` | How the statement was being executed (exec/prepare, etc.) | no |
 | `NumRows` | Number of rows returned. For mutation statements (INSERT, etc) that do not produce result rows, this field reports the number of rows affected. | no |
 | `SQLSTATE` | The SQLSTATE code for the error, if an error was encountered. Empty/omitted if no error. | no |
-| `ErrorText` | The text of the error if any. | yes |
+| `ErrorText` | The text of the error if any. | partially |
 | `Age` | Age of the query in milliseconds. | no |
 | `NumRetries` | Number of retries, when the txn was reretried automatically by the server. | no |
 | `FullTableScan` | Whether the query contains a full table scan. | no |
@@ -2183,7 +2183,7 @@ the "slow query" condition.
 | `ExecMode` | How the statement was being executed (exec/prepare, etc.) | no |
 | `NumRows` | Number of rows returned. For mutation statements (INSERT, etc) that do not produce result rows, this field reports the number of rows affected. | no |
 | `SQLSTATE` | The SQLSTATE code for the error, if an error was encountered. Empty/omitted if no error. | no |
-| `ErrorText` | The text of the error if any. | yes |
+| `ErrorText` | The text of the error if any. | partially |
 | `Age` | Age of the query in milliseconds. | no |
 | `NumRetries` | Number of retries, when the txn was reretried automatically by the server. | no |
 | `FullTableScan` | Whether the query contains a full table scan. | no |
@@ -2476,7 +2476,7 @@ contains common SQL event/execution details.
 | `ExecMode` | How the statement was being executed (exec/prepare, etc.) | no |
 | `NumRows` | Number of rows returned. For mutation statements (INSERT, etc) that do not produce result rows, this field reports the number of rows affected. | no |
 | `SQLSTATE` | The SQLSTATE code for the error, if an error was encountered. Empty/omitted if no error. | no |
-| `ErrorText` | The text of the error if any. | yes |
+| `ErrorText` | The text of the error if any. | partially |
 | `Age` | Age of the query in milliseconds. | no |
 | `NumRetries` | Number of retries, when the txn was reretried automatically by the server. | no |
 | `FullTableScan` | Whether the query contains a full table scan. | no |

diff --git a/pkg/sql/exec_log.go b/pkg/sql/exec_log.go
@@ -26,6 +26,7 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/util/log"
 	"github.com/cockroachdb/cockroach/pkg/util/log/eventpb"
 	"github.com/cockroachdb/cockroach/pkg/util/timeutil"
+	"github.com/cockroachdb/redact"
 )
 
 // This file contains facilities to report SQL activities to separate
@@ -208,9 +209,9 @@ func (p *planner) maybeLogStatementInternal(
 	age := float32(queryDuration.Nanoseconds()) / 1e6
 	// The text of the error encountered, if the query did in fact end
 	// in error.
-	execErrStr := ""
+	var execErrStr redact.RedactableString
 	if err != nil {
-		execErrStr = err.Error()
+		execErrStr = redact.Sprint(err)
 	}
 	// The type of execution context (execute/prepare).
 	lbl := execType.logLabel()

diff --git a/pkg/sql/telemetry_logging_test.go b/pkg/sql/telemetry_logging_test.go
@@ -114,6 +114,7 @@ func TestTelemetryLogging(t *testing.T) {
 		expectedSkipped         []int // Expected skipped query count per expected log line.
 		expectedUnredactedTags  []string
 		expectedApplicationName string
+		expectedErr             string
 	}{
 		{
 			// Test case with statement that is not of type DML.
@@ -128,6 +129,7 @@ func TestTelemetryLogging(t *testing.T) {
 			[]int{0, 0, 0, 0},
 			[]string{"client"},
 			"telemetry-logging-test",
+			"",
 		},
 		{
 			// Test case with statement that is of type DML.
@@ -140,6 +142,7 @@ func TestTelemetryLogging(t *testing.T) {
 			[]int{0},
 			[]string{"client"},
 			"telemetry-logging-test",
+			"",
 		},
 		{
 			// Test case with statement that is of type DML.
@@ -153,6 +156,7 @@ func TestTelemetryLogging(t *testing.T) {
 			[]int{0, 2},
 			[]string{"client"},
 			"telemetry-logging-test",
+			"",
 		},
 		{
 			// Test case with statement that is of type DML.
@@ -165,6 +169,19 @@ func TestTelemetryLogging(t *testing.T) {
 			[]int{0, 3, 0},
 			[]string{"client"},
 			"telemetry-logging-test",
+			"",
+		},
+		// Not of type DML so not sampled
+		{
+			"sql-error",
+			"CREATE USER root;",
+			[]float64{7},
+			`CREATE USER root`,
+			1,
+			[]int{0},
+			[]string{"client"},
+			"telemetry-logging-test",
+			"a role/user named ‹root› already exists",
 		},
 	}
 
@@ -173,7 +190,7 @@ func TestTelemetryLogging(t *testing.T) {
 		for _, execTimestamp := range tc.execTimestampsSeconds {
 			stubTime := timeutil.FromUnixMicros(int64(execTimestamp * 1e6))
 			st.setTime(stubTime)
-			db.Exec(t, tc.query)
+			_, _ = db.DB.ExecContext(context.Background(), tc.query)
 		}
 	}
 
@@ -247,6 +264,12 @@ func TestTelemetryLogging(t *testing.T) {
 				if !strings.Contains(e.Message, "\"ApplicationName\":\""+tc.expectedApplicationName+"\"") {
 					t.Errorf("expected to find unredacted Application Name: %s", tc.expectedApplicationName)
 				}
+				if tc.expectedErr != "" {
+					if !strings.Contains(e.Message, tc.expectedErr) {
+						t.Errorf("%s: missing error %s in message %s", tc.name, tc.expectedErr, e.Message)
+						break
+					}
+				}
 			}
 		}
 		if logCount != expectedLogCount {

diff --git a/pkg/util/log/eventpb/json_encode_generated.go b/pkg/util/log/eventpb/json_encode_generated.go
diff --git a/pkg/util/log/eventpb/sql_audit_events.proto b/pkg/util/log/eventpb/sql_audit_events.proto
@@ -30,7 +30,7 @@ message CommonSQLExecDetails {
   // The SQLSTATE code for the error, if an error was encountered. Empty/omitted if no error.
   string sqlstate = 3 [(gogoproto.customname) = "SQLSTATE", (gogoproto.jsontag) = ",omitempty", (gogoproto.moretags) = "redact:\"nonsensitive\""];
   // The text of the error if any.
-  string error_text = 4 [(gogoproto.jsontag) = ",omitempty"];
+  string error_text = 4 [(gogoproto.jsontag) = ",omitempty", (gogoproto.customtype) = "github.com/cockroachdb/redact.RedactableString", (gogoproto.nullable) = false, (gogoproto.moretags) = "redact:\"mixed\""];
   // Age of the query in milliseconds.
   float age = 5 [(gogoproto.jsontag) = ",omitempty"];
   // Number of retries, when the txn was reretried automatically by the server.