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.

Sign up for GitHub

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

Jump to bottom

Adds more keyspace, table and tablet_type to logs emitted to files #6282

Merged
merged 2 commits into from
Jun 9, 2020
Merged

Adds more keyspace, table and tablet_type to logs emitted to files #6282

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
0fa0a97
Adds more keyspace, table and tablet_type to logs emitted to files
rafael Jun 8, 2020
efb8692
Update tests to reflect new changes
rafael Jun 8, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions go/vt/vtgate/executor.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -195,6 +195,8 @@ func (e *Executor) legacyExecute(ctx context.Context, safeSession *SafeSession,
return 0, nil, err
}

logStats.Keyspace = destKeyspace
logStats.TabletType = destTabletType.String()
// Legacy gateway allows transactions only on MASTER
if UsingLegacyGateway() && safeSession.InTransaction() && destTabletType != topodatapb.TabletType_MASTER {
return 0, nil, vterrors.Errorf(vtrpcpb.Code_INVALID_ARGUMENT, "Executor.execute: transactions are supported only for master tablet types, current type: %v", destTabletType)
Expand Down
11 changes: 8 additions & 3 deletions go/vt/vtgate/logstats.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -39,7 +39,9 @@ import (
type LogStats struct {
Ctx context.Context
Method string
Target *querypb.Target
Keyspace string
TabletType string
Table string
StmtType string
SQL string
BindVariables map[string]*querypb.BindVariable
Expand Down Expand Up @@ -151,9 +153,9 @@ func (stats *LogStats) Logf(w io.Writer, params url.Values) error {
var fmtString string
switch *streamlog.QueryLogFormat {
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\n"
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%q\t\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}\n"
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, \"Keyspace\": %q, \"Table\": %q, \"TabletType\": %q}\n"
}

_, err := fmt.Fprintf(
Expand All @@ -176,6 +178,9 @@ func (stats *LogStats) Logf(w io.Writer, params url.Values) error {
stats.ShardQueries,
stats.RowsAffected,
stats.ErrorStr(),
stats.Keyspace,
stats.Table,
stats.TabletType,
)
return err
}
19 changes: 11 additions & 8 deletions go/vt/vtgate/logstats_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -44,20 +44,23 @@ func TestLogStatsFormat(t *testing.T) {
logStats := NewLogStats(context.Background(), "test", "sql1", map[string]*querypb.BindVariable{"intVal": sqltypes.Int64BindVariable(1)})
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.Keyspace = "ks"
logStats.Table = "table"
logStats.TabletType = "MASTER"
params := map[string][]string{"full": {}}

*streamlog.RedactDebugUIQueries = false
*streamlog.QueryLogFormat = "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\t0.000000\t0.000000\t0.000000\t\t\"sql1\"\tmap[intVal:type:INT64 value:\"1\" ]\t0\t0\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\"\tmap[intVal:type:INT64 value:\"1\" ]\t0\t0\t\"\"\t\"ks\"\t\"table\"\t\"MASTER\"\t\n"
if got != want {
t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
}

*streamlog.RedactDebugUIQueries = true
*streamlog.QueryLogFormat = "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\t0.000000\t0.000000\t0.000000\t\t\"sql1\"\t\"[REDACTED]\"\t0\t0\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\"\t\"[REDACTED]\"\t0\t0\t\"\"\t\"ks\"\t\"table\"\t\"MASTER\"\t\n"
if got != want {
t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
}
Expand All @@ -74,7 +77,7 @@ func TestLogStatsFormat(t *testing.T) {
if err != nil {
t.Errorf("logstats format: error marshaling json: %v -- got:\n%v", err, got)
}
want = "{\n \"BindVars\": {\n \"intVal\": {\n \"type\": \"INT64\",\n \"value\": 1\n }\n },\n \"CommitTime\": 0,\n \"Effective Caller\": \"\",\n \"End\": \"2017-01-01 01:02:04.000001\",\n \"Error\": \"\",\n \"ExecuteTime\": 0,\n \"ImmediateCaller\": \"\",\n \"Method\": \"test\",\n \"PlanTime\": 0,\n \"RemoteAddr\": \"\",\n \"RowsAffected\": 0,\n \"SQL\": \"sql1\",\n \"ShardQueries\": 0,\n \"Start\": \"2017-01-01 01:02:03.000000\",\n \"StmtType\": \"\",\n \"TotalTime\": 1.000001,\n \"Username\": \"\"\n}"
want = "{\n \"BindVars\": {\n \"intVal\": {\n \"type\": \"INT64\",\n \"value\": 1\n }\n },\n \"CommitTime\": 0,\n \"Effective Caller\": \"\",\n \"End\": \"2017-01-01 01:02:04.000001\",\n \"Error\": \"\",\n \"ExecuteTime\": 0,\n \"ImmediateCaller\": \"\",\n \"Keyspace\": \"ks\",\n \"Method\": \"test\",\n \"PlanTime\": 0,\n \"RemoteAddr\": \"\",\n \"RowsAffected\": 0,\n \"SQL\": \"sql1\",\n \"ShardQueries\": 0,\n \"Start\": \"2017-01-01 01:02:03.000000\",\n \"StmtType\": \"\",\n \"Table\": \"table\",\n \"TabletType\": \"MASTER\",\n \"TotalTime\": 1.000001,\n \"Username\": \"\"\n}"
if string(formatted) != want {
t.Errorf("logstats format: got:\n%q\nwant:\n%v\n", string(formatted), want)
}
Expand All @@ -90,7 +93,7 @@ func TestLogStatsFormat(t *testing.T) {
if err != nil {
t.Errorf("logstats format: error marshaling json: %v -- got:\n%v", err, got)
}
want = "{\n \"BindVars\": \"[REDACTED]\",\n \"CommitTime\": 0,\n \"Effective Caller\": \"\",\n \"End\": \"2017-01-01 01:02:04.000001\",\n \"Error\": \"\",\n \"ExecuteTime\": 0,\n \"ImmediateCaller\": \"\",\n \"Method\": \"test\",\n \"PlanTime\": 0,\n \"RemoteAddr\": \"\",\n \"RowsAffected\": 0,\n \"SQL\": \"sql1\",\n \"ShardQueries\": 0,\n \"Start\": \"2017-01-01 01:02:03.000000\",\n \"StmtType\": \"\",\n \"TotalTime\": 1.000001,\n \"Username\": \"\"\n}"
want = "{\n \"BindVars\": \"[REDACTED]\",\n \"CommitTime\": 0,\n \"Effective Caller\": \"\",\n \"End\": \"2017-01-01 01:02:04.000001\",\n \"Error\": \"\",\n \"ExecuteTime\": 0,\n \"ImmediateCaller\": \"\",\n \"Keyspace\": \"ks\",\n \"Method\": \"test\",\n \"PlanTime\": 0,\n \"RemoteAddr\": \"\",\n \"RowsAffected\": 0,\n \"SQL\": \"sql1\",\n \"ShardQueries\": 0,\n \"Start\": \"2017-01-01 01:02:03.000000\",\n \"StmtType\": \"\",\n \"Table\": \"table\",\n \"TabletType\": \"MASTER\",\n \"TotalTime\": 1.000001,\n \"Username\": \"\"\n}"
if string(formatted) != want {
t.Errorf("logstats format: got:\n%q\nwant:\n%v\n", string(formatted), want)
}
Expand All @@ -103,7 +106,7 @@ func TestLogStatsFormat(t *testing.T) {

*streamlog.QueryLogFormat = "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\t0.000000\t0.000000\t0.000000\t\t\"sql1\"\tmap[strVal:type:VARBINARY value:\"abc\" ]\t0\t0\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\"\tmap[strVal:type:VARBINARY value:\"abc\" ]\t0\t0\t\"\"\t\"ks\"\t\"table\"\t\"MASTER\"\t\n"
if got != want {
t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
}
Expand All @@ -118,7 +121,7 @@ func TestLogStatsFormat(t *testing.T) {
if err != nil {
t.Errorf("logstats format: error marshaling json: %v -- got:\n%v", err, got)
}
want = "{\n \"BindVars\": {\n \"strVal\": {\n \"type\": \"VARBINARY\",\n \"value\": \"abc\"\n }\n },\n \"CommitTime\": 0,\n \"Effective Caller\": \"\",\n \"End\": \"2017-01-01 01:02:04.000001\",\n \"Error\": \"\",\n \"ExecuteTime\": 0,\n \"ImmediateCaller\": \"\",\n \"Method\": \"test\",\n \"PlanTime\": 0,\n \"RemoteAddr\": \"\",\n \"RowsAffected\": 0,\n \"SQL\": \"sql1\",\n \"ShardQueries\": 0,\n \"Start\": \"2017-01-01 01:02:03.000000\",\n \"StmtType\": \"\",\n \"TotalTime\": 1.000001,\n \"Username\": \"\"\n}"
want = "{\n \"BindVars\": {\n \"strVal\": {\n \"type\": \"VARBINARY\",\n \"value\": \"abc\"\n }\n },\n \"CommitTime\": 0,\n \"Effective Caller\": \"\",\n \"End\": \"2017-01-01 01:02:04.000001\",\n \"Error\": \"\",\n \"ExecuteTime\": 0,\n \"ImmediateCaller\": \"\",\n \"Keyspace\": \"ks\",\n \"Method\": \"test\",\n \"PlanTime\": 0,\n \"RemoteAddr\": \"\",\n \"RowsAffected\": 0,\n \"SQL\": \"sql1\",\n \"ShardQueries\": 0,\n \"Start\": \"2017-01-01 01:02:03.000000\",\n \"StmtType\": \"\",\n \"Table\": \"table\",\n \"TabletType\": \"MASTER\",\n \"TotalTime\": 1.000001,\n \"Username\": \"\"\n}"
if string(formatted) != want {
t.Errorf("logstats format: got:\n%q\nwant:\n%v\n", string(formatted), want)
}
Expand All @@ -135,14 +138,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\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\" ]\t0\t0\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 */\"\tmap[intVal:type:INT64 value:\"1\" ]\t0\t0\t\"\"\t\"\"\t\"\"\t\"\"\t\n"
if got != want {
t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
}

*streamlog.QueryLogFilterTag = "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\t0.000000\t0.000000\t0.000000\t\t\"sql1 /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\" ]\t0\t0\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 */\"\tmap[intVal:type:INT64 value:\"1\" ]\t0\t0\t\"\"\t\"\"\t\"\"\t\"\"\t\n"
if got != want {
t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
}
Expand Down
3 changes: 3 additions & 0 deletions go/vt/vtgate/plan_execute.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -156,6 +156,9 @@ func (e *Executor) executePlan(ctx context.Context, plan *engine.Plan, vcursor *
qr, err := plan.Instructions.Execute(vcursor, bindVars, true)

// 5: Log and add statistics
logStats.Keyspace = plan.Instructions.GetKeyspaceName()
logStats.Table = plan.Instructions.GetTableName()
logStats.TabletType = vcursor.TabletType().String()
errCount := e.logExecutionEnd(logStats, execStart, plan, err, qr)
plan.AddStats(1, time.Since(logStats.StartTime), uint64(logStats.ShardQueries), logStats.RowsAffected, errCount)

Expand Down