Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

add optional tag-based filtering for query logging #4895

Merged
merged 3 commits into from
Jun 1, 2019
Merged

add optional tag-based filtering for query logging #4895

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
f79549b
add optional tag-based filtering for query logging
demmer May 31, 2019
a0f2d1f
ensure querylogz still shows queries when filter tag is enabled
demmer May 31, 2019
1bfa92d
rename FilterTag to QueryLogFilterTag for consistency and clarity
demmer May 31, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
13 changes: 13 additions & 0 deletions go/streamlog/streamlog.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@ import (
"net/url"
"os"
"os/signal"
"strings"
"sync"
"syscall"

Expand All @@ -40,6 +41,9 @@ var (
// QueryLogFormat controls the format of the query log (either text or json)
QueryLogFormat = flag.String("querylog-format", "text", "format for query logs (\"text\" or \"json\")")

// QueryLogFilterTag contains an optional string that must be present in the query for it to be logged
QueryLogFilterTag = flag.String("querylog-filter-tag", "", "string that must be present in the query for it to be logged")

sendCount = stats.NewCountersWithSingleLabel("StreamlogSend", "stream log send count", "logger_names")
deliveredCount = stats.NewCountersWithMultiLabels(
"StreamlogDelivered",
Expand Down Expand Up @@ -201,3 +205,12 @@ func GetFormatter(logger *StreamLogger) LogFormatter {
return fmter.Logf(w, params)
}
}

// ShouldEmitLog returns whether the log with the given SQL query
// should be emitted or filtered
func ShouldEmitLog(sql string) bool {
if *QueryLogFilterTag == "" {
return true
}
return strings.Contains(sql, *QueryLogFilterTag)
}
4 changes: 4 additions & 0 deletions go/vt/vtgate/logstats.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -121,6 +121,10 @@ func (stats *LogStats) RemoteAddrUsername() (string, string) {
// Logf formats the log record to the given writer, either as
// tab-separated list of logged fields or as JSON.
func (stats *LogStats) Logf(w io.Writer, params url.Values) error {
if !streamlog.ShouldEmitLog(stats.SQL) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does this include the full query or just the comments? Do you have the parsed sql in this context? I wonder if a better approach is to have a proper directive in the trailing comments. If stats.SQL contains the full original query, one thing that it's not ideal about the current approach is that random queries that contain the LogFilterTag will sneak into the logging.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It is the full query but without the bind variables, which is what’s logged today.

It is true that a more robust system would use properly parsed comment directives but I think this isn’t too big of a deal since users can easily come up with a filter tag that doesn’t match any of the table names / column names, and since the bind vars aren’t in the string there’s no worry about accidental matching of any column value.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also fwiw there isn’t an easy way to plumb the parsed query down into the logging subsystem so we’d probably need to parse again which seems overly conservative compared to the simple string search.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, parsing again just for this does not make sense to me.

Thanks for the clarifications.

return nil
}

formattedBindVars := "\"[REDACTED]\""
if !*streamlog.RedactDebugUIQueries {
_, fullBindParams := params["full"]
Expand Down
29 changes: 29 additions & 0 deletions go/vt/vtgate/logstats_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -126,6 +126,35 @@ func TestLogStatsFormat(t *testing.T) {
*streamlog.QueryLogFormat = "text"
}

func TestLogStatsFilter(t *testing.T) {
defer func() { *streamlog.QueryLogFilterTag = "" }()

logStats := NewLogStats(context.Background(), "test", "sql1 /* LOG_THIS_QUERY */", 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)
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"
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"
if got != want {
t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
}

*streamlog.QueryLogFilterTag = "NOT_THIS_QUERY"
got = testFormat(logStats, url.Values(params))
want = ""
if got != want {
t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
}
}

func TestLogStatsContextHTML(t *testing.T) {
html := "HtmlContext"
callInfo := &fakecallinfo.FakeCallInfo{
Expand Down
12 changes: 12 additions & 0 deletions go/vt/vtgate/querylogz_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,7 @@ import (
"time"

"golang.org/x/net/context"
"vitess.io/vitess/go/streamlog"
"vitess.io/vitess/go/vt/callerid"
)

Expand Down Expand Up @@ -142,6 +143,17 @@ func TestQuerylogzHandlerFormatting(t *testing.T) {
close(ch)
body, _ = ioutil.ReadAll(response.Body)
checkQuerylogzHasStats(t, slowQueryPattern, logStats, body)

// ensure querylogz is not affected by the filter tag
*streamlog.QueryLogFilterTag = "XXX_SKIP_ME"
defer func() { *streamlog.QueryLogFilterTag = "" }()
ch = make(chan interface{}, 1)
ch <- logStats
querylogzHandler(ch, response, req)
close(ch)
body, _ = ioutil.ReadAll(response.Body)
checkQuerylogzHasStats(t, slowQueryPattern, logStats, body)

}

func checkQuerylogzHasStats(t *testing.T, pattern []string, logStats *LogStats, page []byte) {
Expand Down
11 changes: 11 additions & 0 deletions go/vt/vttablet/tabletserver/querylogz_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,7 @@ import (
"time"

"golang.org/x/net/context"
"vitess.io/vitess/go/streamlog"
"vitess.io/vitess/go/vt/callerid"
"vitess.io/vitess/go/vt/vttablet/tabletserver/planbuilder"
"vitess.io/vitess/go/vt/vttablet/tabletserver/tabletenv"
Expand Down Expand Up @@ -148,6 +149,16 @@ func TestQuerylogzHandler(t *testing.T) {
close(ch)
body, _ = ioutil.ReadAll(response.Body)
checkQuerylogzHasStats(t, slowQueryPattern, logStats, body)

// ensure querylogz is not affected by the filter tag
*streamlog.QueryLogFilterTag = "XXX_SKIP_ME"
defer func() { *streamlog.QueryLogFilterTag = "" }()
ch = make(chan interface{}, 1)
ch <- logStats
querylogzHandler(ch, response, req)
close(ch)
body, _ = ioutil.ReadAll(response.Body)
checkQuerylogzHasStats(t, slowQueryPattern, logStats, body)
}

func checkQuerylogzHasStats(t *testing.T, pattern []string, logStats *tabletenv.LogStats, page []byte) {
Expand Down
4 changes: 4 additions & 0 deletions go/vt/vttablet/tabletserver/tabletenv/logstats.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -180,6 +180,10 @@ func (stats *LogStats) CallInfo() (string, string) {
// Logf formats the log record to the given writer, either as
// tab-separated list of logged fields or as JSON.
func (stats *LogStats) Logf(w io.Writer, params url.Values) error {
if !streamlog.ShouldEmitLog(stats.OriginalSQL) {
return nil
}

rewrittenSQL := "[REDACTED]"
formattedBindVars := "\"[REDACTED]\""

Expand Down
35 changes: 35 additions & 0 deletions go/vt/vttablet/tabletserver/tabletenv/logstats_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -149,6 +149,41 @@ func TestLogStatsFormat(t *testing.T) {
*streamlog.QueryLogFormat = "text"
}

func TestLogStatsFilter(t *testing.T) {
defer func() { *streamlog.QueryLogFilterTag = "" }()

logStats := NewLogStats(context.Background(), "test")
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.OriginalSQL = "sql /* LOG_THIS_QUERY */"
logStats.BindVariables = map[string]*querypb.BindVariable{"intVal": sqltypes.Int64BindVariable(1)}
logStats.AddRewrittenSQL("sql with pii", time.Now())
logStats.MysqlResponseTime = 0
logStats.Rows = [][]sqltypes.Value{{sqltypes.NewVarBinary("a")}}
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\t\t\"sql /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\" ]\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t1\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\t\t\"sql /* LOG_THIS_QUERY */\"\tmap[intVal:type:INT64 value:\"1\" ]\t1\t\"sql with pii\"\tmysql\t0.000000\t0.000000\t0\t1\t\"\"\t\n"
if got != want {
t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
}

*streamlog.QueryLogFilterTag = "NOT_THIS_QUERY"
got = testFormat(logStats, url.Values(params))
want = ""
if got != want {
t.Errorf("logstats format: got:\n%q\nwant:\n%q\n", got, want)
}

}

func TestLogStatsFormatQuerySources(t *testing.T) {
logStats := NewLogStats(context.Background(), "test")
if logStats.FmtQuerySources() != "none" {
Expand Down