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.

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 option to log error queries only #17554

Merged
merged 9 commits into from
Jan 22, 2025
5 changes: 5 additions & 0 deletions changelog/22.0/22.0.0/summary.md
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,7 @@
- **[Support for LAST_INSERT_ID(x)](#last-insert-id)**
- **[Support for Maximum Idle Connections in the Pool](#max-idle-connections)**
- **[Stalled Disk Recovery in VTOrc](#stall-disk-recovery)**
- **[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 Down Expand Up @@ -106,6 +107,10 @@ VTOrc can now identify and recover from stalled disk errors. VTTablets test whet

To opt into this feature, `--enable-primary-disk-stalled-recovery` flag has to be specified on VTOrc, and `--disk-write-dir` flag has to be specified on the vttablets. `--disk-write-interval` and `--disk-write-timeout` flags can be used to configure the polling interval and timeout respectively.

### <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.
--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.
--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.
harshit-gangal marked this conversation as resolved.
Show resolved Hide resolved
--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
81 changes: 38 additions & 43 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,29 @@ var (
[]string{"Log", "Subscriber"})
)

var (
redactDebugUIQueries bool
queryLogFilterTag string
queryLogRowThreshold uint64
queryLogFormat = "text"
queryLogSampleRate float64
)

func GetRedactDebugUIQueries() bool {
return redactDebugUIQueries
}

func SetRedactDebugUIQueries(newRedactDebugUIQueries bool) {
redactDebugUIQueries = newRedactDebugUIQueries
}
const QueryLogModeError = "error"

func SetQueryLogFilterTag(newQueryLogFilterTag string) {
queryLogFilterTag = newQueryLogFilterTag
type QueryLogConfig struct {
RedactDebugUIQueries bool
FilterTag string
Format string
Mode string
RowThreshold uint64
sampleRate float64
}

func SetQueryLogRowThreshold(newQueryLogRowThreshold uint64) {
queryLogRowThreshold = newQueryLogRowThreshold
var queryLogConfigInstance = QueryLogConfig{
Format: "text",
}

func SetQueryLogSampleRate(sampleRate float64) {
queryLogSampleRate = sampleRate
func GetQueryLogConfig() QueryLogConfig {
return queryLogConfigInstance
}

func GetQueryLogFormat() string {
return queryLogFormat
}

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

func init() {
Expand All @@ -91,19 +80,22 @@ 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)")
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)")

// 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.`)
}

const (
Expand Down Expand Up @@ -257,27 +249,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
harshit-gangal marked this conversation as resolved.
Show resolved Hide resolved
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
Loading