diff --git a/go/sqldb/sql_error.go b/go/sqldb/sql_error.go index b5ca9de6308..46b5e3280f5 100644 --- a/go/sqldb/sql_error.go +++ b/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() } diff --git a/go/vt/sqlparser/parsed_query.go b/go/vt/sqlparser/parsed_query.go index 93846301104..78e202de713 100644 --- a/go/vt/sqlparser/parsed_query.go +++ b/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. diff --git a/go/vt/sqlparser/truncate_query.go b/go/vt/sqlparser/truncate_query.go new file mode 100644 index 00000000000..62d5ee58383 --- /dev/null +++ b/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) +} diff --git a/go/vt/utils/utils.go b/go/vt/utils/utils.go index f931491b691..398aecd8ddc 100644 --- a/go/vt/utils/utils.go +++ b/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]" -} diff --git a/go/vt/vtgate/planner.go b/go/vt/vtgate/planner.go index 0a7230007bc..aafd6f89628 100644 --- a/go/vt/vtgate/planner.go +++ b/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())) diff --git a/go/vt/vtgate/vtgate.go b/go/vt/vtgate/vtgate.go index ea7cc4bebc2..ffa54f40d56 100644 --- a/go/vt/vtgate/vtgate.go +++ b/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 { diff --git a/go/vt/vtgate/vtgate_test.go b/go/vt/vtgate/vtgate_test.go index 11f86bcc498..4b0a1634e93 100644 --- a/go/vt/vtgate/vtgate_test.go +++ b/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) + } +} diff --git a/go/vt/vttablet/endtoend/misc_test.go b/go/vt/vttablet/endtoend/misc_test.go index be7db90df43..ed0f53b75e6 100644 --- a/go/vt/vttablet/endtoend/misc_test.go +++ b/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) + } +} diff --git a/go/vt/vttablet/tabletserver/query_engine.go b/go/vt/vttablet/tabletserver/query_engine.go index d5161f570b9..5def3ae4eaa 100644 --- a/go/vt/vttablet/tabletserver/query_engine.go +++ b/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() diff --git a/go/vt/vttablet/tabletserver/querylogz.go b/go/vt/vttablet/tabletserver/querylogz.go index 5ecc571cf1f..15554e01797 100644 --- a/go/vt/vttablet/tabletserver/querylogz.go +++ b/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(` diff --git a/go/vt/vttablet/tabletserver/querytypes/bound_query.go b/go/vt/vttablet/tabletserver/querytypes/bound_query.go index ccdc2aeb539..06d037af289 100644 --- a/go/vt/vttablet/tabletserver/querytypes/bound_query.go +++ b/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()) diff --git a/go/vt/vttablet/tabletserver/queryz.go b/go/vt/vttablet/tabletserver/queryz.go index 2df736d000f..0774db8824b 100644 --- a/go/vt/vttablet/tabletserver/queryz.go +++ b/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, diff --git a/go/vt/vttablet/tabletserver/tabletserver.go b/go/vt/vttablet/tabletserver/tabletserver.go index 3f2ba36651d..30d881a6dca 100644 --- a/go/vt/vttablet/tabletserver/tabletserver.go +++ b/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) }