feat: de-couple --log.prober to be an independent logger

CHANGELOG.md

@@ -2,6 +2,9 @@
 
 BREAKING CHANGES:
 
+* The `--log.prober` flag behavior has changed. The scrape probe logger is now an independent logger. Please review the README.md and adjust configurations as needed. #1461
+* Log leveling has been improved for several prober modules. Changes include logging errors at `ERROR` level instead of `INFO`, and adjusting many prober logs from `INFO` to `DEBUG` level. To see more detailed probe logs, set `--log.prober=debug`. #1461
+
 Changes:
 
 * [CHANGE]

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 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()
+	logLevelProber = kingpin.Flag("log.prober", "Log level for probe request logs. One of: [debug, info, warn, error]. Please see the section `Controlling log level for probe logs` in the project README for more information.").Default("info").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()
@@ -85,6 +85,13 @@ func run() int {
 		logger.Warn("Error setting log prober level, log prober level unchanged", "err", err, "current_level", probeLogLevel.String())
 	}
 
+	scrapeLoggerConfig := &promslog.Config{
+		Level:  probeLogLevel,
+		Writer: promslogConfig.Writer,
+		Format: promslogConfig.Format,
+		Style:  promslogConfig.Style,
+	}
+
 	logger.Info("Starting blackbox_exporter", "version", version.Info())
 	logger.Info(version.BuildContext())
 
