Truncate long queries in error logs

go/sqldb/sql_error.go

@@ -9,6 +9,8 @@ import (
 	"fmt"
 	"regexp"
 	"strconv"
+
+	"github.com/youtube/vitess/go/vt/sqlparser"
 )
 
 const (
@@ -49,8 +51,9 @@ func (se *SQLError) Error() string {
 	fmt.Fprintf(buf, " (errno %v) (sqlstate %v)", se.Num, se.State)
 
 	if se.Query != "" {
-		fmt.Fprintf(buf, " during query: %s", se.Query)
+		fmt.Fprintf(buf, " during query: %s", sqlparser.TruncateForLog(se.Query))
 	}
+
 	return buf.String()
 }
 

go/vt/sqlparser/parsed_query.go

@@ -11,7 +11,6 @@ import (
 	"fmt"
 
 	"github.com/youtube/vitess/go/sqltypes"
-	"github.com/youtube/vitess/go/vt/utils"
 
 	querypb "github.com/youtube/vitess/go/vt/proto/query"
 )
@@ -54,7 +53,7 @@ func (pq *ParsedQuery) GenerateQuery(bindVariables map[string]interface{}) ([]by
 // MarshalJSON is a custom JSON marshaler for ParsedQuery.
 // Note that any queries longer that 512 bytes will be truncated.
 func (pq *ParsedQuery) MarshalJSON() ([]byte, error) {
-	return json.Marshal(utils.TruncateQuery(pq.Query))
+	return json.Marshal(TruncateForUI(pq.Query))
 }
 
 // EncodeValue encodes one bind variable value into the query.

go/vt/sqlparser/truncate_query.go

@@ -0,0 +1,38 @@
+// Copyright 2015, Google Inc. All rights reserved.
+// Use of this source code is governed by a BSD-style
+// license that can be found in the LICENSE file.
+
+package sqlparser
+
+import (
+	"flag"
+)
+
+var (
+	// Maximum length for a query in a sqlerror string. 0 means unlimited.
+	TruncateUILen  = flag.Int("sql-max-length-ui", 512, "truncate queries in debug UIs to the given length (default 512)")
+	TruncateErrLen = flag.Int("sql-max-length-errors", 0, "truncate queries in error logs to the given length (default unlimited)")
+)
+
+func truncateQuery(query string, max int) string {
+	sql, comments := SplitTrailingComments(query)
+
+	if max == 0 || len(sql) <= max {
+		return sql + comments
+	}
+
+	return sql[:max-12] + " [TRUNCATED]" + comments
+}
+
+// TruncateForUI is used when displaying queries on various Vitess status pages
+// to keep the pages small enough to load and render properly
+func TruncateForUI(query string) string {
+	return truncateQuery(query, *TruncateUILen)
+}
+
+// TruncateForLog is used when displaying queries as part of error logs
+// to avoid overwhelming logging systems with potentially long queries and
+// bind value data.
+func TruncateForLog(query string) string {
+	return truncateQuery(query, *TruncateErrLen)
+}

go/vt/utils/utils.go

@@ -10,12 +10,3 @@ func CloneBindVariables(bindVariables map[string]interface{}) map[string]interfa
 	}
 	return result
 }
-
-// TruncateQuery all long query strings to a maximum length of 512 to keep logs
-// and debug UI output to be a sane length.
-func TruncateQuery(query string) string {
-	if len(query) <= 512 {
-		return query
-	}
-	return query[:500] + " [TRUNCATED]"
-}

go/vt/vtgate/planner.go

