Skip to content

fix: stop scrape logger spam, refactor scrape logger design #1381

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

Merged
electron0zero merged 2 commits into from
May 21, 2025
+162 −41
Merged

fix: stop scrape logger spam, refactor scrape logger design #1381

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
7df3031
fix: stop scrape logger spam, refactor scrape logger design
tjhop May 8, 2025
7dd2222
docs(README): add section on --log.prober behavior with sample output
tjhop May 21, 2025
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
117 changes: 117 additions & 0 deletions README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -50,6 +50,123 @@ using the `--web.config.file` parameter. The format of the file is described
Note that the TLS and basic authentication settings affect all HTTP endpoints:
/metrics for scraping, /probe for probing, and the web UI.

### Controlling log level for probe logs

It is possible to control the level at which probe logs related to a scrape are output as.

Probe logs default to `debug` level, and can be controlled by the `--log.prober` flag.
This means that probe scrape logs will not be output unless the level configured for the probe logger via `--log.prober` is >= the level configured for the blackbox_exporter via `--log.level`.

Sample output demonstrating the use and effect of these flags can be seen below.

> _Note_
>
> All log samples below used the following basic `blackbox.yml` configuration file and contain the probe logs of a single scrape generated by `curl`

```bash
# blackbox.yml
modules:
http_2xx:
prober: http

# generate probe
curl "http://localhost:9115/probe?target=prometheus.io&module=http_2xx"
```

<details>
<summary>Example output with `--log.level=info` and `--log.prober=debug` (default)</summary>

```bash
./blackbox_exporter --config.file ./blackbox.yml --log.level=info --log.prober=debug
time=2025-05-21T04:10:54.131Z level=INFO source=main.go:88 msg="Starting blackbox_exporter" version="(version=0.26.0, branch=fix/scrape-logger-spam, revision=7df3031feecba82f1a534336979b4e5920f79b72)"
time=2025-05-21T04:10:54.131Z level=INFO source=main.go:89 msg="(go=go1.24.1, platform=linux/amd64, user=tjhop@contraband, date=20250521-04:00:25, tags=unknown)"
time=2025-05-21T04:10:54.132Z level=INFO source=main.go:101 msg="Loaded config file"
time=2025-05-21T04:10:54.133Z level=INFO source=tls_config.go:347 msg="Listening on" address=[::]:9115
time=2025-05-21T04:10:54.133Z level=INFO source=tls_config.go:350 msg="TLS is disabled." http2=false address=[::]:9115
^Ctime=2025-05-21T04:11:03.619Z level=INFO source=main.go:283 msg="Received SIGTERM, exiting gracefully..."
```
</details>

<details>
<summary>Example output with `--log.level=info` and `--log.prober=info`</summary>

