From 230230cf0b9bdcb19f8ae9869651fdbe50f50a81 Mon Sep 17 00:00:00 2001 From: Aliaksandr Valialkin Date: Sat, 11 Nov 2023 12:30:08 +0100 Subject: [PATCH] lib/logger: add `-loggerMaxArgLen` command-line flag for fine-tuning the maximum length of logged args --- README.md | 2 ++ app/vmselect/promql/eval.go | 7 ++++++- app/vmselect/promql/rollup_result_cache.go | 11 ++++++----- docs/CHANGELOG.md | 1 + docs/README.md | 2 ++ docs/Single-server-VictoriaMetrics.md | 2 ++ lib/bytesutil/bytesutil.go | 11 ----------- lib/logger/logger.go | 18 +++++------------- lib/storage/search.go | 3 ++- lib/storage/tag_filters.go | 3 ++- lib/stringsutil/stringsutil.go | 16 ++++++++++++++++ 11 files changed, 44 insertions(+), 32 deletions(-) create mode 100644 lib/stringsutil/stringsutil.go diff --git a/README.md b/README.md index 5b2d87c2c..2a92447b5 100644 --- a/README.md +++ b/README.md @@ -2655,6 +2655,8 @@ Pass `-help` to VictoriaMetrics in order to see the list of supported command-li Allows renaming fields in JSON formatted logs. Example: "ts:timestamp,msg:message" renames "ts" to "timestamp" and "msg" to "message". Supported fields: ts, level, caller, msg -loggerLevel string Minimum level of errors to log. Possible values: INFO, WARN, ERROR, FATAL, PANIC (default "INFO") + -loggerMaxArgLen int + The maximum length of a single logged argument. Longer arguments are replaced with 'arg_start..arg_end', where 'arg_start' and 'arg_end' is prefix and suffix of the arg with the length not exceeding -loggerMaxArgLen / 2 (default 500) -loggerOutput string Output for the logs. Supported values: stderr, stdout (default "stderr") -loggerTimezone string diff --git a/app/vmselect/promql/eval.go b/app/vmselect/promql/eval.go index 7b53180cc..dc930117e 100644 --- a/app/vmselect/promql/eval.go +++ b/app/vmselect/promql/eval.go @@ -23,6 +23,7 @@ import ( "github.com/VictoriaMetrics/VictoriaMetrics/lib/memory" "github.com/VictoriaMetrics/VictoriaMetrics/lib/querytracer" "github.com/VictoriaMetrics/VictoriaMetrics/lib/storage" + "github.com/VictoriaMetrics/VictoriaMetrics/lib/stringsutil" "github.com/VictoriaMetrics/metrics" "github.com/VictoriaMetrics/metricsql" ) @@ -259,7 +260,7 @@ func getTimestamps(start, end, step int64, maxPointsPerSeries int) []int64 { func evalExpr(qt *querytracer.Tracer, ec *EvalConfig, e metricsql.Expr) ([]*timeseries, error) { if qt.Enabled() { query := string(e.AppendString(nil)) - query = bytesutil.LimitStringLen(query, 300) + query = stringsutil.LimitStringLen(query, 300) mayCache := ec.mayCache() qt = qt.NewChild("eval: query=%s, timeRange=%s, step=%d, mayCache=%v", query, ec.timeRangeString(), ec.Step, mayCache) } @@ -1409,6 +1410,10 @@ func evalInstantRollup(qt *querytracer.Tracer, ec *EvalConfig, funcName string, } func hasDuplicateSeries(tss []*timeseries) bool { + if len(tss) <= 1 { + return false + } + m := make(map[string]struct{}, len(tss)) bb := bbPool.Get() defer bbPool.Put(bb) diff --git a/app/vmselect/promql/rollup_result_cache.go b/app/vmselect/promql/rollup_result_cache.go index a90c9d2e6..f0b98381e 100644 --- a/app/vmselect/promql/rollup_result_cache.go +++ b/app/vmselect/promql/rollup_result_cache.go @@ -17,6 +17,7 @@ import ( "github.com/VictoriaMetrics/VictoriaMetrics/lib/memory" "github.com/VictoriaMetrics/VictoriaMetrics/lib/querytracer" "github.com/VictoriaMetrics/VictoriaMetrics/lib/storage" + "github.com/VictoriaMetrics/VictoriaMetrics/lib/stringsutil" "github.com/VictoriaMetrics/VictoriaMetrics/lib/workingsetcache" "github.com/VictoriaMetrics/fastcache" "github.com/VictoriaMetrics/metrics" @@ -205,7 +206,7 @@ func ResetRollupResultCache() { func (rrc *rollupResultCache) GetInstantValues(qt *querytracer.Tracer, expr metricsql.Expr, window, step int64, etfss [][]storage.TagFilter) []*timeseries { if qt.Enabled() { query := string(expr.AppendString(nil)) - query = bytesutil.LimitStringLen(query, 300) + query = stringsutil.LimitStringLen(query, 300) qt = qt.NewChild("rollup cache get instant values: query=%s, window=%d, step=%d", query, window, step) defer qt.Done() } @@ -227,7 +228,7 @@ func (rrc *rollupResultCache) GetInstantValues(qt *querytracer.Tracer, expr metr func (rrc *rollupResultCache) PutInstantValues(qt *querytracer.Tracer, expr metricsql.Expr, window, step int64, etfss [][]storage.TagFilter, tss []*timeseries) { if qt.Enabled() { query := string(expr.AppendString(nil)) - query = bytesutil.LimitStringLen(query, 300) + query = stringsutil.LimitStringLen(query, 300) startStr := "" if len(tss) > 0 { startStr = storage.TimestampToHumanReadableFormat(tss[0].Timestamps[0]) @@ -260,7 +261,7 @@ func (rrc *rollupResultCache) DeleteInstantValues(qt *querytracer.Tracer, expr m if qt.Enabled() { query := string(expr.AppendString(nil)) - query = bytesutil.LimitStringLen(query, 300) + query = stringsutil.LimitStringLen(query, 300) qt.Printf("rollup result cache delete instant values: query=%s, window=%d, step=%d", query, window, step) } } @@ -268,7 +269,7 @@ func (rrc *rollupResultCache) DeleteInstantValues(qt *querytracer.Tracer, expr m func (rrc *rollupResultCache) GetSeries(qt *querytracer.Tracer, ec *EvalConfig, expr metricsql.Expr, window int64) (tss []*timeseries, newStart int64) { if qt.Enabled() { query := string(expr.AppendString(nil)) - query = bytesutil.LimitStringLen(query, 300) + query = stringsutil.LimitStringLen(query, 300) qt = qt.NewChild("rollup cache get series: query=%s, timeRange=%s, window=%d, step=%d", query, ec.timeRangeString(), window, ec.Step) defer qt.Done() } @@ -353,7 +354,7 @@ var resultBufPool bytesutil.ByteBufferPool func (rrc *rollupResultCache) PutSeries(qt *querytracer.Tracer, ec *EvalConfig, expr metricsql.Expr, window int64, tss []*timeseries) { if qt.Enabled() { query := string(expr.AppendString(nil)) - query = bytesutil.LimitStringLen(query, 300) + query = stringsutil.LimitStringLen(query, 300) qt = qt.NewChild("rollup cache put series: query=%s, timeRange=%s, step=%d, window=%d, series=%d", query, ec.timeRangeString(), ec.Step, window, len(tss)) defer qt.Done() } diff --git a/docs/CHANGELOG.md b/docs/CHANGELOG.md index 17696e662..fe3b2f2e9 100644 --- a/docs/CHANGELOG.md +++ b/docs/CHANGELOG.md @@ -81,6 +81,7 @@ The sandbox cluster installation is running under the constant load generated by * FEATURE: all: track requests with wrong auth key and wrong basic auth at `vm_http_request_errors_total` [metric](https://docs.victoriametrics.com/#monitoring) with `reason="wrong_auth_key"` and `reason="wrong_basic_auth"`. See [this issue](https://github.com/victoriaMetrics/victoriaMetrics/issues/4590). Thanks to @venkatbvc for the [pull request](https://github.com/VictoriaMetrics/VictoriaMetrics/pull/5166). * FEATURE: [vmauth](https://docs.victoriametrics.com/vmauth.html): add `tls_insecure_skip_verify` parameter which allows to disable TLS verification for backend connection. See [this issue](https://github.com/VictoriaMetrics/VictoriaMetrics/issues/5240). * FEATURE: `vmstorage`: add `-blockcache.missesBeforeCaching` command-line flag, which can be used for fine-tuning RAM usage for `indexdb/dataBlocks` cache when queries touching big number of time series are executed. +* FEATURE: add `-loggerMaxArgLen` command-line flag for fine-tuning the maximum lengths of logged args. * BUGFIX: [vmalert](https://docs.victoriametrics.com/vmalert.html): strip sensitive information such as auth headers or passwords from datasource, remote-read, remote-write or notifier URLs in log messages or UI. This behavior is by default and is controlled via `-datasource.showURL`, `-remoteRead.showURL`, `remoteWrite.showURL` or `-notifier.showURL` cmd-line flags. See [this issue](https://github.com/VictoriaMetrics/VictoriaMetrics/issues/5044). * BUGFIX: [vmalert](https://docs.victoriametrics.com/vmalert.html): fix vmalert web UI when running on 32-bit architectures machine. diff --git a/docs/README.md b/docs/README.md index 3432fda58..1f57c0436 100644 --- a/docs/README.md +++ b/docs/README.md @@ -2658,6 +2658,8 @@ Pass `-help` to VictoriaMetrics in order to see the list of supported command-li Allows renaming fields in JSON formatted logs. Example: "ts:timestamp,msg:message" renames "ts" to "timestamp" and "msg" to "message". Supported fields: ts, level, caller, msg -loggerLevel string Minimum level of errors to log. Possible values: INFO, WARN, ERROR, FATAL, PANIC (default "INFO") + -loggerMaxArgLen int + The maximum length of a single logged argument. Longer arguments are replaced with 'arg_start..arg_end', where 'arg_start' and 'arg_end' is prefix and suffix of the arg with the length not exceeding -loggerMaxArgLen / 2 (default 500) -loggerOutput string Output for the logs. Supported values: stderr, stdout (default "stderr") -loggerTimezone string diff --git a/docs/Single-server-VictoriaMetrics.md b/docs/Single-server-VictoriaMetrics.md index 9e16d636b..5e63299fe 100644 --- a/docs/Single-server-VictoriaMetrics.md +++ b/docs/Single-server-VictoriaMetrics.md @@ -2666,6 +2666,8 @@ Pass `-help` to VictoriaMetrics in order to see the list of supported command-li Allows renaming fields in JSON formatted logs. Example: "ts:timestamp,msg:message" renames "ts" to "timestamp" and "msg" to "message". Supported fields: ts, level, caller, msg -loggerLevel string Minimum level of errors to log. Possible values: INFO, WARN, ERROR, FATAL, PANIC (default "INFO") + -loggerMaxArgLen int + The maximum length of a single logged argument. Longer arguments are replaced with 'arg_start..arg_end', where 'arg_start' and 'arg_end' is prefix and suffix of the arg with the length not exceeding -loggerMaxArgLen / 2 (default 500) -loggerOutput string Output for the logs. Supported values: stderr, stdout (default "stderr") -loggerTimezone string diff --git a/lib/bytesutil/bytesutil.go b/lib/bytesutil/bytesutil.go index 8d9d1c560..daa01232d 100644 --- a/lib/bytesutil/bytesutil.go +++ b/lib/bytesutil/bytesutil.go @@ -79,14 +79,3 @@ func ToUnsafeBytes(s string) (b []byte) { slh.Cap = sh.Len return b } - -// LimitStringLen limits the length of s to maxLen. -// -// If len(s) > maxLen, then the function concatenates s prefix with s suffix. -func LimitStringLen(s string, maxLen int) string { - if maxLen <= 4 || len(s) <= maxLen { - return s - } - n := maxLen/2 - 1 - return s[:n] + ".." + s[len(s)-n:] -} diff --git a/lib/logger/logger.go b/lib/logger/logger.go index e5d93660d..1575e25c3 100644 --- a/lib/logger/logger.go +++ b/lib/logger/logger.go @@ -13,6 +13,7 @@ import ( "time" "github.com/VictoriaMetrics/VictoriaMetrics/lib/buildinfo" + "github.com/VictoriaMetrics/VictoriaMetrics/lib/stringsutil" "github.com/VictoriaMetrics/metrics" ) @@ -23,6 +24,8 @@ var ( loggerTimezone = flag.String("loggerTimezone", "UTC", "Timezone to use for timestamps in logs. Timezone must be a valid IANA Time Zone. "+ "For example: America/New_York, Europe/Berlin, Etc/GMT+3 or Local") disableTimestamps = flag.Bool("loggerDisableTimestamps", false, "Whether to disable writing timestamps in logs") + maxLogArgLen = flag.Int("loggerMaxArgLen", 500, "The maximum length of a single logged argument. Longer arguments are replaced with 'arg_start..arg_end', "+ + "where 'arg_start' and 'arg_end' is prefix and suffix of the arg with the length not exceeding -loggerMaxArgLen / 2") errorsPerSecondLimit = flag.Int("loggerErrorsPerSecondLimit", 0, `Per-second limit on the number of ERROR messages. If more than the given number of errors are emitted per second, the remaining errors are suppressed. Zero values disable the rate limit`) warnsPerSecondLimit = flag.Int("loggerWarnsPerSecondLimit", 0, `Per-second limit on the number of WARN messages. If more than the given number of warns are emitted per second, then the remaining warns are suppressed. Zero values disable the rate limit`) @@ -134,7 +137,7 @@ func logLevelSkipframes(skipframes int, level, format string, args []interface{} if shouldSkipLog(level) { return } - msg := formatLogMessage(500, format, args) + msg := formatLogMessage(*maxLogArgLen, format, args) logMessage(level, msg, 3+skipframes) } @@ -149,23 +152,12 @@ func formatLogMessage(maxArgLen int, format string, args []interface{}) string { x = x[n+1:] if strings.HasPrefix(x, "s") || strings.HasPrefix(x, "q") { s := fmt.Sprintf("%s", args[i]) - args[i] = limitStringLength(maxArgLen, s) + args[i] = stringsutil.LimitStringLen(s, maxArgLen) } } return fmt.Sprintf(format, args...) } -func limitStringLength(maxLen int, s string) string { - if len(s) <= maxLen { - return s - } - n := (maxLen / 2) - 1 - if n < 0 { - n = 0 - } - return s[:n] + ".." + s[len(s)-n:] -} - func logLimiterCleaner() { for { time.Sleep(time.Second) diff --git a/lib/storage/search.go b/lib/storage/search.go index f5b4ab7f8..9c33cbf68 100644 --- a/lib/storage/search.go +++ b/lib/storage/search.go @@ -10,6 +10,7 @@ import ( "github.com/VictoriaMetrics/VictoriaMetrics/lib/fasttime" "github.com/VictoriaMetrics/VictoriaMetrics/lib/logger" "github.com/VictoriaMetrics/VictoriaMetrics/lib/querytracer" + "github.com/VictoriaMetrics/VictoriaMetrics/lib/stringsutil" ) // BlockRef references a Block. @@ -277,7 +278,7 @@ type TagFilter struct { // String returns string representation of tf. func (tf *TagFilter) String() string { op := tf.getOp() - value := bytesutil.LimitStringLen(string(tf.Value), 60) + value := stringsutil.LimitStringLen(string(tf.Value), 60) if len(tf.Key) == 0 { return fmt.Sprintf("__name__%s%q", op, value) } diff --git a/lib/storage/tag_filters.go b/lib/storage/tag_filters.go index bc7492590..3ef0acc61 100644 --- a/lib/storage/tag_filters.go +++ b/lib/storage/tag_filters.go @@ -16,6 +16,7 @@ import ( "github.com/VictoriaMetrics/VictoriaMetrics/lib/lrucache" "github.com/VictoriaMetrics/VictoriaMetrics/lib/memory" "github.com/VictoriaMetrics/VictoriaMetrics/lib/regexutil" + "github.com/VictoriaMetrics/VictoriaMetrics/lib/stringsutil" ) // convertToCompositeTagFilterss converts tfss to composite filters. @@ -293,7 +294,7 @@ func (tf *tagFilter) Less(other *tagFilter) bool { // String returns human-readable tf value. func (tf *tagFilter) String() string { op := tf.getOp() - value := bytesutil.LimitStringLen(string(tf.value), 60) + value := stringsutil.LimitStringLen(string(tf.value), 60) if bytes.Equal(tf.key, graphiteReverseTagKey) { return fmt.Sprintf("__graphite_reverse__%s%q", op, value) } diff --git a/lib/stringsutil/stringsutil.go b/lib/stringsutil/stringsutil.go new file mode 100644 index 000000000..cd5754cfd --- /dev/null +++ b/lib/stringsutil/stringsutil.go @@ -0,0 +1,16 @@ +package stringsutil + +// LimitStringLen limits the length of s with maxLen. +// +// If len(s) > maxLen, then s is replaced with "s_prefix..s_suffix", +// so the total length of the returned string doesn't exceed maxLen. +func LimitStringLen(s string, maxLen int) string { + if len(s) <= maxLen || maxLen <= 4 { + return s + } + n := (maxLen / 2) - 1 + if n < 0 { + n = 0 + } + return s[:n] + ".." + s[len(s)-n:] +}