vitess.io/vitess@v0.16.2/go/vt/vtgate/logstats/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 logstats 18 19 import ( 20 "bytes" 21 "context" 22 "encoding/json" 23 "errors" 24 "fmt" 25 "net/url" 26 "os" 27 "strconv" 28 "strings" 29 "testing" 30 "time" 31 32 "github.com/stretchr/testify/assert" 33 "github.com/stretchr/testify/require" 34 35 "vitess.io/vitess/go/hack" 36 37 "vitess.io/vitess/go/sqltypes" 38 "vitess.io/vitess/go/streamlog" 39 "vitess.io/vitess/go/vt/callinfo" 40 "vitess.io/vitess/go/vt/callinfo/fakecallinfo" 41 querypb "vitess.io/vitess/go/vt/proto/query" 42 ) 43 44 func TestMain(m *testing.M) { 45 hack.DisableProtoBufRandomness() 46 os.Exit(m.Run()) 47 } 48 49 func testFormat(t *testing.T, stats *LogStats, params url.Values) string { 50 var b bytes.Buffer 51 err := stats.Logf(&b, params) 52 require.NoError(t, err) 53 return b.String() 54 } 55 56 func TestLogStatsFormat(t *testing.T) { 57 defer func() { 58 streamlog.SetRedactDebugUIQueries(false) 59 streamlog.SetQueryLogFormat("text") 60 }() 61 logStats := NewLogStats(context.Background(), "test", "sql1", "suuid", nil) 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.TablesUsed = []string{"ks1.tbl1", "ks2.tbl2"} 65 logStats.TabletType = "PRIMARY" 66 logStats.ActiveKeyspace = "db" 67 params := map[string][]string{"full": {}} 68 intBindVar := map[string]*querypb.BindVariable{"intVal": sqltypes.Int64BindVariable(1)} 69 stringBindVar := map[string]*querypb.BindVariable{"strVal": sqltypes.StringBindVariable("abc")} 70 71 tests := []struct { 72 name string 73 redact bool 74 format string 75 expected string 76 bindVars map[string]*querypb.BindVariable 77 }{ 78 { // 0 79 redact: false, 80 format: "text", 81 expected: "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\"PRIMARY\"\t\"suuid\"\tfalse\t[\"ks1.tbl1\",\"ks2.tbl2\"]\t\"db\"\n", 82 bindVars: intBindVar, 83 }, { // 1 84 redact: true, 85 format: "text", 86 expected: "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\"PRIMARY\"\t\"suuid\"\tfalse\t[\"ks1.tbl1\",\"ks2.tbl2\"]\t\"db\"\n", 87 bindVars: intBindVar, 88 }, { // 2 89 redact: false, 90 format: "json", 91 expected: "{\"ActiveKeyspace\":\"db\",\"BindVars\":{\"intVal\":{\"type\":\"INT64\",\"value\":1}},\"Cached Plan\":false,\"CommitTime\":0,\"Effective Caller\":\"\",\"End\":\"2017-01-01 01:02:04.000001\",\"Error\":\"\",\"ExecuteTime\":0,\"ImmediateCaller\":\"\",\"Method\":\"test\",\"PlanTime\":0,\"RemoteAddr\":\"\",\"RowsAffected\":0,\"SQL\":\"sql1\",\"SessionUUID\":\"suuid\",\"ShardQueries\":0,\"Start\":\"2017-01-01 01:02:03.000000\",\"StmtType\":\"\",\"TablesUsed\":[\"ks1.tbl1\",\"ks2.tbl2\"],\"TabletType\":\"PRIMARY\",\"TotalTime\":1.000001,\"Username\":\"\"}", 92 bindVars: intBindVar, 93 }, { // 3 94 redact: true, 95 format: "json", 96 expected: "{\"ActiveKeyspace\":\"db\",\"BindVars\":\"[REDACTED]\",\"Cached Plan\":false,\"CommitTime\":0,\"Effective Caller\":\"\",\"End\":\"2017-01-01 01:02:04.000001\",\"Error\":\"\",\"ExecuteTime\":0,\"ImmediateCaller\":\"\",\"Method\":\"test\",\"PlanTime\":0,\"RemoteAddr\":\"\",\"RowsAffected\":0,\"SQL\":\"sql1\",\"SessionUUID\":\"suuid\",\"ShardQueries\":0,\"Start\":\"2017-01-01 01:02:03.000000\",\"StmtType\":\"\",\"TablesUsed\":[\"ks1.tbl1\",\"ks2.tbl2\"],\"TabletType\":\"PRIMARY\",\"TotalTime\":1.000001,\"Username\":\"\"}", 97 bindVars: intBindVar, 98 }, { // 4 99 redact: false, 100 format: "text", 101 expected: "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:VARCHAR value:\"abc\"]\t0\t0\t\"\"\t\"PRIMARY\"\t\"suuid\"\tfalse\t[\"ks1.tbl1\",\"ks2.tbl2\"]\t\"db\"\n", 102 bindVars: stringBindVar, 103 }, { // 5 104 redact: true, 105 format: "text", 106 expected: "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\"PRIMARY\"\t\"suuid\"\tfalse\t[\"ks1.tbl1\",\"ks2.tbl2\"]\t\"db\"\n", 107 bindVars: stringBindVar, 108 }, { // 6 109 redact: false, 110 format: "json", 111 expected: "{\"ActiveKeyspace\":\"db\",\"BindVars\":{\"strVal\":{\"type\":\"VARCHAR\",\"value\":\"abc\"}},\"Cached Plan\":false,\"CommitTime\":0,\"Effective Caller\":\"\",\"End\":\"2017-01-01 01:02:04.000001\",\"Error\":\"\",\"ExecuteTime\":0,\"ImmediateCaller\":\"\",\"Method\":\"test\",\"PlanTime\":0,\"RemoteAddr\":\"\",\"RowsAffected\":0,\"SQL\":\"sql1\",\"SessionUUID\":\"suuid\",\"ShardQueries\":0,\"Start\":\"2017-01-01 01:02:03.000000\",\"StmtType\":\"\",\"TablesUsed\":[\"ks1.tbl1\",\"ks2.tbl2\"],\"TabletType\":\"PRIMARY\",\"TotalTime\":1.000001,\"Username\":\"\"}", 112 bindVars: stringBindVar, 113 }, { // 7 114 redact: true, 115 format: "json", 116 expected: "{\"ActiveKeyspace\":\"db\",\"BindVars\":\"[REDACTED]\",\"Cached Plan\":false,\"CommitTime\":0,\"Effective Caller\":\"\",\"End\":\"2017-01-01 01:02:04.000001\",\"Error\":\"\",\"ExecuteTime\":0,\"ImmediateCaller\":\"\",\"Method\":\"test\",\"PlanTime\":0,\"RemoteAddr\":\"\",\"RowsAffected\":0,\"SQL\":\"sql1\",\"SessionUUID\":\"suuid\",\"ShardQueries\":0,\"Start\":\"2017-01-01 01:02:03.000000\",\"StmtType\":\"\",\"TablesUsed\":[\"ks1.tbl1\",\"ks2.tbl2\"],\"TabletType\":\"PRIMARY\",\"TotalTime\":1.000001,\"Username\":\"\"}", 117 bindVars: stringBindVar, 118 }, 119 } 120 121 for i, test := range tests { 122 t.Run(strconv.Itoa(i), func(t *testing.T) { 123 logStats.BindVariables = test.bindVars 124 for _, variable := range logStats.BindVariables { 125 fmt.Println("->" + fmt.Sprintf("%v", variable)) 126 } 127 streamlog.SetRedactDebugUIQueries(test.redact) 128 streamlog.SetQueryLogFormat(test.format) 129 if test.format == "text" { 130 got := testFormat(t, logStats, params) 131 assert.Equal(t, test.expected, got) 132 for _, variable := range logStats.BindVariables { 133 fmt.Println("->" + fmt.Sprintf("%v", variable)) 134 } 135 return 136 } 137 138 got := testFormat(t, logStats, params) 139 var parsed map[string]any 140 err := json.Unmarshal([]byte(got), &parsed) 141 assert.NoError(t, err) 142 assert.NotNil(t, parsed) 143 formatted, err := json.Marshal(parsed) 144 assert.NoError(t, err) 145 assert.Equal(t, test.expected, string(formatted)) 146 }) 147 } 148 } 149 150 func TestLogStatsFilter(t *testing.T) { 151 defer func() { streamlog.SetQueryLogFilterTag("") }() 152 153 logStats := NewLogStats(context.Background(), "test", "sql1 /* LOG_THIS_QUERY */", "", map[string]*querypb.BindVariable{"intVal": sqltypes.Int64BindVariable(1)}) 154 logStats.StartTime = time.Date(2017, time.January, 1, 1, 2, 3, 0, time.UTC) 155 logStats.EndTime = time.Date(2017, time.January, 1, 1, 2, 4, 1234, time.UTC) 156 params := map[string][]string{"full": {}} 157 158 got := testFormat(t, logStats, params) 159 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\"\"\tfalse\t[]\t\"\"\n" 160 assert.Equal(t, want, got) 161 162 streamlog.SetQueryLogFilterTag("LOG_THIS_QUERY") 163 got = testFormat(t, logStats, params) 164 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\"\"\tfalse\t[]\t\"\"\n" 165 assert.Equal(t, want, got) 166 167 streamlog.SetQueryLogFilterTag("NOT_THIS_QUERY") 168 got = testFormat(t, logStats, params) 169 want = "" 170 assert.Equal(t, want, got) 171 } 172 173 func TestLogStatsRowThreshold(t *testing.T) { 174 defer func() { streamlog.SetQueryLogRowThreshold(0) }() 175 176 logStats := NewLogStats(context.Background(), "test", "sql1 /* LOG_THIS_QUERY */", "", map[string]*querypb.BindVariable{"intVal": sqltypes.Int64BindVariable(1)}) 177 logStats.StartTime = time.Date(2017, time.January, 1, 1, 2, 3, 0, time.UTC) 178 logStats.EndTime = time.Date(2017, time.January, 1, 1, 2, 4, 1234, time.UTC) 179 params := map[string][]string{"full": {}} 180 181 got := testFormat(t, logStats, params) 182 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\"\"\tfalse\t[]\t\"\"\n" 183 assert.Equal(t, want, got) 184 185 streamlog.SetQueryLogRowThreshold(0) 186 got = testFormat(t, logStats, params) 187 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\"\"\tfalse\t[]\t\"\"\n" 188 assert.Equal(t, want, got) 189 streamlog.SetQueryLogRowThreshold(1) 190 got = testFormat(t, logStats, params) 191 assert.Empty(t, got) 192 } 193 194 func TestLogStatsContextHTML(t *testing.T) { 195 html := "HtmlContext" 196 callInfo := &fakecallinfo.FakeCallInfo{ 197 Html: html, 198 } 199 ctx := callinfo.NewContext(context.Background(), callInfo) 200 logStats := NewLogStats(ctx, "test", "sql1", "", map[string]*querypb.BindVariable{}) 201 if string(logStats.ContextHTML()) != html { 202 t.Fatalf("expect to get html: %s, but got: %s", html, string(logStats.ContextHTML())) 203 } 204 } 205 206 func TestLogStatsErrorStr(t *testing.T) { 207 logStats := NewLogStats(context.Background(), "test", "sql1", "", map[string]*querypb.BindVariable{}) 208 if logStats.ErrorStr() != "" { 209 t.Fatalf("should not get error in stats, but got: %s", logStats.ErrorStr()) 210 } 211 errStr := "unknown error" 212 logStats.Error = errors.New(errStr) 213 if !strings.Contains(logStats.ErrorStr(), errStr) { 214 t.Fatalf("expect string '%s' in error message, but got: %s", errStr, logStats.ErrorStr()) 215 } 216 } 217 218 func TestLogStatsRemoteAddrUsername(t *testing.T) { 219 logStats := NewLogStats(context.Background(), "test", "sql1", "", map[string]*querypb.BindVariable{}) 220 addr, user := logStats.RemoteAddrUsername() 221 if addr != "" { 222 t.Fatalf("remote addr should be empty") 223 } 224 if user != "" { 225 t.Fatalf("username should be empty") 226 } 227 228 remoteAddr := "1.2.3.4" 229 username := "vt" 230 callInfo := &fakecallinfo.FakeCallInfo{ 231 Remote: remoteAddr, 232 User: username, 233 } 234 ctx := callinfo.NewContext(context.Background(), callInfo) 235 logStats = NewLogStats(ctx, "test", "sql1", "", map[string]*querypb.BindVariable{}) 236 addr, user = logStats.RemoteAddrUsername() 237 if addr != remoteAddr { 238 t.Fatalf("expected to get remote addr: %s, but got: %s", remoteAddr, addr) 239 } 240 if user != username { 241 t.Fatalf("expected to get username: %s, but got: %s", username, user) 242 } 243 }