```bash
./blackbox_exporter --config.file ./blackbox.yml --log.level=info --log.prober=info
time=2025-05-21T04:12:09.884Z level=INFO source=main.go:88 msg="Starting blackbox_exporter" version="(version=0.26.0, branch=fix/scrape-logger-spam, revision=7df3031feecba82f1a534336979b4e5920f79b72)"
time=2025-05-21T04:12:09.884Z level=INFO source=main.go:89 msg="(go=go1.24.1, platform=linux/amd64, user=tjhop@contraband, date=20250521-04:00:25, tags=unknown)"
time=2025-05-21T04:12:09.884Z level=INFO source=main.go:101 msg="Loaded config file"
time=2025-05-21T04:12:09.885Z level=INFO source=tls_config.go:347 msg="Listening on" address=[::]:9115
time=2025-05-21T04:12:09.885Z level=INFO source=tls_config.go:350 msg="TLS is disabled." http2=false address=[::]:9115
time=2025-05-21T04:12:13.827Z level=INFO source=handler.go:194 msg="Beginning probe" module=http_2xx target=prometheus.io probe=http timeout_seconds=119.5
time=2025-05-21T04:12:13.827Z level=INFO source=handler.go:194 msg="Resolving target address" module=http_2xx target=prometheus.io target=prometheus.io ip_protocol=ip4
time=2025-05-21T04:12:13.829Z level=INFO source=handler.go:194 msg="Resolved target address" module=http_2xx target=prometheus.io target=prometheus.io ip=172.67.201.240
time=2025-05-21T04:12:13.829Z level=INFO source=handler.go:194 msg="Making HTTP request" module=http_2xx target=prometheus.io url=http://172.67.201.240 host=prometheus.io
time=2025-05-21T04:12:13.860Z level=INFO source=handler.go:194 msg="Received redirect" module=http_2xx target=prometheus.io location=https://prometheus.io/
time=2025-05-21T04:12:13.860Z level=INFO source=handler.go:194 msg="Making HTTP request" module=http_2xx target=prometheus.io url=https://prometheus.io/ host=""
time=2025-05-21T04:12:13.860Z level=INFO source=handler.go:194 msg="Address does not match first address, not sending TLS ServerName" module=http_2xx target=prometheus.io first=172.67.201.240 address=prometheus.io
time=2025-05-21T04:12:13.974Z level=INFO source=handler.go:194 msg="Received HTTP response" module=http_2xx target=prometheus.io status_code=200
time=2025-05-21T04:12:13.974Z level=INFO source=handler.go:194 msg="Response timings for roundtrip" module=http_2xx target=prometheus.io roundtrip=0 start=2025-05-21T00:12:13.829-04:00 dnsDone=2025-05-21T00:12:13.829-04:00 connectDone=2025-05-21T00:12:13.839-04:00 gotConn=2025-05-21T00:12:13.839-04:00 responseStart=2025-05-21T00:12:13.860-04:00 tlsStart=0001-01-01T00:00:00.000Z tlsDone=0001-01-01T00:00:00.000Z end=0001-01-01T00:00:00.000Z
time=2025-05-21T04:12:13.974Z level=INFO source=handler.go:194 msg="Response timings for roundtrip" module=http_2xx target=prometheus.io roundtrip=1 start=2025-05-21T00:12:13.860-04:00 dnsDone=2025-05-21T00:12:13.861-04:00 connectDone=2025-05-21T00:12:13.869-04:00 gotConn=2025-05-21T00:12:13.925-04:00 responseStart=2025-05-21T00:12:13.974-04:00 tlsStart=2025-05-21T00:12:13.869-04:00 tlsDone=2025-05-21T00:12:13.925-04:00 end=2025-05-21T00:12:13.974-04:00
time=2025-05-21T04:12:13.974Z level=INFO source=handler.go:194 msg="Probe succeeded" module=http_2xx target=prometheus.io duration_seconds=0.14708839
^Ctime=2025-05-21T04:12:17.818Z level=INFO source=main.go:283 msg="Received SIGTERM, exiting gracefully..."
```
</details>

<details>
<summary>Example output with `--log.level=debug` and `--log.prober=info`</summary>