@@ -188,7 +195,7 @@ func run() int {
 		sc.Lock()
 		conf := sc.C
 		sc.Unlock()
-		prober.Handler(w, r, conf, logger, rh, *timeoutOffset, nil, moduleUnknownCounter, promslogConfig.Level, probeLogLevel)
+		prober.Handler(w, r, conf, logger, rh, *timeoutOffset, nil, moduleUnknownCounter, scrapeLoggerConfig)
 	})
 	http.HandleFunc(*routePrefix, func(w http.ResponseWriter, r *http.Request) {
 		w.Header().Set("Content-Type", "text/html")

prober/dns.go

@@ -42,7 +42,7 @@ func validRRs(rrs *[]dns.RR, v *config.DNSRRValidator, logger *slog.Logger) bool
 		return false
 	}
 	for _, rr := range *rrs {
-		logger.Info("Validating RR", "rr", rr)
+		logger.Debug("Validating RR", "rr", rr)
 		for _, re := range v.FailIfMatchesRegexp {
 			match, err := regexp.MatchString(re, rr.String())
 			if err != nil {
@@ -115,7 +115,7 @@ func validRcode(rcode int, valid []string, logger *slog.Logger) bool {
 	}
 	for _, rc := range validRcodes {
 		if rcode == rc {
-			logger.Info("Rcode is valid", "rcode", rcode, "string_rcode", dns.RcodeToString[rcode])
+			logger.Debug("Rcode is valid", "rcode", rcode, "string_rcode", dns.RcodeToString[rcode])
 			return true
 		}
 	}
@@ -243,7 +243,7 @@ func ProbeDNS(ctx context.Context, target string, module config.Module, registry
 			logger.Error("Error parsing source ip address", "srcIP", module.DNS.SourceIPAddress)
 			return false
 		}
-		logger.Info("Using local address", "srcIP", srcIP)
+		logger.Debug("Using local address", "srcIP", srcIP)
 		client.Dialer = &net.Dialer{}
 		if module.DNS.TransportProtocol == "tcp" {
 			client.Dialer.LocalAddr = &net.TCPAddr{IP: srcIP}
@@ -258,7 +258,7 @@ func ProbeDNS(ctx context.Context, target string, module config.Module, registry
 	msg.Question = make([]dns.Question, 1)
 	msg.Question[0] = dns.Question{dns.Fqdn(module.DNS.QueryName), qt, qc}
 
-	logger.Info("Making DNS query", "target", targetIP, "dial_protocol", dialProtocol, "query", module.DNS.QueryName, "type", qt, "class", qc)
+	logger.Debug("Making DNS query", "target", targetIP, "dial_protocol", dialProtocol, "query", module.DNS.QueryName, "type", qt, "class", qc)
 	timeoutDeadline, _ := ctx.Deadline()
 	client.Timeout = time.Until(timeoutDeadline)
 	requestStart := time.Now()
@@ -273,7 +273,7 @@ func ProbeDNS(ctx context.Context, target string, module config.Module, registry
 		logger.Error("Error while sending a DNS query", "err", err)
 		return false
 	}
-	logger.Info("Got response", "response", response)
+	logger.Debug("Got response", "response", response)
 
 	probeDNSAnswerRRSGauge.Set(float64(len(response.Answer)))
 	probeDNSAuthorityRRSGauge.Set(float64(len(response.Ns)))
@@ -297,17 +297,17 @@ func ProbeDNS(ctx context.Context, target string, module config.Module, registry
 	if !validRcode(response.Rcode, module.DNS.ValidRcodes, logger) {
 		return false
 	}
-	logger.Info("Validating Answer RRs")
+	logger.Debug("Validating Answer RRs")
 	if !validRRs(&response.Answer, &module.DNS.ValidateAnswer, logger) {
 		logger.Error("Answer RRs validation failed")
 		return false
 	}
-	logger.Info("Validating Authority RRs")
+	logger.Debug("Validating Authority RRs")
 	if !validRRs(&response.Ns, &module.DNS.ValidateAuthority, logger) {
 		logger.Error("Authority RRs validation failed")
 		return false
 	}
-	logger.Info("Validating Additional RRs")
+	logger.Debug("Validating Additional RRs")
 	if !validRRs(&response.Extra, &module.DNS.ValidateAdditional, logger) {
 		logger.Error("Additional RRs validation failed")
 		return false

prober/handler.go

@@ -45,7 +45,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,
-	logLevel, logLevelProber *promslog.Level) {
+	promslogConfig *promslog.Config) {
 
 	if params == nil {
 		params = r.URL.Query()
@@ -110,10 +110,10 @@ func Handler(w http.ResponseWriter, r *http.Request, c *config.Config, logger *s
 		}
 	}
 
-	sl := newScrapeLogger(logger, moduleName, target, logLevel, logLevelProber)
+	sl := newScrapeLogger(promslogConfig, moduleName, target)
 	slLogger := slog.New(sl)
 
-	slLogger.Info("Beginning probe", "probe", module.Prober, "timeout_seconds", timeoutSeconds)
+	slLogger.Debug("Beginning probe", "probe", module.Prober, "timeout_seconds", timeoutSeconds)
 
 	start := time.Now()
 	registry := prometheus.NewRegistry()
@@ -124,12 +124,12 @@ func Handler(w http.ResponseWriter, r *http.Request, c *config.Config, logger *s
 	probeDurationGauge.Set(duration)
 	if success {
 		probeSuccessGauge.Set(1)
-		slLogger.Info("Probe succeeded", "duration_seconds", duration)
+		slLogger.Debug("Probe succeeded", "duration_seconds", duration)
 	} else {
 		slLogger.Error("Probe failed", "duration_seconds", duration)
 	}
 
-	debugOutput := DebugOutput(&module, &sl.buffer, registry)
+	debugOutput := DebugOutput(&module, sl.buffer, registry)
 	rh.Add(moduleName, target, debugOutput, success)
 
 	if r.URL.Query().Get("debug") == "true" {
@@ -160,10 +160,10 @@ func setHTTPHost(hostname string, module *config.Module) error {
 }
 
 type scrapeLogger struct {
-	next           *slog.Logger
-	buffer         bytes.Buffer
-	bufferLogger   *slog.Logger
-	logLevelProber *promslog.Level
+	next         *slog.Logger
+	buffer       *bytes.Buffer
+	bufferLogger *slog.Logger
+	config       *promslog.Config
 }
 
 // Enabled returns true if both A) the scrapeLogger's internal `next` logger
@@ -181,17 +181,12 @@ 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 {
-	level := getSlogLevel(sl.logLevelProber.String())
 	var errs []error
-	// Clone record so we can override the level. 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.
 	rec := r.Clone()
-	rec.Level = level
 
 	// Scrape logger should only write to next, the "real" logger, if next
 	// is enabled to write at the level the `--log.prober` flag is set to.
-	if sl.next.Enabled(context.Background(), level) {
+	if sl.next.Enabled(context.Background(), sl.config.Level.Level()) {
 		errs = append(errs, sl.next.Handler().Handle(ctx, rec))
 	}
 
@@ -206,53 +201,47 @@ func (sl *scrapeLogger) Handle(ctx context.Context, r slog.Record) error {
 // 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)),
-		logLevelProber: sl.logLevelProber,
+		next:         slog.New(sl.next.Handler().WithAttrs(attrs)),
+		buffer:       sl.buffer,
+		bufferLogger: slog.New(sl.bufferLogger.Handler().WithAttrs(attrs)),
+		config:       sl.config,
 	}
 }
 
 // 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)),
-		logLevelProber: sl.logLevelProber,
+		next:         slog.New(sl.next.Handler().WithGroup(name)),
+		buffer:       sl.buffer,
+		bufferLogger: slog.New(sl.bufferLogger.Handler().WithGroup(name)),
+		config:       sl.config,
 	}
 }
 
-func newScrapeLogger(logger *slog.Logger, module string, target string, logLevel, logLevelProber *promslog.Level) *scrapeLogger {
-	if logLevelProber == nil {
-		logLevelProber = promslog.NewLevel()
-	}
+func newScrapeLogger(config *promslog.Config, module string, target string) *scrapeLogger {
+	// The base logger that will write to stderr like usual.
+	l := promslog.New(config)
+
+	// The buffer logger, which uses the same promslog.Config and writes to
+	// a bytes.Buffer for retrieval when using the `debug` URL param.
+	var buf bytes.Buffer
+	bl := promslog.New(&promslog.Config{
+		Writer: &buf,
+		Level:  config.Level,
+		Format: config.Format,
+		Style:  config.Style,
+	})
+
 	sl := &scrapeLogger{
-		next:           logger.With("module", module, "target", target),
-		buffer:         bytes.Buffer{},
-		logLevelProber: logLevelProber,
+		next:         l.With("module", module, "target", target),
+		buffer:       &buf,
+		bufferLogger: bl.With("module", module, "target", target),
+		config:       config,
 	}
-	bl := promslog.New(&promslog.Config{Writer: &sl.buffer, Level: logLevel})
-	sl.bufferLogger = bl.With("module", module, "target", target)
 	return sl
 }
 
-func getSlogLevel(level string) slog.Level {
-	switch level {
-	case "info":
-		return slog.LevelInfo
-	case "debug":
-		return slog.LevelDebug
-	case "error":
-		return slog.LevelError
-	case "warn":
-		return slog.LevelWarn
-	default:
-		return slog.LevelInfo
-	}
-}
-
 // DebugOutput returns plaintext debug output for a probe.
 func DebugOutput(module *config.Module, logBuffer *bytes.Buffer, registry *prometheus.Registry) string {
 	buf := &bytes.Buffer{}

prober/handler_test.go

@@ -16,6 +16,7 @@ package prober
 import (
 	"bytes"
 	"fmt"
+	"log/slog"
 	"net"
 	"net/http"
 	"net/http/httptest"
@@ -59,7 +60,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(), promslog.NewLevel())
+		Handler(w, r, c, promslog.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, &promslog.Config{})
 	})
 
 	handler.ServeHTTP(rr, req)
@@ -81,7 +82,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(), promslog.NewLevel())
+		Handler(w, r, c, promslog.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, &promslog.Config{})
 	})
 	handler.ServeHTTP(rr, req)
 
@@ -106,6 +107,52 @@ func TestDebugOutputSecretsHidden(t *testing.T) {
 	}
 }
 
+func TestDebugOutputScrapeLoggerLevels(t *testing.T) {
+	var tests = map[string]struct {
+		level         string
+		debugCheck    string
+		infoCheck     string
+		debugExpected bool
+	}{
+		"info_level":  {level: "info", debugCheck: "level=DEBUG", infoCheck: "level=INFO", debugExpected: false},
+		"debug_level": {level: "debug", debugCheck: "level=DEBUG", infoCheck: "level=INFO", debugExpected: true},
+	}
+
+	for name, tc := range tests {
+		t.Run(name, func(t *testing.T) {
+			lvl := promslog.NewLevel()
+			lvl.Set(tc.level)
+			var buf bytes.Buffer
+			c := &promslog.Config{
+				Level:  lvl,
+				Writer: &buf,
+			}
+
+			sl := newScrapeLogger(c, "http_2xx", "prometheus.io")
+			slLogger := slog.New(sl)
+			slLogger.Info("info test")
+			slLogger.Debug("debug test")
+			out := buf.String()
+
+			// Info log should always be present.
+			if !strings.Contains(out, tc.infoCheck) {
+				t.Errorf("Expected info level log, but none found. Logs: %s\n", out)
+			}
+
+			// Debug log should only be present if debug is enabled.
+			if tc.debugExpected {
+				if !strings.Contains(out, tc.debugCheck) {
+					t.Errorf("Expected debug level log, but none found. Logs: %s\n", out)
+				}
+			} else {
+				if strings.Contains(out, tc.debugCheck) {
+					t.Errorf("Expected no debug level log, but a debug level entry was found. Logs: %s\n", out)
+				}
+			}
+		})
+	}
+}
+
 func TestTimeoutIsSetCorrectly(t *testing.T) {
 	var tests = []struct {
 		inModuleTimeout     time.Duration
@@ -177,7 +224,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(), promslog.NewLevel())
+		Handler(w, r, c, promslog.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, &promslog.Config{})
 	})
 
 	handler.ServeHTTP(rr, req)
@@ -195,7 +242,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(), promslog.NewLevel())
+		Handler(w, r, c, promslog.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, &promslog.Config{})
 	})
 
 	rr = httptest.NewRecorder()
@@ -242,7 +289,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(), promslog.NewLevel())
+		Handler(w, r, c, promslog.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, &promslog.Config{})
 	})
 
 	handler.ServeHTTP(rr, req)