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  }