```bash
./blackbox_exporter --config.file ./blackbox.yml --log.level=debug --log.prober=info
time=2025-05-21T04:13:18.497Z level=INFO source=main.go:88 msg="Starting blackbox_exporter" version="(version=0.26.0, branch=fix/scrape-logger-spam, revision=7df3031feecba82f1a534336979b4e5920f79b72)"
time=2025-05-21T04:13:18.497Z level=INFO source=main.go:89 msg="(go=go1.24.1, platform=linux/amd64, user=tjhop@contraband, date=20250521-04:00:25, tags=unknown)"
time=2025-05-21T04:13:18.497Z level=INFO source=main.go:101 msg="Loaded config file"
time=2025-05-21T04:13:18.498Z level=DEBUG source=main.go:116 msg=http://contraband:9115
time=2025-05-21T04:13:18.498Z level=DEBUG source=main.go:130 msg=/
time=2025-05-21T04:13:18.498Z level=INFO source=tls_config.go:347 msg="Listening on" address=[::]:9115
time=2025-05-21T04:13:18.498Z level=INFO source=tls_config.go:350 msg="TLS is disabled." http2=false address=[::]:9115
time=2025-05-21T04:13:23.169Z level=INFO source=handler.go:194 msg="Beginning probe" module=http_2xx target=prometheus.io probe=http timeout_seconds=119.5
time=2025-05-21T04:13:23.169Z level=INFO source=handler.go:194 msg="Resolving target address" module=http_2xx target=prometheus.io target=prometheus.io ip_protocol=ip4
time=2025-05-21T04:13:23.170Z level=INFO source=handler.go:194 msg="Resolved target address" module=http_2xx target=prometheus.io target=prometheus.io ip=104.21.60.220
time=2025-05-21T04:13:23.170Z level=INFO source=handler.go:194 msg="Making HTTP request" module=http_2xx target=prometheus.io url=http://104.21.60.220 host=prometheus.io
time=2025-05-21T04:13:23.202Z level=INFO source=handler.go:194 msg="Received redirect" module=http_2xx target=prometheus.io location=https://prometheus.io/
time=2025-05-21T04:13:23.202Z level=INFO source=handler.go:194 msg="Making HTTP request" module=http_2xx target=prometheus.io url=https://prometheus.io/ host=""
time=2025-05-21T04:13:23.202Z level=INFO source=handler.go:194 msg="Address does not match first address, not sending TLS ServerName" module=http_2xx target=prometheus.io first=104.21.60.220 address=prometheus.io
time=2025-05-21T04:13:23.316Z level=INFO source=handler.go:194 msg="Received HTTP response" module=http_2xx target=prometheus.io status_code=200
time=2025-05-21T04:13:23.319Z level=INFO source=handler.go:194 msg="Response timings for roundtrip" module=http_2xx target=prometheus.io roundtrip=0 start=2025-05-21T00:13:23.171-04:00 dnsDone=2025-05-21T00:13:23.171-04:00 connectDone=2025-05-21T00:13:23.181-04:00 gotConn=2025-05-21T00:13:23.181-04:00 responseStart=2025-05-21T00:13:23.201-04:00 tlsStart=0001-01-01T00:00:00.000Z tlsDone=0001-01-01T00:00:00.000Z end=0001-01-01T00:00:00.000Z
time=2025-05-21T04:13:23.319Z level=INFO source=handler.go:194 msg="Response timings for roundtrip" module=http_2xx target=prometheus.io roundtrip=1 start=2025-05-21T00:13:23.202-04:00 dnsDone=2025-05-21T00:13:23.203-04:00 connectDone=2025-05-21T00:13:23.212-04:00 gotConn=2025-05-21T00:13:23.268-04:00 responseStart=2025-05-21T00:13:23.316-04:00 tlsStart=2025-05-21T00:13:23.212-04:00 tlsDone=2025-05-21T00:13:23.268-04:00 end=2025-05-21T00:13:23.319-04:00
time=2025-05-21T04:13:23.319Z level=INFO source=handler.go:194 msg="Probe succeeded" module=http_2xx target=prometheus.io duration_seconds=0.150580389
^Ctime=2025-05-21T04:13:27.945Z level=INFO source=main.go:283 msg="Received SIGTERM, exiting gracefully..."
```
</details>


<details>
<summary>Example output with `--log.level=debug` and `--log.prober=debug`</summary>