@@ -335,7 +335,7 @@ func (plr *Planner) ServeHTTP(response http.ResponseWriter, request *http.Reques
 		response.Header().Set("Content-Type", "text/plain")
 		response.Write([]byte(fmt.Sprintf("Length: %d\n", len(keys))))
 		for _, v := range keys {
-			response.Write([]byte(fmt.Sprintf("%#v\n", v)))
+			response.Write([]byte(fmt.Sprintf("%#v\n", sqlparser.TruncateForUI(v))))
 			if plan, ok := plr.plans.Peek(v); ok {
 				if b, err := json.MarshalIndent(plan, "", "  "); err != nil {
 					response.Write([]byte(err.Error()))

go/vt/vtgate/vtgate.go

@@ -976,6 +976,20 @@ func (vtg *VTGate) VSchemaStats() *VSchemaStats {
 	return vtg.router.planner.VSchemaStats()
 }
 
+func truncateErrorStrings(data map[string]interface{}) map[string]interface{} {
+	ret := map[string]interface{}{}
+	for key, val := range data {
+		mapVal, ok := val.(map[string]interface{})
+		if ok {
+			ret[key] = truncateErrorStrings(mapVal)
+		} else {
+			strVal := fmt.Sprintf("%v", val)
+			ret[key] = sqlparser.TruncateForLog(strVal)
+		}
+	}
+	return ret
+}
+
 func recordAndAnnotateError(err error, statsKey []string, request map[string]interface{}, logger *logutil.ThrottledLogger) error {
 	ec := vterrors.Code(err)
 	fullKey := []string{
@@ -984,6 +998,10 @@ func recordAndAnnotateError(err error, statsKey []string, request map[string]int
 		statsKey[2],
 		ec.String(),
 	}
+
+	// Traverse the request structure and truncate any long values
+	request = truncateErrorStrings(request)
+
 	errorCounts.Add(fullKey, 1)
 	// Most errors are not logged by vtgate beecause they're either too spammy or logged elsewhere.
 	switch ec {

go/vt/vtgate/vtgate_test.go

@@ -16,6 +16,7 @@ import (
 	"github.com/youtube/vitess/go/sqltypes"
 	"github.com/youtube/vitess/go/vt/discovery"
 	"github.com/youtube/vitess/go/vt/key"
+	"github.com/youtube/vitess/go/vt/sqlparser"
 	"github.com/youtube/vitess/go/vt/topo"
 	"github.com/youtube/vitess/go/vt/vterrors"
 	"github.com/youtube/vitess/go/vt/vttablet/sandboxconn"
@@ -2662,3 +2663,33 @@ func TestParseTarget(t *testing.T) {
 		}
 	}
 }
+
+func TestLogTruncation(t *testing.T) {
+	*sqlparser.TruncateErrLen = 30
+
+	query := map[string]interface{}{
+		"Sql": "THIS IS A LONG QUERY THAT WILL BE TRUNCATED AWAY",
+		"BindVariables": map[string]interface{}{
+			"vtg1": 100,
+			"vtg2": "short string",
+			"vtg3": "this is a long bind variable that will be truncated away as well",
+			"vtg4": "another string",
+		},
+	}
+
+	truncated := truncateErrorStrings(query)
+
+	expected := map[string]interface{}{
+		"Sql": "THIS IS A LONG QUE [TRUNCATED]",
+		"BindVariables": map[string]interface{}{
+			"vtg1": "100", // <== Truncating also converts to string
+			"vtg2": "short string",
+			"vtg3": "this is a long bin [TRUNCATED]",
+			"vtg4": "another string",
+		},
+	}
+
+	if (!reflect.DeepEqual(truncated, expected)){
+		t.Errorf("query was not truncated properly: got %v expected %v", truncated, expected)
+	}
+}

go/vt/vttablet/endtoend/misc_test.go

@@ -20,6 +20,7 @@ import (
 
 	"github.com/youtube/vitess/go/sqldb"
 	"github.com/youtube/vitess/go/sqltypes"
+	"github.com/youtube/vitess/go/vt/sqlparser"
 	"github.com/youtube/vitess/go/vt/vttablet/endtoend/framework"
 
 	querypb "github.com/youtube/vitess/go/vt/proto/query"
@@ -518,3 +519,48 @@ func TestDBAStatements(t *testing.T) {
 		t.Errorf("RowsAffected: %d, want 4", qr.RowsAffected)
 	}
 }
+
+func TestLogTruncation(t *testing.T) {
+	client := framework.NewClient()
+
+	// Test that a long error string is not truncated by default
+	_, err := client.Execute(
+		"insert into vitess_test values(123, :data, null, null)",
+		map[string]interface{}{"data": "THIS IS A LONG LONG LONG LONG QUERY STRING THAT SHOULD BE SHORTENED"},
+	)
+	want := "Data truncated for column 'floatval' at row 1 (errno 1265) (sqlstate 01000) during query: insert into vitess_test values (123, 'THIS IS A LONG LONG LONG LONG QUERY STRING THAT SHOULD BE SHORTENED', null, null) /* _stream vitess_test (intval ) (123 ); */"
+	if err == nil {
+		t.Errorf("query unexpectedly succeeded")
+	}
+	if err.Error() != want {
+		t.Errorf("log was unexpectedly truncated... got %s, wanted %s", err, want)
+	}
+
+	// Test that the data too long error is truncated once the option is set
+	*sqlparser.TruncateErrLen = 30;
+	_, err = client.Execute(
+		"insert into vitess_test values(123, :data, null, null)",
+		map[string]interface{}{"data": "THIS IS A LONG LONG LONG LONG QUERY STRING THAT SHOULD BE SHORTENED"},
+	)
+	want = "Data truncated for column 'floatval' at row 1 (errno 1265) (sqlstate 01000) during query: insert into vitess [TRUNCATED] /* _stream vitess_test (intval ) (123 ); */"
+	if err == nil {
+		t.Errorf("query unexpectedly succeeded")
+	}
+	if err.Error() != want {
+		t.Errorf("log was not truncated properly... got %s, wanted %s", err, want)
+	}
+
+	// Test that trailing comments are preserved data too long error is truncated once the option is set
+	*sqlparser.TruncateErrLen = 30;
+	_, err = client.Execute(
+		"insert into vitess_test values(123, :data, null, null) /* KEEP ME */",
+		map[string]interface{}{"data": "THIS IS A LONG LONG LONG LONG QUERY STRING THAT SHOULD BE SHORTENED"},
+	)
+	want = "Data truncated for column 'floatval' at row 1 (errno 1265) (sqlstate 01000) during query: insert into vitess [TRUNCATED] /* _stream vitess_test (intval ) (123 ); */ /* KEEP ME */"
+	if err == nil {
+		t.Errorf("query unexpectedly succeeded")
+	}
+	if err.Error() != want {
+		t.Errorf("log was not truncated properly... got %s, wanted %s", err, want)
+	}
+}

go/vt/vttablet/tabletserver/query_engine.go

@@ -27,7 +27,6 @@ import (
 	"github.com/youtube/vitess/go/vt/sqlparser"
 	"github.com/youtube/vitess/go/vt/tableacl"
 	tacl "github.com/youtube/vitess/go/vt/tableacl/acl"
-	"github.com/youtube/vitess/go/vt/utils"
 	"github.com/youtube/vitess/go/vt/vterrors"
 	"github.com/youtube/vitess/go/vt/vttablet/tabletserver/connpool"
 	"github.com/youtube/vitess/go/vt/vttablet/tabletserver/planbuilder"
@@ -470,7 +469,7 @@ func (qe *QueryEngine) handleHTTPQueryPlans(response http.ResponseWriter, reques
 	response.Header().Set("Content-Type", "text/plain")
 	response.Write([]byte(fmt.Sprintf("Length: %d\n", len(keys))))
 	for _, v := range keys {
-		response.Write([]byte(fmt.Sprintf("%#v\n", utils.TruncateQuery(v))))
+		response.Write([]byte(fmt.Sprintf("%#v\n", sqlparser.TruncateForUI(v))))
 		if plan := qe.peekQuery(v); plan != nil {
 			if b, err := json.MarshalIndent(plan.Plan, "", "  "); err != nil {
 				response.Write([]byte(err.Error()))
@@ -489,7 +488,7 @@ func (qe *QueryEngine) handleHTTPQueryStats(response http.ResponseWriter, reques
 	for _, v := range keys {
 		if plan := qe.peekQuery(v); plan != nil {
 			var pqstats perQueryStats
-			pqstats.Query = unicoded(utils.TruncateQuery(v))
+			pqstats.Query = unicoded(sqlparser.TruncateForUI(v))
 			pqstats.Table = plan.TableName().String()
 			pqstats.Plan = plan.PlanID
 			pqstats.QueryCount, pqstats.Time, pqstats.MysqlTime, pqstats.RowCount, pqstats.ErrorCount = plan.Stats()

go/vt/vttablet/tabletserver/querylogz.go

@@ -16,8 +16,8 @@ import (
 	log "github.com/golang/glog"
 	"github.com/youtube/vitess/go/acl"
 	"github.com/youtube/vitess/go/vt/logz"
+	"github.com/youtube/vitess/go/vt/sqlparser"
 	"github.com/youtube/vitess/go/vt/vttablet/tabletserver/tabletenv"
-	"github.com/youtube/vitess/go/vt/utils"
 )
 
 var (
@@ -47,7 +47,7 @@ var (
 	querylogzFuncMap = template.FuncMap{
 		"stampMicro":   func(t time.Time) string { return t.Format(time.StampMicro) },
 		"cssWrappable": logz.Wrappable,
-		"truncateQuery": utils.TruncateQuery,
+		"truncateQuery": sqlparser.TruncateForUI,
 		"unquote":      func(s string) string { return strings.Trim(s, "\"") },
 	}
 	querylogzTmpl = template.Must(template.New("example").Funcs(querylogzFuncMap).Parse(`

go/vt/vttablet/tabletserver/querytypes/bound_query.go

@@ -11,6 +11,7 @@ import (
 	"fmt"
 
 	"github.com/youtube/vitess/go/sqltypes"
+	"github.com/youtube/vitess/go/vt/sqlparser"
 )
 
 // This file defines the BoundQuery type.
@@ -36,16 +37,19 @@ type BoundQuery struct {
 // and also truncates data if it's too long
 func QueryAsString(sql string, bindVariables map[string]interface{}) string {
 	buf := &bytes.Buffer{}
-	fmt.Fprintf(buf, "Sql: %q, BindVars: {", slimit(sql, 5000))
+	fmt.Fprintf(buf, "Sql: %q, BindVars: {", sqlparser.TruncateForLog(sql))
 	for k, v := range bindVariables {
+		var valString string;
 		switch val := v.(type) {
 		case []byte:
-			fmt.Fprintf(buf, "%s: %q, ", k, slimit(string(val), 256))
+			valString = string(val);
 		case string:
-			fmt.Fprintf(buf, "%s: %q, ", k, slimit(val, 256))
+			valString = val;
 		default:
-			fmt.Fprintf(buf, "%s: %v, ", k, v)
+			valString = fmt.Sprintf("%v", v);
 		}
+
+		fmt.Fprintf(buf, "%s: %q", k, sqlparser.TruncateForLog(valString));
 	}
 	fmt.Fprintf(buf, "}")
 	return string(buf.Bytes())

go/vt/vttablet/tabletserver/queryz.go

@@ -14,8 +14,8 @@ import (
 	log "github.com/golang/glog"
 	"github.com/youtube/vitess/go/acl"
 	"github.com/youtube/vitess/go/vt/logz"
+	"github.com/youtube/vitess/go/vt/sqlparser"
 	"github.com/youtube/vitess/go/vt/vttablet/tabletserver/planbuilder"
-	"github.com/youtube/vitess/go/vt/utils"
 )
 
 var (
@@ -138,7 +138,7 @@ func queryzHandler(qe *QueryEngine, w http.ResponseWriter, r *http.Request) {
 			continue
 		}
 		Value := &queryzRow{
-			Query:  logz.Wrappable(utils.TruncateQuery(v)),
+			Query:  logz.Wrappable(sqlparser.TruncateForUI(v)),
 			Table:  plan.TableName().String(),
 			Plan:   plan.PlanID,
 			Reason: plan.Reason,

go/vt/vttablet/tabletserver/tabletserver.go

@@ -1337,7 +1337,7 @@ func (tsv *TabletServer) convertError(sql string, bindVariables map[string]inter
 	// If so, we don't want to suppress the error. This will allow VTGate to
 	// detect and perform buffering during failovers.
 	if tsv.TerseErrors && len(bindVariables) != 0 && errCode != vtrpcpb.Code_FAILED_PRECONDITION {
-		errstr = fmt.Sprintf("(errno %d) (sqlstate %s) during query: %s", errnum, sqlState, sql)
+		errstr = fmt.Sprintf("(errno %d) (sqlstate %s) during query: %s", errnum, sqlState, sqlparser.TruncateForLog(sql))
 	}
 	return vterrors.New(errCode, errstr)
 }