Add vtgate and vttablet flag to truncate errors sent to client (#12899)

* Add vttablet flag `-queryserver-config-truncate-error-len`.

Unlike vanilla MySQL, Vitess sometimes includes client SQL in error
responses leading to potentially large response packets. This
confuses some clients such as PHP's PDO driver. (A bug has been filed
with PHP[0] for this behavior.)

We avoid this edge case by truncating large error messages via this
flag.

[0] https://bugs.php.net/bug.php?id=78797

Signed-off-by: Adam Saponara <as@php.net>

* Add vtgate flag `-vtgate-config-truncate-error-len`

Signed-off-by: dleibovic <dleibovic@etsy.com>

* Apply suggestions from code review

Co-authored-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com>
Signed-off-by: David Leibovic <david.leibovic@gmail.com>

* updates from review: remove 'vtgate-config-' prefix to flag

Signed-off-by: dleibovic <dleibovic@etsy.com>

* updates from review: append '[TRUNCATED]' to truncated error messages

Signed-off-by: dleibovic <dleibovic@etsy.com>

* fixup merge

Signed-off-by: dleibovic <dleibovic@etsy.com>

* fixup formatting

Signed-off-by: dleibovic <dleibovic@etsy.com>

* WIP: updates from review.

vterrors.TruncateError now returns an error rather than a string. Moved vtgate error truncation logic from to vtgate executor.

Signed-off-by: dleibovic <dleibovic@etsy.com>

* hopefully fix tests

Signed-off-by: dleibovic <dleibovic@etsy.com>

* updates from review: remove unecessary variable passing

Signed-off-by: dleibovic <dleibovic@etsy.com>

* fix whitspace

Signed-off-by: dleibovic <dleibovic@etsy.com>

---------

Signed-off-by: Adam Saponara <as@php.net>
Signed-off-by: dleibovic <dleibovic@etsy.com>
Signed-off-by: David Leibovic <david.leibovic@gmail.com>
Signed-off-by: David Leibovic <dleibovic@etsy.com>
Co-authored-by: Adam Saponara <as@php.net>
Co-authored-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com>

config/tablet/default.yaml

@@ -106,6 +106,7 @@ queryCacheSize: 5000                     # queryserver-config-query-cache-size
 schemaReloadIntervalSeconds: 1800        # queryserver-config-schema-reload-time
 watchReplication: false                  # watch_replication_stream
 terseErrors: false                       # queryserver-config-terse-errors
+truncateErrorLen: 0                      # queryserver-config-truncate-error-len
 messagePostponeParallelism: 4            # queryserver-config-message-postpone-cap
 cacheResultFields: true                  # enable-query-plan-field-caching
 

go/flags/endtoend/vtgate.txt

@@ -195,6 +195,7 @@ Usage of vtgate:
       --tracing-sampling-rate float                                      sampling rate for the probabilistic jaeger sampler (default 0.1)
       --tracing-sampling-type string                                     sampling strategy to use for jaeger. possible values are 'const', 'probabilistic', 'rateLimiting', or 'remote' (default "const")
       --transaction_mode string                                          SINGLE: disallow multi-db transactions, MULTI: allow multi-db transactions with best effort commit, TWOPC: allow multi-db transactions with 2pc commit (default "MULTI")
+      --truncate-error-len int                                           truncate errors sent to client if they are longer than this value (0 means do not truncate)
       --v Level                                                          log level for V logs
   -v, --version                                                          print binary version
       --vmodule moduleSpec                                               comma-separated list of pattern=N settings for file-filtered logging

go/flags/endtoend/vttablet.txt

@@ -236,6 +236,7 @@ Usage of vttablet:
       --queryserver-config-terse-errors                                  prevent bind vars from escaping in client error messages
       --queryserver-config-transaction-cap int                           query server transaction cap is the maximum number of transactions allowed to happen at any given point of a time for a single vttablet. E.g. by setting transaction cap to 100, there are at most 100 transactions will be processed by a vttablet and the 101th transaction will be blocked (and fail if it cannot get connection within specified timeout) (default 20)
       --queryserver-config-transaction-timeout duration                  query server transaction timeout (in seconds), a transaction will be killed if it takes longer than this value (default 30s)
+      --queryserver-config-truncate-error-len int                        truncate errors sent to client if they are longer than this value (0 means do not truncate)
       --queryserver-config-txpool-timeout duration                       query server transaction pool timeout, it is how long vttablet waits if tx pool is full (default 1s)
       --queryserver-config-txpool-waiter-cap int                         query server transaction pool waiter limit, this is the maximum number of transactions that can be queued waiting to get a connection (default 5000)
       --queryserver-config-warn-result-size int                          query server result size warning threshold, warn if number of rows returned from vttablet for non-streaming queries exceeds this

go/vt/vterrors/vterrors.go

@@ -361,5 +361,19 @@ func Print(err error) string {
 	return fmt.Sprintf("%v: %v\n", Code(err), err.Error())
 }
 
