Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

querylog: json format version 2 #15271

Open
wants to merge 6 commits into
base: main
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
1 change: 1 addition & 0 deletions go/flags/endtoend/vtcombo.txt
Expand Up @@ -270,6 +270,7 @@ Flags:
--querylog-buffer-size int Maximum number of buffered query logs before throttling log output (default 10)
--querylog-filter-tag string 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
--querylog-format string format for query logs ("text" or "json") (default "text")
--querylog-json-v2 use v2 format for querylog-format=json
--querylog-row-threshold uint Number of rows a query has to return or affect before being logged; not useful for streaming queries. 0 means all queries will be logged.
--queryserver-config-acl-exempt-acl string an acl that exempt from table acl checking (this acl is free to access any vitess tables).
--queryserver-config-annotate-queries prefix queries to MySQL backend with comment indicating vtgate principal (user) and target tablet type
Expand Down
1 change: 1 addition & 0 deletions go/flags/endtoend/vtgate.txt
Expand Up @@ -172,6 +172,7 @@ Flags:
--querylog-buffer-size int Maximum number of buffered query logs before throttling log output (default 10)
--querylog-filter-tag string 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
--querylog-format string format for query logs ("text" or "json") (default "text")
--querylog-json-v2 use v2 format for querylog-format=json
--querylog-row-threshold uint Number of rows a query has to return or affect before being logged; not useful for streaming queries. 0 means all queries will be logged.
--redact-debug-ui-queries redact full queries and bind variables from debug UI
--remote_operation_timeout duration time to wait for a remote operation (default 15s)
Expand Down
1 change: 1 addition & 0 deletions go/flags/endtoend/vttablet.txt
Expand Up @@ -263,6 +263,7 @@ Flags:
--query-log-stream-handler string URL handler for streaming queries log (default "/debug/querylog")
--querylog-filter-tag string 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
--querylog-format string format for query logs ("text" or "json") (default "text")
--querylog-json-v2 use v2 format for querylog-format=json
--querylog-row-threshold uint Number of rows a query has to return or affect before being logged; not useful for streaming queries. 0 means all queries will be logged.
--queryserver-config-acl-exempt-acl string an acl that exempt from table acl checking (this acl is free to access any vitess tables).
--queryserver-config-annotate-queries prefix queries to MySQL backend with comment indicating vtgate principal (user) and target tablet type
Expand Down
140 changes: 140 additions & 0 deletions go/streamlog/bind_variable.go
@@ -0,0 +1,140 @@
/*
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 streamlog

import (
"encoding/json"
"errors"

querypb "vitess.io/vitess/go/vt/proto/query"
)

var ErrUnrecognizedBindVarType = errors.New("unrecognized bind variable type")

// BindVariableValue is used to store querypb.BindVariable values.
type BindVariableValue struct {
Type string
Value []byte
}

// MarshalJSON renders the BindVariableValue as json and optionally redacts the value.
func (bv BindVariableValue) MarshalJSON() ([]byte, error) {
out := map[string]interface{}{
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
out := map[string]interface{}{
out := map[string]any{

For new code IMO.

"Type": bv.Type,
"Value": bv.Value,

Check warning on line 38 in go/streamlog/bind_variable.go

View check run for this annotation

Codecov / codecov/patch

go/streamlog/bind_variable.go#L35-L38

Added lines #L35 - L38 were not covered by tests
}
if GetRedactDebugUIQueries() {
out["Value"] = nil

Check warning on line 41 in go/streamlog/bind_variable.go

View check run for this annotation

Codecov / codecov/patch

go/streamlog/bind_variable.go#L40-L41

Added lines #L40 - L41 were not covered by tests
}
return json.Marshal(out)

Check warning on line 43 in go/streamlog/bind_variable.go

View check run for this annotation

Codecov / codecov/patch

go/streamlog/bind_variable.go#L43

Added line #L43 was not covered by tests
}

// BindVariable is a wrapper for marshal/unmarshaling querypb.BindVariable as json.
// It ensures that the "Type" field is a string representation of the variable
// type instead of an integer-based code that is less portable and human-readable.
//
// This allows a *querypb.BindVariable that would have marshaled
// to this:
//
// {"Type":10262,"Value":"FmtAtEq6S9Y="}
//
// to marshal to this:
//
// {"Type":"VARBINARY","Value":"FmtAtEq6S9Y="}
//
// or if query redaction is enabled, like this:
//
// {"Type":"VARBINARY","Value":null}
type BindVariable struct {
Type string
Value []byte
Values []*BindVariableValue
}

// NewBindVariable returns a wrapped *querypb.BindVariable object.
func NewBindVariable(bv *querypb.BindVariable) BindVariable {
newBv := BindVariable{
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We know the capacity of newBv.Values up front and should preallocate it here before the loop.

Type: bv.Type.String(),
Value: bv.Value,
}
for _, val := range bv.Values {
newBv.Values = append(newBv.Values, &BindVariableValue{
Type: val.Type.String(),
Value: val.Value,
})
}
return newBv
}

// NewBindVariables returns a string-map of wrapped *querypb.BindVariable objects.
func NewBindVariables(bvs map[string]*querypb.BindVariable) map[string]BindVariable {
out := make(map[string]BindVariable, len(bvs))
for key, bindVar := range bvs {
out[key] = NewBindVariable(bindVar)
}
return out
}

// MarshalJSON renders the BindVariable as json and optionally redacts the value.
func (bv BindVariable) MarshalJSON() ([]byte, error) {
out := map[string]interface{}{
"Type": bv.Type,
"Value": bv.Value,
}
if GetRedactDebugUIQueries() {
out["Value"] = nil
}
return json.Marshal(out)
}

// bindVariablesValuesToProto converts a slice of *BindVariableValue to *querypb.Value.
func bindVariablesValuesToProto(vals []*BindVariableValue) ([]*querypb.Value, error) {
values := make([]*querypb.Value, len(vals))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
values := make([]*querypb.Value, len(vals))
values := make([]*querypb.Value, 0, len(vals))

This needs to be allocated with length 0 or else you'll end up appending to a slice populated with zero values up front.

for _, val := range vals {
varType, found := querypb.Type_value[val.Type]
if !found {
return nil, ErrUnrecognizedBindVarType

Check warning on line 110 in go/streamlog/bind_variable.go

View check run for this annotation

Codecov / codecov/patch

go/streamlog/bind_variable.go#L108-L110

Added lines #L108 - L110 were not covered by tests
}
values = append(values, &querypb.Value{
Type: querypb.Type(varType),
Value: val.Value,
})

Check warning on line 115 in go/streamlog/bind_variable.go

View check run for this annotation

Codecov / codecov/patch

go/streamlog/bind_variable.go#L112-L115

Added lines #L112 - L115 were not covered by tests
}
return values, nil
}

// BindVariablesToProto converts a string-map of BindVariable to a string-map of *querypb.BindVariable.
func BindVariablesToProto(bvs map[string]BindVariable) (map[string]*querypb.BindVariable, error) {
out := make(map[string]*querypb.BindVariable, len(bvs))
for key, bindVar := range bvs {
// convert type string to querypb.Type.
varType, found := querypb.Type_value[bindVar.Type]
if !found {
return nil, ErrUnrecognizedBindVarType

Check warning on line 127 in go/streamlog/bind_variable.go

View check run for this annotation

Codecov / codecov/patch

go/streamlog/bind_variable.go#L127

Added line #L127 was not covered by tests
}
values, err := bindVariablesValuesToProto(bindVar.Values)
if err != nil {
return nil, err

Check warning on line 131 in go/streamlog/bind_variable.go

View check run for this annotation

Codecov / codecov/patch

go/streamlog/bind_variable.go#L131

Added line #L131 was not covered by tests
}
out[key] = &querypb.BindVariable{
Type: querypb.Type(varType),
Value: bindVar.Value,
Values: values,
}
}
return out, nil
}
12 changes: 12 additions & 0 deletions go/streamlog/streamlog.go
Expand Up @@ -51,6 +51,7 @@
queryLogFilterTag string
queryLogRowThreshold uint64
queryLogFormat = "text"
queryLogJSONV2 bool
)

func GetRedactDebugUIQueries() bool {
Expand All @@ -77,6 +78,14 @@
queryLogFormat = newQueryLogFormat
}

func UseQueryLogJSONV2() bool {
return queryLogJSONV2
}

func SetQueryLogJSONV2(enabled bool) {
queryLogJSONV2 = enabled
}

func init() {
servenv.OnParseFor("vtcombo", registerStreamLogFlags)
servenv.OnParseFor("vttablet", registerStreamLogFlags)
Expand All @@ -90,6 +99,9 @@
// QueryLogFormat controls the format of the query log (either text or json)
fs.StringVar(&queryLogFormat, "querylog-format", queryLogFormat, "format for query logs (\"text\" or \"json\")")

// QueryLogJSONFormat controls whether the new querylog json format is used
fs.BoolVar(&queryLogJSONV2, "querylog-json-v2", false, "use v2 format for querylog-format=json")

Check warning on line 103 in go/streamlog/streamlog.go

View check run for this annotation

Codecov / codecov/patch

go/streamlog/streamlog.go#L103

Added line #L103 was not covered by tests
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If we already have --querylog-format=json, why not --querylog-format=json-v2 rather than a new flag?


// QueryLogFilterTag contains an optional string that must be present in the query for it to be logged
fs.StringVar(&queryLogFilterTag, "querylog-filter-tag", queryLogFilterTag, "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
2 changes: 1 addition & 1 deletion go/vt/vtgate/executor.go
Expand Up @@ -1093,7 +1093,7 @@ func (e *Executor) getPlan(
}

logStats.SQL = comments.Leading + query + comments.Trailing
logStats.BindVariables = sqltypes.CopyBindVariables(bindVars)
logStats.BindVariables = streamlog.NewBindVariables(sqltypes.CopyBindVariables(bindVars))

return e.cacheAndBuildStatement(ctx, vcursor, query, stmt, reservedVars, bindVarNeeds, logStats)
}
Expand Down
35 changes: 28 additions & 7 deletions go/vt/vtgate/logstats/logstats.go
Expand Up @@ -36,14 +36,13 @@
querypb "vitess.io/vitess/go/vt/proto/query"
)

// LogStats records the stats for a single vtgate query
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Keep this.

type LogStats struct {
Ctx context.Context
Ctx context.Context `json:"-"`
Method string
TabletType string
StmtType string
SQL string
BindVariables map[string]*querypb.BindVariable
BindVariables map[string]streamlog.BindVariable `json:",omitempty"`
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

See below.

StartTime time.Time
EndTime time.Time
ShardQueries uint64
Expand All @@ -52,13 +51,21 @@
PlanTime time.Duration
ExecuteTime time.Duration
CommitTime time.Duration
Error error
Error error `json:",omitempty"`
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This seems incorrect. Did you intend for -?

TablesUsed []string
SessionUUID string
CachedPlan bool
ActiveKeyspace string // ActiveKeyspace is the selected keyspace `use ks`
}

type LogStatsJSON struct {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Name with JSONv2 to separate from the base implementation?

RemoteAddr string
Username string
ImmediateCaller string
EffectiveCaller string
LogStats
}

// NewLogStats constructs a new LogStats with supplied Method and ctx
// field values, and the StartTime field set to the present time.
func NewLogStats(ctx context.Context, methodName, sql, sessionUUID string, bindVars map[string]*querypb.BindVariable) *LogStats {
Expand All @@ -67,7 +74,7 @@
Method: methodName,
SQL: sql,
SessionUUID: sessionUUID,
BindVariables: bindVars,
BindVariables: streamlog.NewBindVariables(bindVars),
StartTime: time.Now(),
}
}
Expand Down Expand Up @@ -137,10 +144,14 @@
}()

formattedBindVars := "\"[REDACTED]\""
if !streamlog.GetRedactDebugUIQueries() {
if !streamlog.GetRedactDebugUIQueries() && !streamlog.UseQueryLogJSONV2() {
_, fullBindParams := params["full"]
bindVarsProto, err := streamlog.BindVariablesToProto(stats.BindVariables)
if err != nil {
return err

Check warning on line 151 in go/vt/vtgate/logstats/logstats.go

View check run for this annotation

Codecov / codecov/patch

go/vt/vtgate/logstats/logstats.go#L151

Added line #L151 was not covered by tests
}
formattedBindVars = sqltypes.FormatBindVariables(
stats.BindVariables,
bindVarsProto,
fullBindParams,
streamlog.GetQueryLogFormat() == streamlog.QueryLogFormatJSON,
)
Expand All @@ -154,6 +165,16 @@
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:
if streamlog.UseQueryLogJSONV2() {
// flag --querylog-json-v2
return json.NewEncoder(w).Encode(LogStatsJSON{
EffectiveCaller: stats.EffectiveCaller(),
ImmediateCaller: stats.ImmediateCaller(),
LogStats: *stats,
RemoteAddr: remoteAddr,
Username: username,
})
}
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"
}

Expand Down
52 changes: 49 additions & 3 deletions go/vt/vtgate/logstats/logstats_test.go
Expand Up @@ -66,15 +66,19 @@ func TestLogStatsFormat(t *testing.T) {
logStats.TabletType = "PRIMARY"
logStats.ActiveKeyspace = "db"
params := map[string][]string{"full": {}}
intBindVar := map[string]*querypb.BindVariable{"intVal": sqltypes.Int64BindVariable(1)}
stringBindVar := map[string]*querypb.BindVariable{"strVal": sqltypes.StringBindVariable("abc")}
intBindVar := map[string]streamlog.BindVariable{
"intVal": streamlog.NewBindVariable(sqltypes.Int64BindVariable(1)),
}
stringBindVar := map[string]streamlog.BindVariable{
"strVal": streamlog.NewBindVariable(sqltypes.StringBindVariable("abc")),
}

tests := []struct {
name string
redact bool
format string
expected string
bindVars map[string]*querypb.BindVariable
bindVars map[string]streamlog.BindVariable
}{
{ // 0
redact: false,
Expand Down Expand Up @@ -148,6 +152,48 @@ func TestLogStatsFormat(t *testing.T) {
}
}

func TestLogStatsFormatJSONV2(t *testing.T) {
defer func() {
streamlog.SetRedactDebugUIQueries(false)
streamlog.SetQueryLogFormat("text")
streamlog.SetQueryLogJSONV2(false)
}()
logStats := NewLogStats(context.Background(), "test", "select * from testtable where name = :strVal and message = :bytesVal", "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.StmtType = "select"
logStats.TablesUsed = []string{"ks1.tbl1", "ks2.tbl2"}
logStats.TabletType = "PRIMARY"
logStats.ActiveKeyspace = "db"
logStats.BindVariables = map[string]streamlog.BindVariable{
"strVal": streamlog.NewBindVariable(sqltypes.StringBindVariable("abc")),
"bytesVal": streamlog.NewBindVariable(sqltypes.BytesBindVariable([]byte("\x16k@\xb4J\xbaK\xd6"))),
}
streamlog.SetQueryLogFormat("json")
streamlog.SetQueryLogJSONV2(true)
var cmpStats LogStatsJSON
{
// unredacted bind variables
streamlog.SetRedactDebugUIQueries(false)
var buf bytes.Buffer
assert.Nil(t, logStats.Logf(&buf, nil))
assert.Equal(t, `{"RemoteAddr":"","Username":"","ImmediateCaller":"","EffectiveCaller":"","Method":"test","TabletType":"PRIMARY","StmtType":"select","SQL":"select * from testtable where name = :strVal and message = :bytesVal","BindVariables":{"bytesVal":{"Type":"VARBINARY","Value":"FmtAtEq6S9Y="},"strVal":{"Type":"VARCHAR","Value":"YWJj"}},"StartTime":"2017-01-01T01:02:03Z","EndTime":"2017-01-01T01:02:04.000001234Z","ShardQueries":0,"RowsAffected":0,"RowsReturned":0,"PlanTime":0,"ExecuteTime":0,"CommitTime":0,"TablesUsed":["ks1.tbl1","ks2.tbl2"],"SessionUUID":"suuid","CachedPlan":false,"ActiveKeyspace":"db"}`, strings.TrimSpace(buf.String()))
assert.Nil(t, json.Unmarshal(buf.Bytes(), &cmpStats))
assert.Equal(t, "VARBINARY", cmpStats.BindVariables["bytesVal"].Type)
assert.Equal(t, []byte("\x16k@\xb4J\xbaK\xd6"), cmpStats.BindVariables["bytesVal"].Value)
assert.Equal(t, "VARCHAR", cmpStats.BindVariables["strVal"].Type)
assert.Equal(t, []byte("abc"), cmpStats.BindVariables["strVal"].Value)
}
{
// redacted bind variables
streamlog.SetRedactDebugUIQueries(true)
var buf bytes.Buffer
assert.Nil(t, logStats.Logf(&buf, nil))
assert.Equal(t, `{"RemoteAddr":"","Username":"","ImmediateCaller":"","EffectiveCaller":"","Method":"test","TabletType":"PRIMARY","StmtType":"select","SQL":"select * from testtable where name = :strVal and message = :bytesVal","BindVariables":{"bytesVal":{"Type":"VARBINARY","Value":null},"strVal":{"Type":"VARCHAR","Value":null}},"StartTime":"2017-01-01T01:02:03Z","EndTime":"2017-01-01T01:02:04.000001234Z","ShardQueries":0,"RowsAffected":0,"RowsReturned":0,"PlanTime":0,"ExecuteTime":0,"CommitTime":0,"TablesUsed":["ks1.tbl1","ks2.tbl2"],"SessionUUID":"suuid","CachedPlan":false,"ActiveKeyspace":"db"}`, strings.TrimSpace(buf.String()))
assert.Nil(t, json.Unmarshal(buf.Bytes(), &cmpStats))
}
}

func TestLogStatsFilter(t *testing.T) {
defer func() { streamlog.SetQueryLogFilterTag("") }()

Expand Down