Merge pull request vitessio#6282 from tinyspeck/add-ks-table-tablet-t…

…ype-to-logs

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

go/vt/vtgate/logstats.go

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

go/vt/vtgate/logstats_test.go

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

go/vt/vtgate/plan_execute.go

@@ -207,6 +207,9 @@ func (e *planExecute) executePlan(ctx context.Context, plan *engine.Plan, vcurso
  }
 
  // 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)