```bash
./blackbox_exporter --config.file ./blackbox.yml --log.level=debug --log.prober=debug
time=2025-05-21T04:14:55.621Z level=INFO source=main.go:88 msg="Starting blackbox_exporter" version="(version=0.26.0, branch=fix/scrape-logger-spam, revision=7df3031feecba82f1a534336979b4e5920f79b72)"
time=2025-05-21T04:14:55.621Z level=INFO source=main.go:89 msg="(go=go1.24.1, platform=linux/amd64, user=tjhop@contraband, date=20250521-04:00:25, tags=unknown)"
time=2025-05-21T04:14:55.622Z level=INFO source=main.go:101 msg="Loaded config file"
time=2025-05-21T04:14:55.622Z level=DEBUG source=main.go:116 msg=http://contraband:9115
time=2025-05-21T04:14:55.622Z level=DEBUG source=main.go:130 msg=/
time=2025-05-21T04:14:55.623Z level=INFO source=tls_config.go:347 msg="Listening on" address=[::]:9115
time=2025-05-21T04:14:55.623Z level=INFO source=tls_config.go:350 msg="TLS is disabled." http2=false address=[::]:9115
time=2025-05-21T04:15:03.048Z level=DEBUG source=handler.go:194 msg="Beginning probe" module=http_2xx target=prometheus.io probe=http timeout_seconds=119.5
time=2025-05-21T04:15:03.049Z level=DEBUG source=handler.go:194 msg="Resolving target address" module=http_2xx target=prometheus.io target=prometheus.io ip_protocol=ip4
time=2025-05-21T04:15:03.050Z level=DEBUG source=handler.go:194 msg="Resolved target address" module=http_2xx target=prometheus.io target=prometheus.io ip=172.67.201.240
time=2025-05-21T04:15:03.050Z level=DEBUG source=handler.go:194 msg="Making HTTP request" module=http_2xx target=prometheus.io url=http://172.67.201.240 host=prometheus.io
time=2025-05-21T04:15:03.089Z level=DEBUG source=handler.go:194 msg="Received redirect" module=http_2xx target=prometheus.io location=https://prometheus.io/
time=2025-05-21T04:15:03.089Z level=DEBUG source=handler.go:194 msg="Making HTTP request" module=http_2xx target=prometheus.io url=https://prometheus.io/ host=""
time=2025-05-21T04:15:03.089Z level=DEBUG source=handler.go:194 msg="Address does not match first address, not sending TLS ServerName" module=http_2xx target=prometheus.io first=172.67.201.240 address=prometheus.io
time=2025-05-21T04:15:03.211Z level=DEBUG source=handler.go:194 msg="Received HTTP response" module=http_2xx target=prometheus.io status_code=200
time=2025-05-21T04:15:03.212Z level=DEBUG source=handler.go:194 msg="Response timings for roundtrip" module=http_2xx target=prometheus.io roundtrip=0 start=2025-05-21T00:15:03.050-04:00 dnsDone=2025-05-21T00:15:03.050-04:00 connectDone=2025-05-21T00:15:03.061-04:00 gotConn=2025-05-21T00:15:03.061-04:00 responseStart=2025-05-21T00:15:03.089-04:00 tlsStart=0001-01-01T00:00:00.000Z tlsDone=0001-01-01T00:00:00.000Z end=0001-01-01T00:00:00.000Z
time=2025-05-21T04:15:03.212Z level=DEBUG source=handler.go:194 msg="Response timings for roundtrip" module=http_2xx target=prometheus.io roundtrip=1 start=2025-05-21T00:15:03.089-04:00 dnsDone=2025-05-21T00:15:03.090-04:00 connectDone=2025-05-21T00:15:03.102-04:00 gotConn=2025-05-21T00:15:03.163-04:00 responseStart=2025-05-21T00:15:03.211-04:00 tlsStart=2025-05-21T00:15:03.102-04:00 tlsDone=2025-05-21T00:15:03.163-04:00 end=2025-05-21T00:15:03.212-04:00
time=2025-05-21T04:15:03.212Z level=DEBUG source=handler.go:194 msg="Probe succeeded" module=http_2xx target=prometheus.io duration_seconds=0.163695815
^Ctime=2025-05-21T04:15:07.862Z level=INFO source=main.go:283 msg="Received SIGTERM, exiting gracefully..."
```
</details>

## Building the software

