Skip to content

Commit

Permalink
Add option to log error queries only (#17554)
Browse files Browse the repository at this point in the history
Signed-off-by: Harshit Gangal <[email protected]>
Signed-off-by: Andres Taylor <[email protected]>
Co-authored-by: Andres Taylor <[email protected]>
  • Loading branch information
harshit-gangal and systay authored Jan 22, 2025
1 parent aaee12a commit d1aa2f4
Show file tree
Hide file tree
Showing 41 changed files with 457 additions and 502 deletions.
7 changes: 6 additions & 1 deletion changelog/22.0/22.0.0/summary.md
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,7 @@
- **[Stalled Disk Recovery in VTOrc](#stall-disk-recovery)**
- **[Update default MySQL version to 8.0.40](#mysql-8-0-40)**
- **[Update lite images to Debian Bookworm](#debian-bookworm)**
- **[Support for Filtering Query logs on Error](#query-logs)**
- **[Minor Changes](#minor-changes)**
- **[VTTablet Flags](#flags-vttablet)**
- **[Topology read concurrency behaviour changes](#topo-read-concurrency-changes)**
Expand All @@ -25,7 +26,7 @@

These are the RPC changes made in this release -

1. `GetTransactionInfo` RPC has been added to both `VtctldServer`, and `TabletManagerClient` interface. These RPCs are used to fecilitate the users in reading the state of an unresolved distributed transaction. This can be useful in debugging what went wrong and how to fix the problem.
1. `GetTransactionInfo` RPC has been added to both `VtctldServer`, and `TabletManagerClient` interface. These RPCs are used to facilitate the users in reading the state of an unresolved distributed transaction. This can be useful in debugging what went wrong and how to fix the problem.

### <a id="deprecations-and-deletions"/>Deprecations and Deletions</a>

Expand Down Expand Up @@ -132,6 +133,10 @@ This is the last time this will be needed in the `8.0.x` series, as starting wit

The base system now uses Debian Bookworm instead of Debian Bullseye for the `vitess/lite` images. This change was brought by [Pull Request #17552].

### <a id="query-logs"/>Support for Filtering Query logs on Error</a>

The `querylog-mode` setting can be configured to `error` to log only queries that result in errors. This option is supported in both VTGate and VTTablet.

## <a id="minor-changes"/>Minor Changes</a>

#### <a id="flags-vttablet"/>VTTablet Flags</a>
Expand Down
1 change: 1 addition & 0 deletions go/flags/endtoend/vtcombo.txt
Original file line number Diff line number Diff line change
Expand Up @@ -272,6 +272,7 @@ Flags:
--querylog-buffer-size int Maximum number of buffered query logs before throttling log output (default 10)
--querylog-filter-tag string string that must be present in the query for it to be logged; if using a value as the tag, you need to disable query normalization
--querylog-format string format for query logs ("text" or "json") (default "text")
--querylog-mode string Mode for logging queries. "error" will only log queries that return an error. Otherwise all queries will be logged. (default "all")
--querylog-row-threshold uint Number of rows a query has to return or affect before being logged; not useful for streaming queries. 0 means all queries will be logged.
--querylog-sample-rate float Sample rate for logging queries. Value must be between 0.0 (no logging) and 1.0 (all queries)
--queryserver-config-acl-exempt-acl string an acl that exempt from table acl checking (this acl is free to access any vitess tables).
Expand Down
1 change: 1 addition & 0 deletions go/flags/endtoend/vtgate.txt
Original file line number Diff line number Diff line change
Expand Up @@ -177,6 +177,7 @@ Flags:
--querylog-buffer-size int Maximum number of buffered query logs before throttling log output (default 10)
--querylog-filter-tag string string that must be present in the query for it to be logged; if using a value as the tag, you need to disable query normalization
--querylog-format string format for query logs ("text" or "json") (default "text")
--querylog-mode string Mode for logging queries. "error" will only log queries that return an error. Otherwise all queries will be logged. (default "all")
--querylog-row-threshold uint Number of rows a query has to return or affect before being logged; not useful for streaming queries. 0 means all queries will be logged.
--querylog-sample-rate float Sample rate for logging queries. Value must be between 0.0 (no logging) and 1.0 (all queries)
--redact-debug-ui-queries redact full queries and bind variables from debug UI
Expand Down
1 change: 1 addition & 0 deletions go/flags/endtoend/vttablet.txt
Original file line number Diff line number Diff line change
Expand Up @@ -264,6 +264,7 @@ Flags:
--query-log-stream-handler string URL handler for streaming queries log (default "/debug/querylog")
--querylog-filter-tag string string that must be present in the query for it to be logged; if using a value as the tag, you need to disable query normalization
--querylog-format string format for query logs ("text" or "json") (default "text")
--querylog-mode string Mode for logging queries. "error" will only log queries that return an error. Otherwise all queries will be logged. (default "all")
--querylog-row-threshold uint Number of rows a query has to return or affect before being logged; not useful for streaming queries. 0 means all queries will be logged.
--querylog-sample-rate float Sample rate for logging queries. Value must be between 0.0 (no logging) and 1.0 (all queries)
--queryserver-config-acl-exempt-acl string an acl that exempt from table acl checking (this acl is free to access any vitess tables).
Expand Down
96 changes: 48 additions & 48 deletions go/streamlog/streamlog.go
Original file line number Diff line number Diff line change
Expand Up @@ -20,7 +20,7 @@ package streamlog
import (
"fmt"
"io"
rand "math/rand/v2"
"math/rand/v2"
"net/http"
"net/url"
"os"
Expand All @@ -47,40 +47,42 @@ var (
[]string{"Log", "Subscriber"})
)

var (
redactDebugUIQueries bool
queryLogFilterTag string
queryLogRowThreshold uint64
queryLogFormat = "text"
queryLogSampleRate float64
)
const (
// QueryLogFormatText is the format specifier for text querylog output
QueryLogFormatText = "text"

func GetRedactDebugUIQueries() bool {
return redactDebugUIQueries
}
// QueryLogFormatJSON is the format specifier for json querylog output
QueryLogFormatJSON = "json"

func SetRedactDebugUIQueries(newRedactDebugUIQueries bool) {
redactDebugUIQueries = newRedactDebugUIQueries
}
// QueryLogModeAll is the mode specifier for logging all queries
QueryLogModeAll = "all"

func SetQueryLogFilterTag(newQueryLogFilterTag string) {
queryLogFilterTag = newQueryLogFilterTag
}
// QueryLogModeError is the mode specifier for logging only queries that return an error
QueryLogModeError = "error"
)

func SetQueryLogRowThreshold(newQueryLogRowThreshold uint64) {
queryLogRowThreshold = newQueryLogRowThreshold
type QueryLogConfig struct {
RedactDebugUIQueries bool
FilterTag string
Format string
Mode string
RowThreshold uint64
sampleRate float64
}

func SetQueryLogSampleRate(sampleRate float64) {
queryLogSampleRate = sampleRate
var queryLogConfigInstance = QueryLogConfig{
Format: QueryLogFormatText,
Mode: QueryLogModeAll,
}

func GetQueryLogFormat() string {
return queryLogFormat
func GetQueryLogConfig() QueryLogConfig {
return queryLogConfigInstance
}

func SetQueryLogFormat(newQueryLogFormat string) {
queryLogFormat = newQueryLogFormat
func NewQueryLogConfigForTest() QueryLogConfig {
return QueryLogConfig{
Format: QueryLogFormatText,
}
}

func init() {
Expand All @@ -91,28 +93,23 @@ func init() {

func registerStreamLogFlags(fs *pflag.FlagSet) {
// RedactDebugUIQueries controls whether full queries and bind variables are suppressed from debug UIs.
fs.BoolVar(&redactDebugUIQueries, "redact-debug-ui-queries", redactDebugUIQueries, "redact full queries and bind variables from debug UI")
fs.BoolVar(&queryLogConfigInstance.RedactDebugUIQueries, "redact-debug-ui-queries", queryLogConfigInstance.RedactDebugUIQueries, "redact full queries and bind variables from debug UI")

// QueryLogFormat controls the format of the query log (either text or json)
fs.StringVar(&queryLogFormat, "querylog-format", queryLogFormat, "format for query logs (\"text\" or \"json\")")
fs.StringVar(&queryLogConfigInstance.Format, "querylog-format", queryLogConfigInstance.Format, "format for query logs (\"text\" or \"json\")")

// QueryLogFilterTag contains an optional string that must be present in the query for it to be logged
fs.StringVar(&queryLogFilterTag, "querylog-filter-tag", queryLogFilterTag, "string that must be present in the query for it to be logged; if using a value as the tag, you need to disable query normalization")
fs.StringVar(&queryLogConfigInstance.FilterTag, "querylog-filter-tag", queryLogConfigInstance.FilterTag, "string that must be present in the query for it to be logged; if using a value as the tag, you need to disable query normalization")

// QueryLogRowThreshold only log queries returning or affecting this many rows
fs.Uint64Var(&queryLogRowThreshold, "querylog-row-threshold", queryLogRowThreshold, "Number of rows a query has to return or affect before being logged; not useful for streaming queries. 0 means all queries will be logged.")
fs.Uint64Var(&queryLogConfigInstance.RowThreshold, "querylog-row-threshold", queryLogConfigInstance.RowThreshold, "Number of rows a query has to return or affect before being logged; not useful for streaming queries. 0 means all queries will be logged.")

// QueryLogSampleRate causes a sample of queries to be logged
fs.Float64Var(&queryLogSampleRate, "querylog-sample-rate", queryLogSampleRate, "Sample rate for logging queries. Value must be between 0.0 (no logging) and 1.0 (all queries)")
}

const (
// QueryLogFormatText is the format specifier for text querylog output
QueryLogFormatText = "text"
fs.Float64Var(&queryLogConfigInstance.sampleRate, "querylog-sample-rate", queryLogConfigInstance.sampleRate, "Sample rate for logging queries. Value must be between 0.0 (no logging) and 1.0 (all queries)")

// QueryLogFormatJSON is the format specifier for json querylog output
QueryLogFormatJSON = "json"
)
// QueryLogMode controls the mode for logging queries (all or error)
fs.StringVar(&queryLogConfigInstance.Mode, "querylog-mode", queryLogConfigInstance.Mode, `Mode for logging queries. "error" will only log queries that return an error. Otherwise all queries will be logged.`)
}

// StreamLogger is a non-blocking broadcaster of messages.
// Subscribers can use channels or HTTP.
Expand Down Expand Up @@ -257,27 +254,30 @@ func GetFormatter[T any](logger *StreamLogger[T]) LogFormatter {
}
}

// shouldSampleQuery returns true if a query should be sampled based on queryLogSampleRate
func shouldSampleQuery() bool {
if queryLogSampleRate <= 0 {
// shouldSampleQuery returns true if a query should be sampled based on sampleRate
func (qlConfig QueryLogConfig) shouldSampleQuery() bool {
if qlConfig.sampleRate <= 0 {
return false
} else if queryLogSampleRate >= 1 {
} else if qlConfig.sampleRate >= 1 {
return true
}
return rand.Float64() <= queryLogSampleRate
return rand.Float64() <= qlConfig.sampleRate
}

// ShouldEmitLog returns whether the log with the given SQL query
// should be emitted or filtered
func ShouldEmitLog(sql string, rowsAffected, rowsReturned uint64) bool {
if shouldSampleQuery() {
func (qlConfig QueryLogConfig) ShouldEmitLog(sql string, rowsAffected, rowsReturned uint64, hasError bool) bool {
if qlConfig.shouldSampleQuery() {
return true
}
if queryLogRowThreshold > max(rowsAffected, rowsReturned) && queryLogFilterTag == "" {
if qlConfig.RowThreshold > max(rowsAffected, rowsReturned) && qlConfig.FilterTag == "" {
return false
}
if queryLogFilterTag != "" {
return strings.Contains(sql, queryLogFilterTag)
if qlConfig.FilterTag != "" {
return strings.Contains(sql, qlConfig.FilterTag)
}
if qlConfig.Mode == QueryLogModeError {
return hasError
}
return true
}
79 changes: 29 additions & 50 deletions go/streamlog/streamlog_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -266,40 +266,29 @@ func TestFile(t *testing.T) {
}

func TestShouldSampleQuery(t *testing.T) {
queryLogSampleRate = -1
assert.False(t, shouldSampleQuery())
qlConfig := QueryLogConfig{sampleRate: -1}
assert.False(t, qlConfig.shouldSampleQuery())

queryLogSampleRate = 0
assert.False(t, shouldSampleQuery())
qlConfig.sampleRate = 0
assert.False(t, qlConfig.shouldSampleQuery())

// for test coverage, can't test a random result
queryLogSampleRate = 0.5
shouldSampleQuery()
qlConfig.sampleRate = 1.0
assert.True(t, qlConfig.shouldSampleQuery())

queryLogSampleRate = 1.0
assert.True(t, shouldSampleQuery())

queryLogSampleRate = 100.0
assert.True(t, shouldSampleQuery())
qlConfig.sampleRate = 100.0
assert.True(t, qlConfig.shouldSampleQuery())
}

func TestShouldEmitLog(t *testing.T) {
origQueryLogFilterTag := queryLogFilterTag
origQueryLogRowThreshold := queryLogRowThreshold
origQueryLogSampleRate := queryLogSampleRate
defer func() {
SetQueryLogFilterTag(origQueryLogFilterTag)
SetQueryLogRowThreshold(origQueryLogRowThreshold)
SetQueryLogSampleRate(origQueryLogSampleRate)
}()

tests := []struct {
sql string
qLogFilterTag string
qLogRowThreshold uint64
qLogSampleRate float64
qLogMode string
rowsAffected uint64
rowsReturned uint64
errored bool
ok bool
}{
{
Expand Down Expand Up @@ -356,43 +345,33 @@ func TestShouldEmitLog(t *testing.T) {
rowsReturned: 17,
ok: true,
},
{
sql: "log only error - no error",
qLogMode: "error",
errored: false,
ok: false,
},
{
sql: "log only error - errored",
qLogMode: "error",
errored: true,
ok: true,
},
}

for _, tt := range tests {
t.Run(tt.sql, func(t *testing.T) {
SetQueryLogFilterTag(tt.qLogFilterTag)
SetQueryLogRowThreshold(tt.qLogRowThreshold)
SetQueryLogSampleRate(tt.qLogSampleRate)

require.Equal(t, tt.ok, ShouldEmitLog(tt.sql, tt.rowsAffected, tt.rowsReturned))
qlConfig := QueryLogConfig{
FilterTag: tt.qLogFilterTag,
RowThreshold: tt.qLogRowThreshold,
sampleRate: tt.qLogSampleRate,
Mode: tt.qLogMode,
}
require.Equal(t, tt.ok, qlConfig.ShouldEmitLog(tt.sql, tt.rowsAffected, tt.rowsReturned, tt.errored))
})
}
}

func BenchmarkShouldEmitLog(b *testing.B) {
b.Run("default", func(b *testing.B) {
SetQueryLogSampleRate(0.0)
for i := 0; i < b.N; i++ {
ShouldEmitLog("select * from test where user='someone'", 0, 123)
}
})
b.Run("filter_tag", func(b *testing.B) {
SetQueryLogSampleRate(0.0)
SetQueryLogFilterTag("LOG_QUERY")
defer SetQueryLogFilterTag("")
for i := 0; i < b.N; i++ {
ShouldEmitLog("select /* LOG_QUERY=1 */ * from test where user='someone'", 0, 123)
}
})
b.Run("50%_sample_rate", func(b *testing.B) {
SetQueryLogSampleRate(0.5)
defer SetQueryLogSampleRate(0.0)
for i := 0; i < b.N; i++ {
ShouldEmitLog("select * from test where user='someone'", 0, 123)
}
})
}

func TestGetFormatter(t *testing.T) {
tests := []struct {
name string
Expand Down
7 changes: 6 additions & 1 deletion go/vt/vtexplain/vtexplain_vtgate.go
Original file line number Diff line number Diff line change
Expand Up @@ -74,7 +74,12 @@ func (vte *VTExplain) initVtgateExecutor(ctx context.Context, ts *topo.Server, v
var schemaTracker vtgate.SchemaInfo // no schema tracker for these tests
queryLogBufferSize := 10
plans := theine.NewStore[vtgate.PlanCacheKey, *engine.Plan](4*1024*1024, false)
vte.vtgateExecutor = vtgate.NewExecutor(ctx, vte.env, vte.explainTopo, Cell, resolver, opts.Normalize, false, streamSize, plans, schemaTracker, false, opts.PlannerVersion, 0, vtgate.NewDynamicViperConfig())
eConfig := vtgate.ExecutorConfig{
Normalize: opts.Normalize,
StreamSize: streamSize,
AllowScatter: true,
}
vte.vtgateExecutor = vtgate.NewExecutor(ctx, vte.env, vte.explainTopo, Cell, resolver, eConfig, false, plans, schemaTracker, opts.PlannerVersion, vtgate.NewDynamicViperConfig())
vte.vtgateExecutor.SetQueryLogger(streamlog.New[*logstats.LogStats]("VTGate", queryLogBufferSize))

return nil
Expand Down
2 changes: 1 addition & 1 deletion go/vt/vtgate/bench_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -80,7 +80,7 @@ func BenchmarkWithNormalizer(b *testing.B) {
func BenchmarkWithoutNormalizer(b *testing.B) {
vtgateInst, _, ctx := createVtgateEnv(b)

vtgateInst.executor.normalize = false
vtgateInst.executor.config.Normalize = false

for i := 0; i < b.N; i++ {
_, _, err := vtgateInst.Execute(
Expand Down
Loading

0 comments on commit d1aa2f4

Please sign in to comment.