querylog: json format version 2

go/flags/endtoend/vtcombo.txt

@@ -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

go/flags/endtoend/vtgate.txt

@@ -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)

go/flags/endtoend/vttablet.txt

@@ -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

go/streamlog/bind_variable.go

@@ -0,0 +1,102 @@
+/*
+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")
+
+// BindVariable is a wrapper for marshal/unmarshaling querypb.BindVariable as json.
+type BindVariable querypb.BindVariable
+
+// NewBindVariable returns a wrapped *querypb.BindVariable object.
+func NewBindVariable(bv *querypb.BindVariable) BindVariable {
+	return BindVariable(*bv)
+}
+
+// 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
+}
+
+// UnmarshalJSON unmarshals the custom BindVariable json-format.
+// See MarshalJSON for more information.
+func (bv *BindVariable) UnmarshalJSON(b []byte) error {
+	in := struct {
+		Type  string
+		Value []byte
+	}{}
+	if err := json.Unmarshal(b, &in); err != nil {
+		return err
+	}
+	// convert type string to querypb.Type and pass along Value.
+	typeVal, found := querypb.Type_value[in.Type]
+	if !found {
+		return ErrUnrecognizedBindVarType
+	}
+	bv.Type = querypb.Type(typeVal)
+	bv.Value = in.Value
+	return nil
+}
+
+// MarshalJSON renders the wrapped *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}
+func (bv BindVariable) MarshalJSON() ([]byte, error) {
+	// convert querypb.Type integer to string and pass along Value.
+	out := map[string]interface{}{
+		"Type":  bv.Type.String(),
+		"Value": bv.Value,
+	}
+	if GetRedactDebugUIQueries() {
+		out["Value"] = nil
+	}
+	return json.Marshal(out)
+}
+
+// BindVariablesToProto converts a string-map of BindVariable to a string-map of *querypb.BindVariable.
+func BindVariablesToProto(bvs map[string]BindVariable) map[string]*querypb.BindVariable {
+	out := make(map[string]*querypb.BindVariable, len(bvs))
+	for key, bindVar := range bvs {
+		bv := querypb.BindVariable(bindVar)
+		out[key] = &bv
+	}
+	return out
+}

go/streamlog/streamlog.go

@@ -51,6 +51,7 @@
 	queryLogFilterTag    string
 	queryLogRowThreshold uint64
 	queryLogFormat       = "text"
+	queryLogJSONV2       bool
 )
 
 func GetRedactDebugUIQueries() bool {
@@ -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)
@@ -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")
+
 	// 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")
 

go/vt/vtgate/executor.go

@@ -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)
 }

go/vt/vtgate/logstats/logstats.go

@@ -36,14 +36,13 @@ import (
 	querypb "vitess.io/vitess/go/vt/proto/query"
 )
 
-// LogStats records the stats for a single vtgate query
 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"`
 	StartTime      time.Time
 	EndTime        time.Time
 	ShardQueries   uint64
@@ -52,13 +51,21 @@ type LogStats struct {
 	PlanTime       time.Duration
 	ExecuteTime    time.Duration
 	CommitTime     time.Duration
-	Error          error
+	Error          error `json:",omitempty"`
 	TablesUsed     []string
 	SessionUUID    string
 	CachedPlan     bool
 	ActiveKeyspace string // ActiveKeyspace is the selected keyspace `use ks`
 }
 
+type LogStatsJSON struct {
+	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 {
@@ -67,7 +74,7 @@ func NewLogStats(ctx context.Context, methodName, sql, sessionUUID string, bindV
 		Method:        methodName,
 		SQL:           sql,
 		SessionUUID:   sessionUUID,
-		BindVariables: bindVars,
+		BindVariables: streamlog.NewBindVariables(bindVars),
 		StartTime:     time.Now(),
 	}
 }
@@ -137,10 +144,10 @@ func (stats *LogStats) Logf(w io.Writer, params url.Values) error {
 	}()
 
 	formattedBindVars := "\"[REDACTED]\""
-	if !streamlog.GetRedactDebugUIQueries() {
+	if !streamlog.GetRedactDebugUIQueries() && !streamlog.UseQueryLogJSONV2() {
 		_, fullBindParams := params["full"]
 		formattedBindVars = sqltypes.FormatBindVariables(
-			stats.BindVariables,
+			streamlog.BindVariablesToProto(stats.BindVariables),
 			fullBindParams,
 			streamlog.GetQueryLogFormat() == streamlog.QueryLogFormatJSON,
 		)
@@ -154,6 +161,16 @@ func (stats *LogStats) Logf(w io.Writer, params url.Values) error {
 	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"
 	}
 

go/vt/vtgate/logstats/logstats_test.go

@@ -66,15 +66,19 @@
 	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,
@@ -122,16 +126,16 @@
 	for i, test := range tests {
 		t.Run(strconv.Itoa(i), func(t *testing.T) {
 			logStats.BindVariables = test.bindVars
 			for _, variable := range logStats.BindVariables {
 				fmt.Println("->" + fmt.Sprintf("%v", variable))
 			}
 			streamlog.SetRedactDebugUIQueries(test.redact)
 			streamlog.SetQueryLogFormat(test.format)
 			if test.format == "text" {
 				got := testFormat(t, logStats, params)
 				assert.Equal(t, test.expected, got)
 				for _, variable := range logStats.BindVariables {
 					fmt.Println("->" + fmt.Sprintf("%v", variable))
 				}
 				return
 			}
@@ -148,6 +152,48 @@
 	}
 }
 
+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, querypb.Type_VARBINARY, cmpStats.BindVariables["bytesVal"].Type)
+		assert.Equal(t, []byte("\x16k@\xb4J\xbaK\xd6"), cmpStats.BindVariables["bytesVal"].Value)
+		assert.Equal(t, querypb.Type_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("") }()