+// TruncateError truncates error messages that are longer than the
+// specified length.
+func TruncateError(oldErr error, max int) error {
+	if oldErr == nil || max <= 0 || len(oldErr.Error()) <= max {
+		return oldErr
+	}
+
+	if max <= 12 {
+		return New(Code(oldErr), "[TRUNCATED]")
+	}
+
+	return New(Code(oldErr), oldErr.Error()[:max-12]+" [TRUNCATED]")
+}
+
 func (f *fundamental) ErrorState() State       { return f.state }
 func (f *fundamental) ErrorCode() vtrpcpb.Code { return f.code }

go/vt/vtgate/executor.go

@@ -114,6 +114,10 @@ type Executor struct {
 
 	// allowScatter will fail planning if set to false and a plan contains any scatter queries
 	allowScatter bool
+
+	// truncateErrorLen truncates errors sent to client if they are above this value
+	// (0 means do not truncate).
+	truncateErrorLen int
 }
 
 var executorOnce sync.Once
@@ -212,6 +216,7 @@ func (e *Executor) Execute(ctx context.Context, method string, safeSession *Safe
 
 	logStats.SaveEndTime()
 	QueryLogger.Send(logStats)
+	err = vterrors.TruncateError(err, truncateErrorLen)
 	return result, err
 }
 
@@ -344,7 +349,7 @@ func (e *Executor) StreamExecute(
 
 	logStats.SaveEndTime()
 	QueryLogger.Send(logStats)
-	return err
+	return vterrors.TruncateError(err, truncateErrorLen)
 
 }
 
@@ -1224,7 +1229,7 @@ func (e *Executor) Prepare(ctx context.Context, method string, safeSession *Safe
 		logStats.SaveEndTime()
 		QueryLogger.Send(logStats)
 	}
