vitess.io/vitess@v0.16.2/go/vt/vttablet/tabletserver/tabletenv/logstats_test.go (about)

     1  /*
     2  Copyright 2019 The Vitess Authors.
     3  
     4  Licensed under the Apache License, Version 2.0 (the "License");
     5  you may not use this file except in compliance with the License.
     6  You may obtain a copy of the License at
     7  
     8      http://www.apache.org/licenses/LICENSE-2.0
     9  
    10  Unless required by applicable law or agreed to in writing, software
    11  distributed under the License is distributed on an "AS IS" BASIS,
    12  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
    13  See the License for the specific language governing permissions and
    14  limitations under the License.
    15  */
    16  
    17  package tabletenv
    18  
    19  import (
    20  	"bytes"
    21  	"context"
    22  	"encoding/json"
    23  	"errors"
    24  	"net/url"
    25  	"strings"
    26  	"testing"
    27  	"time"
    28  
    29  	"vitess.io/vitess/go/sqltypes"
    30  	"vitess.io/vitess/go/streamlog"
    31  	"vitess.io/vitess/go/vt/callinfo"
    32  	"vitess.io/vitess/go/vt/callinfo/fakecallinfo"
    33  	querypb "vitess.io/vitess/go/vt/proto/query"
    34  )
    35  
    36  func TestLogStats(t *testing.T) {
    37  	logStats := NewLogStats(context.Background(), "test")
    38  	logStats.AddRewrittenSQL("sql1", time.Now())
    39  
    40  	if !strings.Contains(logStats.RewrittenSQL(), "sql1") {
    41  		t.Fatalf("RewrittenSQL should contains sql: sql1")
    42  	}
    43  
    44  	if logStats.SizeOfResponse() != 0 {
    45  		t.Fatalf("there is no rows in log stats, estimated size should be 0 bytes")
    46  	}
    47  
    48  	logStats.Rows = [][]sqltypes.Value{{sqltypes.NewVarBinary("a")}}
    49  	if logStats.SizeOfResponse() <= 0 {
    50  		t.Fatalf("log stats has some rows, should have positive response size")
    51  	}
    52  }
    53  
    54  func testFormat(stats *LogStats, params url.Values) string {
    55  	var b bytes.Buffer
    56  	stats.Logf(&b, params)
    57  	return b.String()
    58  }
    59  
    60  func TestLogStatsFormat(t *testing.T) {
    61  	logStats := NewLogStats(context.Background(), "test")
    62  	logStats.StartTime = time.Date(2017, time.January, 1, 1, 2, 3, 0, time.UTC)
    63  	logStats.EndTime = time.Date(2017, time.January, 1, 1, 2, 4, 1234, time.UTC)
    64  	logStats.OriginalSQL = "sql"
    65  	logStats.BindVariables = map[string]*querypb.BindVariable{"intVal": sqltypes.Int64BindVariable(1)}
    66  	logStats.AddRewrittenSQL("sql with pii", time.Now())
    67  	logStats.MysqlResponseTime = 0
    68  	logStats.TransactionID = 12345
    69  	logStats.Rows = [][]sqltypes.Value{{sqltypes.NewVarBinary("a")}}
    70  	params := map[string][]string{"full": {}}
    71  
    72  	streamlog.SetRedactDebugUIQueries(false)
    73  	streamlog.SetQueryLogFormat("text")
    74  	got := testFormat(logStats, url.Values(params))
    75  	want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql\"\tmap[intVal:type:INT64 value:\"1\"]\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t12345\t1\t\"\"\t\n"
    76  	if got != want {
    77  		t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
    78  	}
    79  
    80  	streamlog.SetRedactDebugUIQueries(true)
    81  	streamlog.SetQueryLogFormat("text")
    82  	got = testFormat(logStats, url.Values(params))
    83  	want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql\"\t\"[REDACTED]\"\t1\t\"[REDACTED]\"\tmysql\t0.000000\t0.000000\t0\t12345\t1\t\"\"\t\n"
    84  	if got != want {
    85  		t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
    86  	}
    87  
    88  	streamlog.SetRedactDebugUIQueries(false)
    89  	streamlog.SetQueryLogFormat("json")
    90  	got = testFormat(logStats, url.Values(params))
    91  	var parsed map[string]any
    92  	err := json.Unmarshal([]byte(got), &parsed)
    93  	if err != nil {
    94  		t.Errorf("logstats format: error unmarshaling json: %v -- got:\n%v", err, got)
    95  	}
    96  	formatted, err := json.MarshalIndent(parsed, "", "    ")
    97  	if err != nil {
    98  		t.Errorf("logstats format: error marshaling json: %v -- got:\n%v", err, got)
    99  	}
   100  	want = "{\n    \"BindVars\": {\n        \"intVal\": {\n            \"type\": \"INT64\",\n            \"value\": 1\n        }\n    },\n    \"CallInfo\": \"\",\n    \"ConnWaitTime\": 0,\n    \"Effective Caller\": \"\",\n    \"End\": \"2017-01-01 01:02:04.000001\",\n    \"Error\": \"\",\n    \"ImmediateCaller\": \"\",\n    \"Method\": \"test\",\n    \"MysqlTime\": 0,\n    \"OriginalSQL\": \"sql\",\n    \"PlanType\": \"\",\n    \"Queries\": 1,\n    \"QuerySources\": \"mysql\",\n    \"ResponseSize\": 1,\n    \"RewrittenSQL\": \"sql with pii\",\n    \"RowsAffected\": 0,\n    \"Start\": \"2017-01-01 01:02:03.000000\",\n    \"TotalTime\": 1.000001,\n    \"TransactionID\": 12345,\n    \"Username\": \"\"\n}"
   101  	if string(formatted) != want {
   102  		t.Errorf("logstats format: got:\n%q\nwant:\n%v\n", string(formatted), want)
   103  	}
   104  
   105  	streamlog.SetRedactDebugUIQueries(true)
   106  	streamlog.SetQueryLogFormat("json")
   107  	got = testFormat(logStats, url.Values(params))
   108  	err = json.Unmarshal([]byte(got), &parsed)
   109  	if err != nil {
   110  		t.Errorf("logstats format: error unmarshaling json: %v -- got:\n%v", err, got)
   111  	}
   112  	formatted, err = json.MarshalIndent(parsed, "", "    ")
   113  	if err != nil {
   114  		t.Errorf("logstats format: error marshaling json: %v -- got:\n%v", err, got)
   115  	}
   116  	want = "{\n    \"BindVars\": \"[REDACTED]\",\n    \"CallInfo\": \"\",\n    \"ConnWaitTime\": 0,\n    \"Effective Caller\": \"\",\n    \"End\": \"2017-01-01 01:02:04.000001\",\n    \"Error\": \"\",\n    \"ImmediateCaller\": \"\",\n    \"Method\": \"test\",\n    \"MysqlTime\": 0,\n    \"OriginalSQL\": \"sql\",\n    \"PlanType\": \"\",\n    \"Queries\": 1,\n    \"QuerySources\": \"mysql\",\n    \"ResponseSize\": 1,\n    \"RewrittenSQL\": \"[REDACTED]\",\n    \"RowsAffected\": 0,\n    \"Start\": \"2017-01-01 01:02:03.000000\",\n    \"TotalTime\": 1.000001,\n    \"TransactionID\": 12345,\n    \"Username\": \"\"\n}"
   117  	if string(formatted) != want {
   118  		t.Errorf("logstats format: got:\n%q\nwant:\n%v\n", string(formatted), want)
   119  	}
   120  
   121  	streamlog.SetRedactDebugUIQueries(false)
   122  
   123  	// Make sure formatting works for string bind vars. We can't do this as part of a single
   124  	// map because the output ordering is undefined.
   125  	logStats.BindVariables = map[string]*querypb.BindVariable{"strVal": sqltypes.StringBindVariable("abc")}
   126  
   127  	streamlog.SetQueryLogFormat("text")
   128  	got = testFormat(logStats, url.Values(params))
   129  	want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql\"\tmap[strVal:type:VARCHAR value:\"abc\"]\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t12345\t1\t\"\"\t\n"
   130  	if got != want {
   131  		t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
   132  	}
   133  
   134  	streamlog.SetQueryLogFormat("json")
   135  	got = testFormat(logStats, url.Values(params))
   136  	err = json.Unmarshal([]byte(got), &parsed)
   137  	if err != nil {
   138  		t.Errorf("logstats format: error unmarshaling json: %v -- got:\n%v", err, got)
   139  	}
   140  	formatted, err = json.MarshalIndent(parsed, "", "    ")
   141  	if err != nil {
   142  		t.Errorf("logstats format: error marshaling json: %v -- got:\n%v", err, got)
   143  	}
   144  	want = "{\n    \"BindVars\": {\n        \"strVal\": {\n            \"type\": \"VARCHAR\",\n            \"value\": \"abc\"\n        }\n    },\n    \"CallInfo\": \"\",\n    \"ConnWaitTime\": 0,\n    \"Effective Caller\": \"\",\n    \"End\": \"2017-01-01 01:02:04.000001\",\n    \"Error\": \"\",\n    \"ImmediateCaller\": \"\",\n    \"Method\": \"test\",\n    \"MysqlTime\": 0,\n    \"OriginalSQL\": \"sql\",\n    \"PlanType\": \"\",\n    \"Queries\": 1,\n    \"QuerySources\": \"mysql\",\n    \"ResponseSize\": 1,\n    \"RewrittenSQL\": \"sql with pii\",\n    \"RowsAffected\": 0,\n    \"Start\": \"2017-01-01 01:02:03.000000\",\n    \"TotalTime\": 1.000001,\n    \"TransactionID\": 12345,\n    \"Username\": \"\"\n}"
   145  	if string(formatted) != want {
   146  		t.Errorf("logstats format: got:\n%q\nwant:\n%v\n", string(formatted), want)
   147  	}
   148  
   149  	streamlog.SetQueryLogFormat("text")
   150  }
   151  
   152  func TestLogStatsFilter(t *testing.T) {
   153  	defer func() { streamlog.SetQueryLogFilterTag("") }()
   154  
   155  	logStats := NewLogStats(context.Background(), "test")
   156  	logStats.StartTime = time.Date(2017, time.January, 1, 1, 2, 3, 0, time.UTC)
   157  	logStats.EndTime = time.Date(2017, time.January, 1, 1, 2, 4, 1234, time.UTC)
   158  	logStats.OriginalSQL = "sql /* LOG_THIS_QUERY */"
   159  	logStats.BindVariables = map[string]*querypb.BindVariable{"intVal": sqltypes.Int64BindVariable(1)}
   160  	logStats.AddRewrittenSQL("sql with pii", time.Now())
   161  	logStats.MysqlResponseTime = 0
   162  	logStats.Rows = [][]sqltypes.Value{{sqltypes.NewVarBinary("a")}}
   163  	params := map[string][]string{"full": {}}
   164  
   165  	got := testFormat(logStats, url.Values(params))
   166  	want := "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\"]\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t0\t1\t\"\"\t\n"
   167  	if got != want {
   168  		t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
   169  	}
   170  
   171  	streamlog.SetQueryLogFilterTag("LOG_THIS_QUERY")
   172  	got = testFormat(logStats, url.Values(params))
   173  	want = "test\t\t\t''\t''\t2017-01-01 01:02:03.000000\t2017-01-01 01:02:04.000001\t1.000001\t\t\"sql /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\"]\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t0\t1\t\"\"\t\n"
   174  	if got != want {
   175  		t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
   176  	}
   177  
   178  	streamlog.SetQueryLogFilterTag("NOT_THIS_QUERY")
   179  	got = testFormat(logStats, url.Values(params))
   180  	want = ""
   181  	if got != want {
   182  		t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
   183  	}
   184  
   185  }
   186  
   187  func TestLogStatsFormatQuerySources(t *testing.T) {
   188  	logStats := NewLogStats(context.Background(), "test")
   189  	if logStats.FmtQuerySources() != "none" {
   190  		t.Fatalf("should return none since log stats does not have any query source, but got: %s", logStats.FmtQuerySources())
   191  	}
   192  
   193  	logStats.QuerySources |= QuerySourceMySQL
   194  	if !strings.Contains(logStats.FmtQuerySources(), "mysql") {
   195  		t.Fatalf("'mysql' should be in formatted query sources")
   196  	}
   197  
   198  	logStats.QuerySources |= QuerySourceConsolidator
   199  	if !strings.Contains(logStats.FmtQuerySources(), "consolidator") {
   200  		t.Fatalf("'consolidator' should be in formatted query sources")
   201  	}
   202  }
   203  
   204  func TestLogStatsContextHTML(t *testing.T) {
   205  	html := "HtmlContext"
   206  	callInfo := &fakecallinfo.FakeCallInfo{
   207  		Html: html,
   208  	}
   209  	ctx := callinfo.NewContext(context.Background(), callInfo)
   210  	logStats := NewLogStats(ctx, "test")
   211  	if string(logStats.ContextHTML()) != html {
   212  		t.Fatalf("expect to get html: %s, but got: %s", html, string(logStats.ContextHTML()))
   213  	}
   214  }
   215  
   216  func TestLogStatsErrorStr(t *testing.T) {
   217  	logStats := NewLogStats(context.Background(), "test")
   218  	if logStats.ErrorStr() != "" {
   219  		t.Fatalf("should not get error in stats, but got: %s", logStats.ErrorStr())
   220  	}
   221  	errStr := "unknown error"
   222  	logStats.Error = errors.New(errStr)
   223  	if !strings.Contains(logStats.ErrorStr(), errStr) {
   224  		t.Fatalf("expect string '%s' in error message, but got: %s", errStr, logStats.ErrorStr())
   225  	}
   226  }
   227  
   228  func TestLogStatsCallInfo(t *testing.T) {
   229  	logStats := NewLogStats(context.Background(), "test")
   230  	caller, user := logStats.CallInfo()
   231  	if caller != "" {
   232  		t.Fatalf("caller should be empty")
   233  	}
   234  	if user != "" {
   235  		t.Fatalf("username should be empty")
   236  	}
   237  
   238  	remoteAddr := "1.2.3.4"
   239  	username := "vt"
   240  	callInfo := &fakecallinfo.FakeCallInfo{
   241  		Remote: remoteAddr,
   242  		Method: "FakeExecute",
   243  		User:   username,
   244  	}
   245  	ctx := callinfo.NewContext(context.Background(), callInfo)
   246  	logStats = NewLogStats(ctx, "test")
   247  	caller, user = logStats.CallInfo()
   248  	wantCaller := remoteAddr + ":FakeExecute(fakeRPC)"
   249  	if caller != wantCaller {
   250  		t.Fatalf("expected to get caller: %s, but got: %s", wantCaller, caller)
   251  	}
   252  	if user != username {
   253  		t.Fatalf("expected to get username: %s, but got: %s", username, user)
   254  	}
   255  }