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 }