-	return fld, err
+	return fld, vterrors.TruncateError(err, truncateErrorLen)
 }
 
 func (e *Executor) prepare(ctx context.Context, safeSession *SafeSession, sql string, bindVars map[string]*querypb.BindVariable, logStats *logstats.LogStats) ([]*querypb.Field, error) {

go/vt/vtgate/executor_test.go

@@ -2665,6 +2665,27 @@ func TestExecutorPrepareExecute(t *testing.T) {
 	require.Error(t, err)
 }
 
+func TestExecutorTruncateErrors(t *testing.T) {
+	save := truncateErrorLen
+	truncateErrorLen = 32
+	defer func() { truncateErrorLen = save }()
+
+	executor, _, _, _ := createExecutorEnv()
+	session := NewSafeSession(&vtgatepb.Session{})
+	fn := func(r *sqltypes.Result) error {
+		return nil
+	}
+
+	_, err := executor.Execute(ctx, "TestExecute", session, "invalid statement", nil)
+	assert.EqualError(t, err, "syntax error at posi [TRUNCATED]")
+
+	err = executor.StreamExecute(ctx, "TestExecute", session, "invalid statement", nil, fn)
+	assert.EqualError(t, err, "syntax error at posi [TRUNCATED]")
+
+	_, err = executor.Prepare(context.Background(), "TestExecute", session, "invalid statement", nil)
+	assert.EqualError(t, err, "[BUG] unrecognized p [TRUNCATED]")
+}
+
 func TestExecutorFlushStmt(t *testing.T) {
 	executor, _, _, _ := createExecutorEnv()
 

go/vt/vtgate/vtgate.go

@@ -62,7 +62,8 @@ var (
 	normalizeQueries = true
 	streamBufferSize = 32 * 1024
 
-	terseErrors bool
+	terseErrors      bool
+	truncateErrorLen int
 
 	// plan cache related flag
 	queryPlanCacheSize   = cache.DefaultConfig.MaxEntries
@@ -117,6 +118,7 @@ func registerFlags(fs *pflag.FlagSet) {
 	fs.StringVar(&transactionMode, "transaction_mode", transactionMode, "SINGLE: disallow multi-db transactions, MULTI: allow multi-db transactions with best effort commit, TWOPC: allow multi-db transactions with 2pc commit")
 	fs.BoolVar(&normalizeQueries, "normalize_queries", normalizeQueries, "Rewrite queries with bind vars. Turn this off if the app itself sends normalized queries with bind vars.")
 	fs.BoolVar(&terseErrors, "vtgate-config-terse-errors", terseErrors, "prevent bind vars from escaping in returned errors")
+	fs.IntVar(&truncateErrorLen, "truncate-error-len", truncateErrorLen, "truncate errors sent to client if they are longer than this value (0 means do not truncate)")
 	fs.IntVar(&streamBufferSize, "stream_buffer_size", streamBufferSize, "the number of bytes sent from vtgate for each stream call. It's recommended to keep this value in sync with vttablet's query-server-config-stream-buffer-size.")
 	fs.Int64Var(&queryPlanCacheSize, "gate_query_cache_size", queryPlanCacheSize, "gate server query cache size, maximum number of queries to be cached. vtgate analyzes every incoming query and generate a query plan, these plans are being cached in a cache. This config controls the expected amount of unique entries in the cache.")
 	fs.Int64Var(&queryPlanCacheMemory, "gate_query_cache_memory", queryPlanCacheMemory, "gate server query cache size in bytes, maximum amount of memory to be cached. vtgate analyzes every incoming query and generate a query plan, these plans are being cached in a lru cache. This config controls the capacity of the lru cache.")

go/vt/vttablet/tabletserver/tabletenv/config.go

@@ -149,6 +149,7 @@ func registerTabletEnvFlags(fs *pflag.FlagSet) {
 	fs.BoolVar(&currentConfig.EnableTableACLDryRun, "queryserver-config-enable-table-acl-dry-run", defaultConfig.EnableTableACLDryRun, "If this flag is enabled, tabletserver will emit monitoring metrics and let the request pass regardless of table acl check results")
 	fs.StringVar(&currentConfig.TableACLExemptACL, "queryserver-config-acl-exempt-acl", defaultConfig.TableACLExemptACL, "an acl that exempt from table acl checking (this acl is free to access any vitess tables).")
 	fs.BoolVar(&currentConfig.TerseErrors, "queryserver-config-terse-errors", defaultConfig.TerseErrors, "prevent bind vars from escaping in client error messages")
+	fs.IntVar(&currentConfig.TruncateErrorLen, "queryserver-config-truncate-error-len", defaultConfig.TruncateErrorLen, "truncate errors sent to client if they are longer than this value (0 means do not truncate)")
 	fs.BoolVar(&currentConfig.AnnotateQueries, "queryserver-config-annotate-queries", defaultConfig.AnnotateQueries, "prefix queries to MySQL backend with comment indicating vtgate principal (user) and target tablet type")
 	fs.BoolVar(&currentConfig.WatchReplication, "watch_replication_stream", false, "When enabled, vttablet will stream the MySQL replication stream from the local server, and use it to update schema when it sees a DDL.")
 	fs.BoolVar(&currentConfig.TrackSchemaVersions, "track_schema_versions", false, "When enabled, vttablet will store versions of schemas at each position that a DDL is applied and allow retrieval of the schema corresponding to a position")
@@ -322,6 +323,7 @@ type TabletConfig struct {
 	WatchReplication                        bool                              `json:"watchReplication,omitempty"`
 	TrackSchemaVersions                     bool                              `json:"trackSchemaVersions,omitempty"`
 	TerseErrors                             bool                              `json:"terseErrors,omitempty"`
+	TruncateErrorLen                        int                               `json:"truncateErrorLen,omitempty"`
 	AnnotateQueries                         bool                              `json:"annotateQueries,omitempty"`
 	MessagePostponeParallelism              int                               `json:"messagePostponeParallelism,omitempty"`
 	DeprecatedCacheResultFields             bool                              `json:"cacheResultFields,omitempty"`

go/vt/vttablet/tabletserver/tabletserver.go

@@ -98,6 +98,7 @@ type TabletServer struct {
 	stats                  *tabletenv.Stats
 	QueryTimeout           atomic.Int64
 	TerseErrors            bool
+	TruncateErrorLen       int
 	enableHotRowProtection bool
 	topoServer             *topo.Server
 
@@ -155,6 +156,7 @@ func NewTabletServer(name string, config *tabletenv.TabletConfig, topoServer *to
 		stats:                  tabletenv.NewStats(exporter),
 		config:                 config,
 		TerseErrors:            config.TerseErrors,
+		TruncateErrorLen:       config.TruncateErrorLen,
 		enableHotRowProtection: config.HotRowProtection.Mode != tabletenv.Disable,
 		topoServer:             topoServer,
 		alias:                  proto.Clone(alias).(*topodatapb.TabletAlias),
@@ -1576,7 +1578,7 @@ func (tsv *TabletServer) convertAndLogError(ctx context.Context, sql string, bin
 		logStats.Error = err
 	}
 
-	return err
+	return vterrors.TruncateError(err, tsv.TruncateErrorLen)
 }
 
 // truncateSQLAndBindVars calls TruncateForLog which:

go/vt/vttablet/tabletserver/tabletserver_test.go

@@ -1635,6 +1635,28 @@ func TestSanitizeMessagesNoBindVars(t *testing.T) {
 	}
 }
 
+func TestTruncateErrorLen(t *testing.T) {
+	config := tabletenv.NewDefaultConfig()
+	config.TruncateErrorLen = 32
+	tsv := NewTabletServer("TabletServerTest", config, memorytopo.NewServer(""), &topodatapb.TabletAlias{})
+	tl := newTestLogger()
+	defer tl.Close()
+	err := tsv.convertAndLogError(
+		ctx,
+		"select 42 from dual",
+		nil,
+		vterrors.Errorf(vtrpcpb.Code_INTERNAL, "Looooooooooooooooooooooooooooooooong error"),
+		nil,
+	)
+	want := "Looooooooooooooooooo [TRUNCATED]"
+	require.Error(t, err)
+	assert.Equal(t, err.Error(), want)
+	want = "Sql: \"select 42 from dual\", BindVars: {}"
+	if !strings.Contains(tl.getLog(0), want) {
+		t.Errorf("error log %s, want '%s'", tl.getLog(0), want)
+	}
+}
+
 func TestTruncateMessages(t *testing.T) {
 	config := tabletenv.NewDefaultConfig()
 	config.TerseErrors = false