fix: stop scrape logger spam, refactor scrape logger design

main.go

@@ -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 from probe requests. One of: [debug, info, warn, error]").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()
@@ -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())
@@ -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")

prober/handler.go

@@ -16,7 +16,6 @@ package prober
 import (
 	"bytes"
 	"context"
-	"errors"
 	"fmt"
 	"log/slog"
 	"net/http"
@@ -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()
@@ -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)
@@ -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
@@ -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)

prober/handler_test.go

@@ -59,7 +59,7 @@ func TestPrometheusTimeoutHTTP(t *testing.T) {
 
 	rr := httptest.NewRecorder()
 	handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		Handler(w, r, c, promslog.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, promslog.NewLevel())
+		Handler(w, r, c, promslog.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, promslog.NewLevel(), promslog.NewLevel())
 	})
 
 	handler.ServeHTTP(rr, req)
@@ -81,7 +81,7 @@ func TestPrometheusConfigSecretsHidden(t *testing.T) {
 	}
 	rr := httptest.NewRecorder()
 	handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		Handler(w, r, c, promslog.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, promslog.NewLevel())
+		Handler(w, r, c, promslog.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, promslog.NewLevel(), promslog.NewLevel())
 	})
 	handler.ServeHTTP(rr, req)
 
@@ -177,7 +177,7 @@ func TestHostnameParam(t *testing.T) {
 	rr := httptest.NewRecorder()
 
 	handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		Handler(w, r, c, promslog.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, promslog.NewLevel())
+		Handler(w, r, c, promslog.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, promslog.NewLevel(), promslog.NewLevel())
 	})
 
 	handler.ServeHTTP(rr, req)
@@ -195,7 +195,7 @@ func TestHostnameParam(t *testing.T) {
 	c.Modules["http_2xx"].HTTP.Headers["Host"] = hostname + ".something"
 
 	handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		Handler(w, r, c, promslog.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, promslog.NewLevel())
+		Handler(w, r, c, promslog.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, promslog.NewLevel(), promslog.NewLevel())
 	})
 
 	rr = httptest.NewRecorder()
@@ -242,7 +242,7 @@ func TestTCPHostnameParam(t *testing.T) {
 	rr := httptest.NewRecorder()
 
 	handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		Handler(w, r, c, promslog.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, promslog.NewLevel())
+		Handler(w, r, c, promslog.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, promslog.NewLevel(), promslog.NewLevel())
 	})
 
 	handler.ServeHTTP(rr, req)