From 65b4bd9ef6cce66f3984da1247e6be24f4da5416 Mon Sep 17 00:00:00 2001 From: Vilius Okockis Date: Tue, 16 Apr 2024 16:50:20 +0300 Subject: [PATCH] base64 encode bindvar strings in json, inspired by https://github.com/vitessio/vitess/pull/15271 Signed-off-by: Vilius Okockis --- go/logstats/logger.go | 64 ++++-- go/streamlog/streamlog.go | 3 + go/vt/vtgate/logstats.go | 3 + go/vt/vtgate/logstats_test.go | 181 +++++++++++++++++ .../tabletserver/tabletenv/logstats.go | 3 + .../tabletserver/tabletenv/logstats_test.go | 184 ++++++++++++++++++ 6 files changed, 420 insertions(+), 18 deletions(-) diff --git a/go/logstats/logger.go b/go/logstats/logger.go index 7aebbb1263c..a035532558d 100644 --- a/go/logstats/logger.go +++ b/go/logstats/logger.go @@ -17,6 +17,7 @@ limitations under the License. package logstats import ( + "encoding/base64" "io" "sort" "strconv" @@ -29,24 +30,6 @@ import ( querypb "vitess.io/vitess/go/vt/proto/query" ) -type CommonLogger interface { - Init(json bool) - Redacted() - Key(key string) - StringUnquoted(value string) - TabTerminated() - String(value string) - StringSingleQuoted(value string) - Time(t time.Time) - Duration(t time.Duration) - BindVariables(bvars map[string]*querypb.BindVariable, full bool) - Int(i int64) - Uint(u uint64) - Bool(b bool) - Strings(strs []string) - Flush(w io.Writer) error -} - type logbv struct { Name string BVar *querypb.BindVariable @@ -108,6 +91,43 @@ func (log *Logger) appendBVarsJSON(b []byte, bvars map[string]*querypb.BindVaria return append(b, '}') } +// appendBVarsJSONV2 is a new version of appendBVarsJSON that uses base64 encoding +func (log *Logger) appendBVarsJSONV2(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 { + buf := make([]byte, base64.StdEncoding.EncodedLen(len(bv.BVar.Value))) + base64.StdEncoding.Encode(buf, bv.BVar.Value) + b = strconv.AppendQuote(b, hack.String(buf)) + } 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 @@ -186,6 +206,14 @@ func (log *Logger) BindVariables(bvars map[string]*querypb.BindVariable, full bo log.b = log.appendBVarsJSON(log.b, bvars, full) } +// BindVariablesV2 is a new version of BindVariables that uses base64 encoding +func (log *Logger) BindVariablesV2(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.appendBVarsJSONV2(log.b, bvars, full) +} + func (log *Logger) Int(i int64) { log.b = strconv.AppendInt(log.b, i, 10) } diff --git a/go/streamlog/streamlog.go b/go/streamlog/streamlog.go index 32fdb6be241..038c566778c 100644 --- a/go/streamlog/streamlog.go +++ b/go/streamlog/streamlog.go @@ -41,6 +41,9 @@ var ( // QueryLogFormat controls the format of the query log (either text or json) QueryLogFormat = flag.String("querylog-format", "text", "format for query logs (\"text\" or \"json\")") + // QueryLogJSONV2 controls whether the new querylog json format is used + QueryLogJSONV2 = flag.Bool("querylog-json-v2", false, "use v2 format for querylog-format=json") + // QueryLogFilterTag contains an optional string that must be present in the query for it to be logged QueryLogFilterTag = flag.String("querylog-filter-tag", "", "string that must be present in the query for it to be logged; if using a value as the tag, you need to disable query normalization") diff --git a/go/vt/vtgate/logstats.go b/go/vt/vtgate/logstats.go index fb179126b6f..e37d6321724 100644 --- a/go/vt/vtgate/logstats.go +++ b/go/vt/vtgate/logstats.go @@ -129,6 +129,7 @@ func (stats *LogStats) Logf(w io.Writer, params url.Values) error { } redacted := *streamlog.RedactDebugUIQueries + jsonV2 := *streamlog.QueryLogJSONV2 _, fullBindParams := params["full"] remoteAddr, username := stats.RemoteAddrUsername() @@ -163,6 +164,8 @@ func (stats *LogStats) Logf(w io.Writer, params url.Values) error { log.Key("BindVars") if redacted { log.Redacted() + } else if jsonV2 { + log.BindVariablesV2(stats.BindVariables, fullBindParams) } else { log.BindVariables(stats.BindVariables, fullBindParams) } diff --git a/go/vt/vtgate/logstats_test.go b/go/vt/vtgate/logstats_test.go index 5262898230f..7a30f7f832c 100644 --- a/go/vt/vtgate/logstats_test.go +++ b/go/vt/vtgate/logstats_test.go @@ -240,3 +240,184 @@ func TestLogStatsRemoteAddrUsername(t *testing.T) { t.Fatalf("expected to get username: %s, but got: %s", username, user) } } + +func TestLogStatsFormatJSONV2(t *testing.T) { + defer func() { + *streamlog.QueryLogFormat = "text" + *streamlog.QueryLogJSONV2 = false + }() + *streamlog.QueryLogFormat = "json" + *streamlog.QueryLogJSONV2 = true + params := map[string][]string{"full": {}} + logStats := NewLogStats(context.Background(), "test", "sql1", "suuid", nil) + logStats.StartTime = time.Date(2017, time.January, 1, 1, 2, 3, 0, time.UTC) + logStats.EndTime = time.Date(2017, time.January, 1, 1, 2, 4, 1234, time.UTC) + logStats.BindVariables = map[string]*querypb.BindVariable{} + testsEncoded := []struct { + bindVar *querypb.BindVariable + expected string + }{ + { + &querypb.BindVariable{Type: querypb.Type_BINARY, Value: []byte("abc")}, + "YWJj", + }, { + &querypb.BindVariable{Type: querypb.Type_BIT, Value: []byte("134")}, + "MTM0", + }, { + &querypb.BindVariable{Type: querypb.Type_BLOB, Value: []byte("a")}, + "YQ==", + }, { + &querypb.BindVariable{Type: querypb.Type_CHAR, Value: []byte("a")}, + "YQ==", + }, { + &querypb.BindVariable{Type: querypb.Type_DATE, Value: []byte("2012-02-24")}, + "MjAxMi0wMi0yNA==", + }, { + &querypb.BindVariable{Type: querypb.Type_DATETIME, Value: []byte("2012-02-24 23:19:43")}, + "MjAxMi0wMi0yNCAyMzoxOTo0Mw==", + }, { + &querypb.BindVariable{Type: querypb.Type_DECIMAL, Value: []byte("1.00")}, + "MS4wMA==", + }, { + &querypb.BindVariable{Type: querypb.Type_ENUM, Value: []byte("a")}, + "YQ==", + }, { + &querypb.BindVariable{Type: querypb.Type_SET, Value: []byte("a")}, + "YQ==", + }, { + &querypb.BindVariable{Type: querypb.Type_TEXT, Value: []byte("a")}, + "YQ==", + }, { + &querypb.BindVariable{Type: querypb.Type_TIME, Value: []byte("23:19:43")}, + "MjM6MTk6NDM=", + }, { + &querypb.BindVariable{Type: querypb.Type_TIMESTAMP, Value: []byte("2012-02-24 23:19:43")}, + "MjAxMi0wMi0yNCAyMzoxOTo0Mw==", + }, + } + + for i, test := range testsEncoded { + t.Run(strconv.Itoa(i), func(t *testing.T) { + logStats.BindVariables["vtg"] = test.bindVar + got := testFormat(t, logStats, params) + t.Logf("got: %s", got) + var parsed map[string]interface{} + err := json.Unmarshal([]byte(got), &parsed) + assert.NoError(t, err) + assert.NotNil(t, parsed) + bindVal := parsed["BindVars"].(map[string]interface{})["vtg"].(map[string]interface{})["value"] + + assert.Equal(t, test.expected, bindVal) + }) + } + + testsUnchanged := []struct { + bindVar *querypb.BindVariable + expected interface{} + }{ + { + &querypb.BindVariable{Type: querypb.Type_FLOAT32, Value: []byte("1.00")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_FLOAT64, Value: []byte("1.00")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_INT8, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_INT16, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_INT24, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_INT32, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_INT64, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_UINT8, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_UINT16, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_UINT24, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_UINT32, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_UINT64, Value: []byte("1")}, + float64(1), + }, + } + + for i, test := range testsUnchanged { + t.Run(strconv.Itoa(i), func(t *testing.T) { + logStats.BindVariables["vtg"] = test.bindVar + got := testFormat(t, logStats, params) + t.Logf("got: %s", got) + var parsed map[string]interface{} + err := json.Unmarshal([]byte(got), &parsed) + assert.NoError(t, err) + assert.NotNil(t, parsed) + bindVal := parsed["BindVars"].(map[string]interface{})["vtg"].(map[string]interface{})["value"] + + assert.Equal(t, test.expected, bindVal) + }) + } + + testsUnchangedTuples := []struct { + bindVar *querypb.BindVariable + expected string + }{ + { + &querypb.BindVariable{Type: querypb.Type_TUPLE, Values: []*querypb.Value{ + {Type: querypb.Type_FLOAT64, Value: []byte("1")}, + {Type: querypb.Type_FLOAT64, Value: []byte("2")}, + }}, + "2 items", + }, { + &querypb.BindVariable{Type: querypb.Type_TUPLE, Values: []*querypb.Value{ + {Type: querypb.Type_INT64, Value: []byte("1")}, + {Type: querypb.Type_INT64, Value: []byte("2")}, + }}, + "2 items", + }, { + &querypb.BindVariable{Type: querypb.Type_TUPLE, Values: []*querypb.Value{ + {Type: querypb.Type_UINT64, Value: []byte("1")}, + {Type: querypb.Type_UINT64, Value: []byte("2")}, + }}, + "2 items", + }, { + &querypb.BindVariable{Type: querypb.Type_TUPLE, Values: []*querypb.Value{ + {Type: querypb.Type_VARBINARY, Value: []byte("aa")}, + {Type: querypb.Type_VARBINARY, Value: []byte("bb")}, + }}, + "2 items", + }, { + &querypb.BindVariable{Type: querypb.Type_TUPLE, Values: []*querypb.Value{ + {Type: querypb.Type_VARBINARY, Value: []byte("aa")}, + {Type: querypb.Type_INT64, Value: []byte("1")}, + }}, + "2 items", + }, + } + + for i, test := range testsUnchangedTuples { + t.Run(strconv.Itoa(i), func(t *testing.T) { + logStats.BindVariables["vtg"] = test.bindVar + got := testFormat(t, logStats, params) + t.Logf("got: %s", got) + var parsed map[string]interface{} + err := json.Unmarshal([]byte(got), &parsed) + assert.NoError(t, err) + assert.NotNil(t, parsed) + bindVal := parsed["BindVars"].(map[string]interface{})["vtg"].(map[string]interface{})["value"] + + assert.Equal(t, test.expected, bindVal) + }) + } +} diff --git a/go/vt/vttablet/tabletserver/tabletenv/logstats.go b/go/vt/vttablet/tabletserver/tabletenv/logstats.go index 823f7cd50a6..71980c5a488 100644 --- a/go/vt/vttablet/tabletserver/tabletenv/logstats.go +++ b/go/vt/vttablet/tabletserver/tabletenv/logstats.go @@ -186,6 +186,7 @@ func (stats *LogStats) Logf(w io.Writer, params url.Values) error { } redacted := *streamlog.RedactDebugUIQueries + jsonV2 := *streamlog.QueryLogJSONV2 _, fullBindParams := params["full"] // TODO: remove username here we fully enforce immediate caller id callInfo, username := stats.CallInfo() @@ -215,6 +216,8 @@ func (stats *LogStats) Logf(w io.Writer, params url.Values) error { log.Key("BindVars") if redacted { log.Redacted() + } else if jsonV2 { + log.BindVariablesV2(stats.BindVariables, fullBindParams) } else { log.BindVariables(stats.BindVariables, fullBindParams) } diff --git a/go/vt/vttablet/tabletserver/tabletenv/logstats_test.go b/go/vt/vttablet/tabletserver/tabletenv/logstats_test.go index 82e909fb4d5..6ae7783806f 100644 --- a/go/vt/vttablet/tabletserver/tabletenv/logstats_test.go +++ b/go/vt/vttablet/tabletserver/tabletenv/logstats_test.go @@ -21,12 +21,15 @@ import ( "encoding/json" "errors" "net/url" + "strconv" "strings" "testing" "time" "context" + "github.com/stretchr/testify/assert" + "vitess.io/vitess/go/sqltypes" "vitess.io/vitess/go/streamlog" "vitess.io/vitess/go/vt/callinfo" @@ -254,3 +257,184 @@ func TestLogStatsCallInfo(t *testing.T) { t.Fatalf("expected to get username: %s, but got: %s", username, user) } } + +func TestLogStatsFormatJSONV2(t *testing.T) { + defer func() { + *streamlog.QueryLogFormat = "text" + *streamlog.QueryLogJSONV2 = false + }() + *streamlog.QueryLogFormat = "json" + *streamlog.QueryLogJSONV2 = true + params := map[string][]string{"full": {}} + logStats := NewLogStats(context.Background(), "test") + logStats.StartTime = time.Date(2017, time.January, 1, 1, 2, 3, 0, time.UTC) + logStats.EndTime = time.Date(2017, time.January, 1, 1, 2, 4, 1234, time.UTC) + logStats.BindVariables = map[string]*querypb.BindVariable{} + testsEncoded := []struct { + bindVar *querypb.BindVariable + expected string + }{ + { + &querypb.BindVariable{Type: querypb.Type_BINARY, Value: []byte("abc")}, + "YWJj", + }, { + &querypb.BindVariable{Type: querypb.Type_BIT, Value: []byte("134")}, + "MTM0", + }, { + &querypb.BindVariable{Type: querypb.Type_BLOB, Value: []byte("a")}, + "YQ==", + }, { + &querypb.BindVariable{Type: querypb.Type_CHAR, Value: []byte("a")}, + "YQ==", + }, { + &querypb.BindVariable{Type: querypb.Type_DATE, Value: []byte("2012-02-24")}, + "MjAxMi0wMi0yNA==", + }, { + &querypb.BindVariable{Type: querypb.Type_DATETIME, Value: []byte("2012-02-24 23:19:43")}, + "MjAxMi0wMi0yNCAyMzoxOTo0Mw==", + }, { + &querypb.BindVariable{Type: querypb.Type_DECIMAL, Value: []byte("1.00")}, + "MS4wMA==", + }, { + &querypb.BindVariable{Type: querypb.Type_ENUM, Value: []byte("a")}, + "YQ==", + }, { + &querypb.BindVariable{Type: querypb.Type_SET, Value: []byte("a")}, + "YQ==", + }, { + &querypb.BindVariable{Type: querypb.Type_TEXT, Value: []byte("a")}, + "YQ==", + }, { + &querypb.BindVariable{Type: querypb.Type_TIME, Value: []byte("23:19:43")}, + "MjM6MTk6NDM=", + }, { + &querypb.BindVariable{Type: querypb.Type_TIMESTAMP, Value: []byte("2012-02-24 23:19:43")}, + "MjAxMi0wMi0yNCAyMzoxOTo0Mw==", + }, + } + + for i, test := range testsEncoded { + t.Run(strconv.Itoa(i), func(t *testing.T) { + logStats.BindVariables["vtg"] = test.bindVar + got := testFormat(logStats, url.Values(params)) + t.Logf("got: %s", got) + var parsed map[string]interface{} + err := json.Unmarshal([]byte(got), &parsed) + assert.NoError(t, err) + assert.NotNil(t, parsed) + bindVal := parsed["BindVars"].(map[string]interface{})["vtg"].(map[string]interface{})["value"] + + assert.Equal(t, test.expected, bindVal) + }) + } + + testsUnchanged := []struct { + bindVar *querypb.BindVariable + expected interface{} + }{ + { + &querypb.BindVariable{Type: querypb.Type_FLOAT32, Value: []byte("1.00")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_FLOAT64, Value: []byte("1.00")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_INT8, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_INT16, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_INT24, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_INT32, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_INT64, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_UINT8, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_UINT16, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_UINT24, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_UINT32, Value: []byte("1")}, + float64(1), + }, { + &querypb.BindVariable{Type: querypb.Type_UINT64, Value: []byte("1")}, + float64(1), + }, + } + + for i, test := range testsUnchanged { + t.Run(strconv.Itoa(i), func(t *testing.T) { + logStats.BindVariables["vtg"] = test.bindVar + got := testFormat(logStats, url.Values(params)) + t.Logf("got: %s", got) + var parsed map[string]interface{} + err := json.Unmarshal([]byte(got), &parsed) + assert.NoError(t, err) + assert.NotNil(t, parsed) + bindVal := parsed["BindVars"].(map[string]interface{})["vtg"].(map[string]interface{})["value"] + + assert.Equal(t, test.expected, bindVal) + }) + } + + testsUnchangedTuples := []struct { + bindVar *querypb.BindVariable + expected string + }{ + { + &querypb.BindVariable{Type: querypb.Type_TUPLE, Values: []*querypb.Value{ + {Type: querypb.Type_FLOAT64, Value: []byte("1")}, + {Type: querypb.Type_FLOAT64, Value: []byte("2")}, + }}, + "2 items", + }, { + &querypb.BindVariable{Type: querypb.Type_TUPLE, Values: []*querypb.Value{ + {Type: querypb.Type_INT64, Value: []byte("1")}, + {Type: querypb.Type_INT64, Value: []byte("2")}, + }}, + "2 items", + }, { + &querypb.BindVariable{Type: querypb.Type_TUPLE, Values: []*querypb.Value{ + {Type: querypb.Type_UINT64, Value: []byte("1")}, + {Type: querypb.Type_UINT64, Value: []byte("2")}, + }}, + "2 items", + }, { + &querypb.BindVariable{Type: querypb.Type_TUPLE, Values: []*querypb.Value{ + {Type: querypb.Type_VARBINARY, Value: []byte("aa")}, + {Type: querypb.Type_VARBINARY, Value: []byte("bb")}, + }}, + "2 items", + }, { + &querypb.BindVariable{Type: querypb.Type_TUPLE, Values: []*querypb.Value{ + {Type: querypb.Type_VARBINARY, Value: []byte("aa")}, + {Type: querypb.Type_INT64, Value: []byte("1")}, + }}, + "2 items", + }, + } + + for i, test := range testsUnchangedTuples { + t.Run(strconv.Itoa(i), func(t *testing.T) { + logStats.BindVariables["vtg"] = test.bindVar + got := testFormat(logStats, url.Values(params)) + t.Logf("got: %s", got) + var parsed map[string]interface{} + err := json.Unmarshal([]byte(got), &parsed) + assert.NoError(t, err) + assert.NotNil(t, parsed) + bindVal := parsed["BindVars"].(map[string]interface{})["vtg"].(map[string]interface{})["value"] + + assert.Equal(t, test.expected, bindVal) + }) + } +}