From 7f6d94133559208b68acb423db098a047d494774 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Vicent=20Mart=C3=AD?= <42793+vmg@users.noreply.github.com> Date: Mon, 25 Mar 2024 10:12:32 +0100 Subject: [PATCH] logstats: do not allocate memory while logging (#15539) Signed-off-by: Vicent Marti --- go/logstats/logger.go | 217 ++++++++++++++++++ go/vt/vtgate/logstats/logstats.go | 122 +++++----- go/vt/vtgate/logstats/logstats_test.go | 17 +- go/vt/vttablet/filelogger/filelogger_test.go | 2 +- .../sysloglogger/sysloglogger_test.go | 2 +- .../tabletserver/tabletenv/logstats.go | 106 +++++---- .../tabletserver/tabletenv/logstats_test.go | 8 +- 7 files changed, 343 insertions(+), 131 deletions(-) create mode 100644 go/logstats/logger.go diff --git a/go/logstats/logger.go b/go/logstats/logger.go new file mode 100644 index 00000000000..90e208e7703 --- /dev/null +++ b/go/logstats/logger.go @@ -0,0 +1,217 @@ +/* +Copyright 2024 The Vitess Authors. + +Licensed under the Apache License, Version 2.0 (the "License"); +you may not use this file except in compliance with the License. +You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + +Unless required by applicable law or agreed to in writing, software +distributed under the License is distributed on an "AS IS" BASIS, +WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +See the License for the specific language governing permissions and +limitations under the License. +*/ + +package logstats + +import ( + "io" + "slices" + "strconv" + "strings" + "sync" + "time" + + "vitess.io/vitess/go/hack" + "vitess.io/vitess/go/sqltypes" + querypb "vitess.io/vitess/go/vt/proto/query" +) + +type logbv struct { + Name string + BVar *querypb.BindVariable +} + +// Logger is a zero-allocation logger for logstats. +// It can output logs as JSON or as plaintext, following the commonly used +// logstats format that is shared between the tablets and the gates. +type Logger struct { + b []byte + bvars []logbv + n int + json bool +} + +func sortBVars(sorted []logbv, bvars map[string]*querypb.BindVariable) []logbv { + for k, bv := range bvars { + sorted = append(sorted, logbv{k, bv}) + } + slices.SortFunc(sorted, func(a, b logbv) int { + return strings.Compare(a.Name, b.Name) + }) + return sorted +} + +func (log *Logger) appendBVarsJSON(b []byte, bvars map[string]*querypb.BindVariable, full bool) []byte { + log.bvars = sortBVars(log.bvars[:0], bvars) + + b = append(b, '{') + for i, bv := range log.bvars { + if i > 0 { + b = append(b, ',', ' ') + } + b = strconv.AppendQuote(b, bv.Name) + b = append(b, `: {"type": `...) + b = strconv.AppendQuote(b, querypb.Type_name[int32(bv.BVar.Type)]) + b = append(b, `, "value": `...) + + if sqltypes.IsIntegral(bv.BVar.Type) || sqltypes.IsFloat(bv.BVar.Type) { + b = append(b, bv.BVar.Value...) + } else if bv.BVar.Type == sqltypes.Tuple { + b = append(b, '"') + b = strconv.AppendInt(b, int64(len(bv.BVar.Values)), 10) + b = append(b, ` items"`...) + } else { + if full { + b = strconv.AppendQuote(b, hack.String(bv.BVar.Value)) + } else { + b = append(b, '"') + b = strconv.AppendInt(b, int64(len(bv.BVar.Values)), 10) + b = append(b, ` bytes"`...) + } + } + b = append(b, '}') + } + return append(b, '}') +} + +func (log *Logger) Init(json bool) { + log.n = 0 + log.json = json + if log.json { + log.b = append(log.b, '{') + } +} + +func (log *Logger) Redacted() { + log.String("[REDACTED]") +} + +func (log *Logger) Key(key string) { + if log.json { + if log.n > 0 { + log.b = append(log.b, ',', ' ') + } + log.b = append(log.b, '"') + log.b = append(log.b, key...) + log.b = append(log.b, '"', ':', ' ') + } else { + if log.n > 0 { + log.b = append(log.b, '\t') + } + } + log.n++ +} + +func (log *Logger) StringUnquoted(value string) { + if log.json { + log.b = strconv.AppendQuote(log.b, value) + } else { + log.b = append(log.b, value...) + } +} + +func (log *Logger) TabTerminated() { + if !log.json { + log.b = append(log.b, '\t') + } +} + +func (log *Logger) String(value string) { + log.b = strconv.AppendQuote(log.b, value) +} + +func (log *Logger) StringSingleQuoted(value string) { + if log.json { + log.b = strconv.AppendQuote(log.b, value) + } else { + log.b = append(log.b, '\'') + log.b = append(log.b, value...) + log.b = append(log.b, '\'') + } +} + +func (log *Logger) Time(t time.Time) { + const timeFormat = "2006-01-02 15:04:05.000000" + if log.json { + log.b = append(log.b, '"') + log.b = t.AppendFormat(log.b, timeFormat) + log.b = append(log.b, '"') + } else { + log.b = t.AppendFormat(log.b, timeFormat) + } +} + +func (log *Logger) Duration(t time.Duration) { + log.b = strconv.AppendFloat(log.b, t.Seconds(), 'f', 6, 64) +} + +func (log *Logger) BindVariables(bvars map[string]*querypb.BindVariable, full bool) { + // the bind variables are printed as JSON in text mode because the original + // printing syntax, which was simply `fmt.Sprintf("%v")`, is not stable or + // safe to parse + log.b = log.appendBVarsJSON(log.b, bvars, full) +} + +func (log *Logger) Int(i int64) { + log.b = strconv.AppendInt(log.b, i, 10) +} + +func (log *Logger) Uint(u uint64) { + log.b = strconv.AppendUint(log.b, u, 10) +} + +func (log *Logger) Bool(b bool) { + log.b = strconv.AppendBool(log.b, b) +} + +func (log *Logger) Strings(strs []string) { + log.b = append(log.b, '[') + for i, t := range strs { + if i > 0 { + log.b = append(log.b, ',') + } + log.b = strconv.AppendQuote(log.b, t) + } + log.b = append(log.b, ']') +} + +func (log *Logger) Flush(w io.Writer) (err error) { + if log.json { + log.b = append(log.b, '}') + } + log.b = append(log.b, '\n') + _, err = w.Write(log.b) + + clear(log.bvars) + log.bvars = log.bvars[:0] + log.b = log.b[:0] + log.n = 0 + + loggerPool.Put(log) + return err +} + +var loggerPool = sync.Pool{New: func() any { + return &Logger{} +}} + +// NewLogger returns a new Logger instance to perform logstats logging. +// The logger must be initialized with (*Logger).Init before usage and +// flushed with (*Logger).Flush once all the key-values have been written +// to it. +func NewLogger() *Logger { + return loggerPool.Get().(*Logger) +} diff --git a/go/vt/vtgate/logstats/logstats.go b/go/vt/vtgate/logstats/logstats.go index 5ea7820a72e..8f8ba41e3cd 100644 --- a/go/vt/vtgate/logstats/logstats.go +++ b/go/vt/vtgate/logstats/logstats.go @@ -18,21 +18,16 @@ package logstats import ( "context" - "encoding/json" - "fmt" "io" "net/url" "time" "github.com/google/safehtml" - "vitess.io/vitess/go/sqltypes" + "vitess.io/vitess/go/logstats" "vitess.io/vitess/go/streamlog" - "vitess.io/vitess/go/tb" "vitess.io/vitess/go/vt/callerid" "vitess.io/vitess/go/vt/callinfo" - "vitess.io/vitess/go/vt/log" - querypb "vitess.io/vitess/go/vt/proto/query" ) @@ -128,69 +123,60 @@ func (stats *LogStats) Logf(w io.Writer, params url.Values) error { return nil } - // FormatBindVariables call might panic so we're going to catch it here - // and print out the stack trace for debugging. - defer func() { - if x := recover(); x != nil { - log.Errorf("Uncaught panic:\n%v\n%s", x, tb.Stack(4)) - } - }() - - formattedBindVars := "\"[REDACTED]\"" - if !streamlog.GetRedactDebugUIQueries() { - _, fullBindParams := params["full"] - formattedBindVars = sqltypes.FormatBindVariables( - stats.BindVariables, - fullBindParams, - streamlog.GetQueryLogFormat() == streamlog.QueryLogFormatJSON, - ) - } - - // TODO: remove username here we fully enforce immediate caller id + redacted := streamlog.GetRedactDebugUIQueries() + _, fullBindParams := params["full"] remoteAddr, username := stats.RemoteAddrUsername() - var fmtString string - switch streamlog.GetQueryLogFormat() { - case streamlog.QueryLogFormatText: - fmtString = "%v\t%v\t%v\t'%v'\t'%v'\t%v\t%v\t%.6f\t%.6f\t%.6f\t%.6f\t%v\t%q\t%v\t%v\t%v\t%q\t%q\t%q\t%v\t%v\t%q\n" - case streamlog.QueryLogFormatJSON: - fmtString = "{\"Method\": %q, \"RemoteAddr\": %q, \"Username\": %q, \"ImmediateCaller\": %q, \"Effective Caller\": %q, \"Start\": \"%v\", \"End\": \"%v\", \"TotalTime\": %.6f, \"PlanTime\": %v, \"ExecuteTime\": %v, \"CommitTime\": %v, \"StmtType\": %q, \"SQL\": %q, \"BindVars\": %v, \"ShardQueries\": %v, \"RowsAffected\": %v, \"Error\": %q, \"TabletType\": %q, \"SessionUUID\": %q, \"Cached Plan\": %v, \"TablesUsed\": %v, \"ActiveKeyspace\": %q}\n" - } - - tables := stats.TablesUsed - if tables == nil { - tables = []string{} - } - tablesUsed, marshalErr := json.Marshal(tables) - if marshalErr != nil { - return marshalErr + log := logstats.NewLogger() + log.Init(streamlog.GetQueryLogFormat() == streamlog.QueryLogFormatJSON) + log.Key("Method") + log.StringUnquoted(stats.Method) + log.Key("RemoteAddr") + log.StringUnquoted(remoteAddr) + log.Key("Username") + log.StringUnquoted(username) + log.Key("ImmediateCaller") + log.StringSingleQuoted(stats.ImmediateCaller()) + log.Key("Effective Caller") + log.StringSingleQuoted(stats.EffectiveCaller()) + log.Key("Start") + log.Time(stats.StartTime) + log.Key("End") + log.Time(stats.EndTime) + log.Key("TotalTime") + log.Duration(stats.TotalTime()) + log.Key("PlanTime") + log.Duration(stats.PlanTime) + log.Key("ExecuteTime") + log.Duration(stats.ExecuteTime) + log.Key("CommitTime") + log.Duration(stats.CommitTime) + log.Key("StmtType") + log.StringUnquoted(stats.StmtType) + log.Key("SQL") + log.String(stats.SQL) + log.Key("BindVars") + if redacted { + log.Redacted() + } else { + log.BindVariables(stats.BindVariables, fullBindParams) } - _, err := fmt.Fprintf( - w, - fmtString, - stats.Method, - remoteAddr, - username, - stats.ImmediateCaller(), - stats.EffectiveCaller(), - stats.StartTime.Format("2006-01-02 15:04:05.000000"), - stats.EndTime.Format("2006-01-02 15:04:05.000000"), - stats.TotalTime().Seconds(), - stats.PlanTime.Seconds(), - stats.ExecuteTime.Seconds(), - stats.CommitTime.Seconds(), - stats.StmtType, - stats.SQL, - formattedBindVars, - stats.ShardQueries, - stats.RowsAffected, - stats.ErrorStr(), - stats.TabletType, - stats.SessionUUID, - stats.CachedPlan, - string(tablesUsed), - stats.ActiveKeyspace, - ) - - return err + log.Key("ShardQueries") + log.Uint(stats.ShardQueries) + log.Key("RowsAffected") + log.Uint(stats.RowsAffected) + log.Key("Error") + log.String(stats.ErrorStr()) + log.Key("TabletType") + log.String(stats.TabletType) + log.Key("SessionUUID") + log.String(stats.SessionUUID) + log.Key("Cached Plan") + log.Bool(stats.CachedPlan) + log.Key("TablesUsed") + log.Strings(stats.TablesUsed) + log.Key("ActiveKeyspace") + log.String(stats.ActiveKeyspace) + + return log.Flush(w) } diff --git a/go/vt/vtgate/logstats/logstats_test.go b/go/vt/vtgate/logstats/logstats_test.go index dbe49b200b8..ae3c01e0f0b 100644 --- a/go/vt/vtgate/logstats/logstats_test.go +++ b/go/vt/vtgate/logstats/logstats_test.go @@ -79,7 +79,7 @@ func TestLogStatsFormat(t *testing.T) { { // 0 redact: false, format: "text", - expected: "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1\"\tmap[intVal:type:INT64 value:\"1\"]\t0\t0\t\"\"\t\"PRIMARY\"\t\"suuid\"\tfalse\t[\"ks1.tbl1\",\"ks2.tbl2\"]\t\"db\"\n", + expected: "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t0\t0\t\"\"\t\"PRIMARY\"\t\"suuid\"\tfalse\t[\"ks1.tbl1\",\"ks2.tbl2\"]\t\"db\"\n", bindVars: intBindVar, }, { // 1 redact: true, @@ -99,7 +99,7 @@ func TestLogStatsFormat(t *testing.T) { }, { // 4 redact: false, format: "text", - expected: "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1\"\tmap[strVal:type:VARCHAR value:\"abc\"]\t0\t0\t\"\"\t\"PRIMARY\"\t\"suuid\"\tfalse\t[\"ks1.tbl1\",\"ks2.tbl2\"]\t\"db\"\n", + expected: "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1\"\t{\"strVal\": {\"type\": \"VARCHAR\", \"value\": \"abc\"}}\t0\t0\t\"\"\t\"PRIMARY\"\t\"suuid\"\tfalse\t[\"ks1.tbl1\",\"ks2.tbl2\"]\t\"db\"\n", bindVars: stringBindVar, }, { // 5 redact: true, @@ -129,14 +129,13 @@ func TestLogStatsFormat(t *testing.T) { streamlog.SetQueryLogFormat(test.format) if test.format == "text" { got := testFormat(t, logStats, params) + t.Logf("got: %s", got) assert.Equal(t, test.expected, got) - for _, variable := range logStats.BindVariables { - fmt.Println("->" + fmt.Sprintf("%v", variable)) - } return } got := testFormat(t, logStats, params) + t.Logf("got: %s", got) var parsed map[string]any err := json.Unmarshal([]byte(got), &parsed) assert.NoError(t, err) @@ -157,12 +156,12 @@ func TestLogStatsFilter(t *testing.T) { params := map[string][]string{"full": {}} got := testFormat(t, logStats, params) - want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\"]\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n" + want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n" assert.Equal(t, want, got) streamlog.SetQueryLogFilterTag("LOG_THIS_QUERY") got = testFormat(t, logStats, params) - want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\"]\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n" + want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n" assert.Equal(t, want, got) streamlog.SetQueryLogFilterTag("NOT_THIS_QUERY") @@ -180,12 +179,12 @@ func TestLogStatsRowThreshold(t *testing.T) { params := map[string][]string{"full": {}} got := testFormat(t, logStats, params) - want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\"]\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n" + want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n" assert.Equal(t, want, got) streamlog.SetQueryLogRowThreshold(0) got = testFormat(t, logStats, params) - want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\"]\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n" + want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t0\t0\t\"\"\t\"\"\t\"\"\tfalse\t[]\t\"\"\n" assert.Equal(t, want, got) streamlog.SetQueryLogRowThreshold(1) got = testFormat(t, logStats, params) diff --git a/go/vt/vttablet/filelogger/filelogger_test.go b/go/vt/vttablet/filelogger/filelogger_test.go index 1562c9626a8..f747ebba93b 100644 --- a/go/vt/vttablet/filelogger/filelogger_test.go +++ b/go/vt/vttablet/filelogger/filelogger_test.go @@ -60,7 +60,7 @@ func TestFileLog(t *testing.T) { for i := 0; i < 10; i++ { time.Sleep(10 * time.Millisecond) - want := "\t\t\t''\t''\t0001-01-01 00:00:00.000000\t0001-01-01 00:00:00.000000\t0.000000\t\t\"test 1\"\tmap[]\t1\t\"test 1 PII\"\tmysql\t0.000000\t0.000000\t0\t0\t0\t\"\"\t\n\t\t\t''\t''\t0001-01-01 00:00:00.000000\t0001-01-01 00:00:00.000000\t0.000000\t\t\"test 2\"\tmap[]\t1\t\"test 2 PII\"\tmysql\t0.000000\t0.000000\t0\t0\t0\t\"\"\t\n" + want := "\t\t\t''\t''\t0001-01-01 00:00:00.000000\t0001-01-01 00:00:00.000000\t0.000000\t\t\"test 1\"\t{}\t1\t\"test 1 PII\"\tmysql\t0.000000\t0.000000\t0\t0\t0\t\"\"\t\n\t\t\t''\t''\t0001-01-01 00:00:00.000000\t0001-01-01 00:00:00.000000\t0.000000\t\t\"test 2\"\t{}\t1\t\"test 2 PII\"\tmysql\t0.000000\t0.000000\t0\t0\t0\t\"\"\t\n" contents, _ := os.ReadFile(logPath) got := string(contents) if want == got { diff --git a/go/vt/vttablet/sysloglogger/sysloglogger_test.go b/go/vt/vttablet/sysloglogger/sysloglogger_test.go index c62a4396ac6..8347d0433af 100644 --- a/go/vt/vttablet/sysloglogger/sysloglogger_test.go +++ b/go/vt/vttablet/sysloglogger/sysloglogger_test.go @@ -85,7 +85,7 @@ func (fw *failingFakeWriter) Close() error { return nil } // expectedLogStatsText returns the results expected from the plugin processing a dummy message generated by mockLogStats(...). func expectedLogStatsText(originalSQL string) string { return fmt.Sprintf("Execute\t\t\t''\t''\t0001-01-01 00:00:00.000000\t0001-01-01 00:00:00.000000\t0.000000\tPASS_SELECT\t"+ - "\"%s\"\t%s\t1\t\"%s\"\tmysql\t0.000000\t0.000000\t0\t0\t0\t\"\"", originalSQL, "map[]", originalSQL) + "\"%s\"\t%s\t1\t\"%s\"\tmysql\t0.000000\t0.000000\t0\t0\t0\t\"\"", originalSQL, "{}", originalSQL) } // expectedRedactedLogStatsText returns the results expected from the plugin processing a dummy message generated by mockLogStats(...) diff --git a/go/vt/vttablet/tabletserver/tabletenv/logstats.go b/go/vt/vttablet/tabletserver/tabletenv/logstats.go index 962b5f0b122..ad7e09de169 100644 --- a/go/vt/vttablet/tabletserver/tabletenv/logstats.go +++ b/go/vt/vttablet/tabletserver/tabletenv/logstats.go @@ -18,7 +18,6 @@ package tabletenv import ( "context" - "fmt" "io" "net/url" "strings" @@ -26,6 +25,7 @@ import ( "github.com/google/safehtml" + "vitess.io/vitess/go/logstats" "vitess.io/vitess/go/sqltypes" "vitess.io/vitess/go/streamlog" "vitess.io/vitess/go/vt/callerid" @@ -181,55 +181,65 @@ func (stats *LogStats) Logf(w io.Writer, params url.Values) error { return nil } - rewrittenSQL := "[REDACTED]" - formattedBindVars := "\"[REDACTED]\"" - - if !streamlog.GetRedactDebugUIQueries() { - rewrittenSQL = stats.RewrittenSQL() - - _, fullBindParams := params["full"] - formattedBindVars = sqltypes.FormatBindVariables( - stats.BindVariables, - fullBindParams, - streamlog.GetQueryLogFormat() == streamlog.QueryLogFormatJSON, - ) - } - + redacted := streamlog.GetRedactDebugUIQueries() + _, fullBindParams := params["full"] // TODO: remove username here we fully enforce immediate caller id callInfo, username := stats.CallInfo() - // Valid options for the QueryLogFormat are text or json - var fmtString string - switch streamlog.GetQueryLogFormat() { - case streamlog.QueryLogFormatText: - fmtString = "%v\t%v\t%v\t'%v'\t'%v'\t%v\t%v\t%.6f\t%v\t%q\t%v\t%v\t%q\t%v\t%.6f\t%.6f\t%v\t%v\t%v\t%q\t\n" - case streamlog.QueryLogFormatJSON: - fmtString = "{\"Method\": %q, \"CallInfo\": %q, \"Username\": %q, \"ImmediateCaller\": %q, \"Effective Caller\": %q, \"Start\": \"%v\", \"End\": \"%v\", \"TotalTime\": %.6f, \"PlanType\": %q, \"OriginalSQL\": %q, \"BindVars\": %v, \"Queries\": %v, \"RewrittenSQL\": %q, \"QuerySources\": %q, \"MysqlTime\": %.6f, \"ConnWaitTime\": %.6f, \"RowsAffected\": %v,\"TransactionID\": %v,\"ResponseSize\": %v, \"Error\": %q}\n" + log := logstats.NewLogger() + log.Init(streamlog.GetQueryLogFormat() == streamlog.QueryLogFormatJSON) + log.Key("Method") + log.StringUnquoted(stats.Method) + log.Key("CallInfo") + log.StringUnquoted(callInfo) + log.Key("Username") + log.StringUnquoted(username) + log.Key("ImmediateCaller") + log.StringSingleQuoted(stats.ImmediateCaller()) + log.Key("Effective Caller") + log.StringSingleQuoted(stats.EffectiveCaller()) + log.Key("Start") + log.Time(stats.StartTime) + log.Key("End") + log.Time(stats.EndTime) + log.Key("TotalTime") + log.Duration(stats.TotalTime()) + log.Key("PlanType") + log.StringUnquoted(stats.PlanType) + log.Key("OriginalSQL") + log.String(stats.OriginalSQL) + log.Key("BindVars") + if redacted { + log.Redacted() + } else { + log.BindVariables(stats.BindVariables, fullBindParams) } - - _, err := fmt.Fprintf( - w, - fmtString, - stats.Method, - callInfo, - username, - stats.ImmediateCaller(), - stats.EffectiveCaller(), - stats.StartTime.Format("2006-01-02 15:04:05.000000"), - stats.EndTime.Format("2006-01-02 15:04:05.000000"), - stats.TotalTime().Seconds(), - stats.PlanType, - stats.OriginalSQL, - formattedBindVars, - stats.NumberOfQueries, - rewrittenSQL, - stats.FmtQuerySources(), - stats.MysqlResponseTime.Seconds(), - stats.WaitingForConnection.Seconds(), - stats.RowsAffected, - stats.TransactionID, - stats.SizeOfResponse(), - stats.ErrorStr(), - ) - return err + log.Key("Queries") + log.Int(int64(stats.NumberOfQueries)) + log.Key("RewrittenSQL") + if redacted { + log.Redacted() + } else { + log.String(stats.RewrittenSQL()) + } + log.Key("QuerySources") + log.StringUnquoted(stats.FmtQuerySources()) + log.Key("MysqlTime") + log.Duration(stats.MysqlResponseTime) + log.Key("ConnWaitTime") + log.Duration(stats.WaitingForConnection) + log.Key("RowsAffected") + log.Uint(uint64(stats.RowsAffected)) + log.Key("TransactionID") + log.Int(stats.TransactionID) + log.Key("ResponseSize") + log.Int(int64(stats.SizeOfResponse())) + log.Key("Error") + log.String(stats.ErrorStr()) + + // logstats from the vttablet are always tab-terminated; keep this for backwards + // compatibility for existing parsers + log.TabTerminated() + + return log.Flush(w) } diff --git a/go/vt/vttablet/tabletserver/tabletenv/logstats_test.go b/go/vt/vttablet/tabletserver/tabletenv/logstats_test.go index 84de50aae74..f04b1498982 100644 --- a/go/vt/vttablet/tabletserver/tabletenv/logstats_test.go +++ b/go/vt/vttablet/tabletserver/tabletenv/logstats_test.go @@ -74,7 +74,7 @@ func TestLogStatsFormat(t *testing.T) { streamlog.SetRedactDebugUIQueries(false) streamlog.SetQueryLogFormat("text") got := testFormat(logStats, url.Values(params)) - want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql\"\tmap[intVal:type:INT64 value:\"1\"]\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t12345\t1\t\"\"\t\n" + want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t12345\t1\t\"\"\t\n" if got != want { t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want) } @@ -128,7 +128,7 @@ func TestLogStatsFormat(t *testing.T) { streamlog.SetQueryLogFormat("text") got = testFormat(logStats, url.Values(params)) - want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql\"\tmap[strVal:type:VARCHAR value:\"abc\"]\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t12345\t1\t\"\"\t\n" + want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql\"\t{\"strVal\": {\"type\": \"VARCHAR\", \"value\": \"abc\"}}\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t12345\t1\t\"\"\t\n" if got != want { t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want) } @@ -165,14 +165,14 @@ func TestLogStatsFilter(t *testing.T) { params := map[string][]string{"full": {}} got := testFormat(logStats, url.Values(params)) - want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\"]\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t0\t1\t\"\"\t\n" + want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql /* LOG_THIS_QUERY */\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t0\t1\t\"\"\t\n" if got != want { t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want) } streamlog.SetQueryLogFilterTag("LOG_THIS_QUERY") got = testFormat(logStats, url.Values(params)) - want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\"]\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t0\t1\t\"\"\t\n" + want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql /* LOG_THIS_QUERY */\"\t{\"intVal\": {\"type\": \"INT64\", \"value\": 1}}\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t0\t1\t\"\"\t\n" if got != want { t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want) }