Skip to content

Commit

Permalink
base64 encode bindvar strings in json, inspired by vitessio#15271
Browse files Browse the repository at this point in the history 
Signed-off-by: Vilius Okockis <[email protected]>
  • Loading branch information
@DeathBorn
DeathBorn committed Apr 16, 2024
1 parent a1f1266 commit 65b4bd9
Show file tree
Hide file tree
Showing 6 changed files with 420 additions and 18 deletions.
64 changes: 46 additions & 18 deletions go/logstats/logger.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,7 @@ limitations under the License.
package logstats

import (
"encoding/base64"
"io"
"sort"
"strconv"
Expand All @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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)
}
Expand Down
3 changes: 3 additions & 0 deletions go/streamlog/streamlog.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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")

Expand Down
3 changes: 3 additions & 0 deletions go/vt/vtgate/logstats.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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()

Expand Down Expand Up @@ -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)
}
Expand Down
181 changes: 181 additions & 0 deletions go/vt/vtgate/logstats_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
})
}
}
3 changes: 3 additions & 0 deletions go/vt/vttablet/tabletserver/tabletenv/logstats.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand Down Expand Up @@ -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)
}
Expand Down
Loading

0 comments on commit 65b4bd9

Please sign in to comment.