### Local Build
Expand Down
10 changes: 6 additions & 4 deletions main.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -50,7 +50,7 @@ var (
configFile = kingpin.Flag("config.file", "Blackbox exporter configuration file.").Default("blackbox.yml").String()
timeoutOffset = kingpin.Flag("timeout-offset", "Offset to subtract from timeout in seconds.").Default("0.5").Float64()
configCheck = kingpin.Flag("config.check", "If true validate the config file and then exit.").Default().Bool()
logLevelProber = kingpin.Flag("log.prober", "Log level from probe requests. One of: [debug, info, warn, error]").Default("info").String()
logLevelProber = kingpin.Flag("log.prober", "Log level for probe request logs. One of: [debug, info, warn, error]. Defaults to debug. Please see the section `Controlling log level for probe logs` in the project README for more information.").Default("debug").String()
historyLimit = kingpin.Flag("history.limit", "The maximum amount of items to keep in the history.").Default("100").Uint()
externalURL = kingpin.Flag("web.external-url", "The URL under which Blackbox exporter is externally reachable (for example, if Blackbox exporter is served via a reverse proxy). Used for generating relative and absolute links back to Blackbox exporter itself. If the URL has a path portion, it will be used to prefix all HTTP endpoints served by Blackbox exporter. If omitted, relevant URL components will be derived automatically.").PlaceHolder("<url>").String()
routePrefix = kingpin.Flag("web.route-prefix", "Prefix for the internal routes of web endpoints. Defaults to path of --web.external-url.").PlaceHolder("<path>").String()
Expand Down Expand Up @@ -80,8 +80,10 @@ func run() int {
logger := promslog.New(promslogConfig)
rh := &prober.ResultHistory{MaxResults: *historyLimit}

allowedLevel := promslog.NewLevel()
_ = allowedLevel.Set(*logLevelProber)
probeLogLevel := promslog.NewLevel()
if err := probeLogLevel.Set(*logLevelProber); err != nil {
logger.Warn("Error setting log prober level, log prober level unchanged", "err", err, "current_level", probeLogLevel.String())
}

logger.Info("Starting blackbox_exporter", "version", version.Info())
logger.Info(version.BuildContext())
Expand Down Expand Up @@ -186,7 +188,7 @@ func run() int {
sc.Lock()
conf := sc.C
sc.Unlock()
prober.Handler(w, r, conf, logger, rh, *timeoutOffset, nil, moduleUnknownCounter, allowedLevel)
prober.Handler(w, r, conf, logger, rh, *timeoutOffset, nil, moduleUnknownCounter, promslogConfig.Level, probeLogLevel)
})
http.HandleFunc(*routePrefix, func(w http.ResponseWriter, r *http.Request) {
w.Header().Set("Content-Type", "text/html")
Expand Down
66 changes: 34 additions & 32 deletions prober/handler.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -16,7 +16,6 @@ package prober
import (
"bytes"
"context"
"errors"
"fmt"
"log/slog"
"net/http"
Expand Down Expand Up @@ -45,7 +44,7 @@ var (

func Handler(w http.ResponseWriter, r *http.Request, c *config.Config, logger *slog.Logger, rh *ResultHistory, timeoutOffset float64, params url.Values,
moduleUnknownCounter prometheus.Counter,
logLevelProber *promslog.Level) {
logLevel, logLevelProber *promslog.Level) {

if params == nil {
params = r.URL.Query()
Expand Down Expand Up @@ -110,13 +109,7 @@ func Handler(w http.ResponseWriter, r *http.Request, c *config.Config, logger *s
}
}

if logLevelProber == nil {
logLevelProber = promslog.NewLevel()
}
if logLevelProber.String() == "" {
_ = logLevelProber.Set("info")
}
sl := newScrapeLogger(logger, moduleName, target, logLevelProber)
sl := newScrapeLogger(logger, moduleName, target, logLevel, logLevelProber)
slLogger := slog.New(sl)

slLogger.Info("Beginning probe", "probe", module.Prober, "timeout_seconds", timeoutSeconds)
Expand Down Expand Up @@ -166,10 +159,10 @@ func setHTTPHost(hostname string, module *config.Module) error {
}

type scrapeLogger struct {
next *slog.Logger
buffer bytes.Buffer
bufferLogger *slog.Logger
logLevel *promslog.Level
next *slog.Logger
buffer bytes.Buffer
bufferLogger *slog.Logger
logLevelProber *promslog.Level
}

// Enabled returns true if both A) the scrapeLogger's internal `next` logger
Expand All @@ -187,44 +180,53 @@ func (sl *scrapeLogger) Enabled(ctx context.Context, level slog.Level) bool {
// the internal bufferLogger for use with serving debug output. It implements
// slog.Handler.
func (sl *scrapeLogger) Handle(ctx context.Context, r slog.Record) error {
var errs []error
level := getSlogLevel(sl.logLevelProber.String())

// Collect attributes from record so we can log them directly. We
// hijack log calls to the scrapeLogger and override the level from the
// original log call with the level set via the `--log.prober` flag.
attrs := make([]slog.Attr, r.NumAttrs())
r.Attrs(func(a slog.Attr) bool {
attrs = append(attrs, a)
return true
})

errs = append(errs, sl.next.Handler().Handle(ctx, r.Clone()))
sl.next.LogAttrs(ctx, level, r.Message, attrs...)
sl.bufferLogger.LogAttrs(ctx, level, r.Message, attrs...)

if sl.bufferLogger.Enabled(context.Background(), getSlogLevel(sl.logLevel.String())) {
errs = append(errs, sl.bufferLogger.Handler().Handle(ctx, r.Clone()))
}

return errors.Join(errs...)
return nil
}

// WithAttrs adds the provided attributes to the scrapeLogger's internal logger and
// bufferLogger. It implements slog.Handler.
func (sl *scrapeLogger) WithAttrs(attrs []slog.Attr) slog.Handler {
return &scrapeLogger{
next: slog.New(sl.next.Handler().WithAttrs(attrs)),
buffer: sl.buffer,
bufferLogger: slog.New(sl.bufferLogger.Handler().WithAttrs(attrs)),
logLevel: sl.logLevel,
next: slog.New(sl.next.Handler().WithAttrs(attrs)),
buffer: sl.buffer,
bufferLogger: slog.New(sl.bufferLogger.Handler().WithAttrs(attrs)),
logLevelProber: sl.logLevelProber,
}
}

// WithGroup adds the provided group name to the scrapeLogger's internal logger
// and bufferLogger. It implements slog.Handler.
func (sl *scrapeLogger) WithGroup(name string) slog.Handler {
return &scrapeLogger{
next: slog.New(sl.next.Handler().WithGroup(name)),
buffer: sl.buffer,
bufferLogger: slog.New(sl.bufferLogger.Handler().WithGroup(name)),
logLevel: sl.logLevel,
next: slog.New(sl.next.Handler().WithGroup(name)),
buffer: sl.buffer,
bufferLogger: slog.New(sl.bufferLogger.Handler().WithGroup(name)),
logLevelProber: sl.logLevelProber,
}
}

func newScrapeLogger(logger *slog.Logger, module string, target string, logLevel *promslog.Level) *scrapeLogger {
func newScrapeLogger(logger *slog.Logger, module string, target string, logLevel, logLevelProber *promslog.Level) *scrapeLogger {
if logLevelProber == nil {
logLevelProber = promslog.NewLevel()
}
sl := &scrapeLogger{
next: logger.With("module", module, "target", target),
buffer: bytes.Buffer{},
logLevel: logLevel,
next: logger.With("module", module, "target", target),
buffer: bytes.Buffer{},
logLevelProber: logLevelProber,
}
bl := promslog.New(&promslog.Config{Writer: &sl.buffer, Level: logLevel})
sl.bufferLogger = bl.With("module", module, "target", target)
Expand Down
Loading