Repository: prometheus/blackbox_exporter
Pull request #1091 (2023-07-01 20:47:41)

Log errors from probe
This PR adds a flag `--log.prober` which can be one of: [debug, info, warn, error, none] to investigate probe failures port-mortem. this flag defaults to none.

At the moment, this analyse problems is only possible via Web UI with an large enough history. Access the unprotected web ui can be difficult and the probe history is only available until restart.

jkroepke: @electron0zero Could you please also take a look here?
jkroepke: @electron0zero @roidelapluie or @mem How we can proceed here?
electron0zero: assuming that there are no comments or feedback from other maintainers, I am going to go ahead and merge it.

Patch:
diff --git a/main.go b/main.go
index 2699b6f..0d113b4 100644
--- a/main.go
+++ b/main.go
@@ -47,13 +47,14 @@ import (
 var (
 	sc = config.NewSafeConfig(prometheus.DefaultRegisterer)
 
-	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()
-	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()
-	toolkitFlags  = webflag.AddFlags(kingpin.CommandLine, ":9115")
+	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, none]").Default("none").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()
+	toolkitFlags   = webflag.AddFlags(kingpin.CommandLine, ":9115")
 
 	moduleUnknownCounter = promauto.NewCounter(prometheus.CounterOpts{
 		Name: "blackbox_module_unknown_total",
@@ -79,6 +80,9 @@ func run() int {
 	logger := promlog.New(promlogConfig)
 	rh := &prober.ResultHistory{MaxResults: *historyLimit}
 
+	logLevelProberValue, _ := level.Parse(*logLevelProber)
+	logLevelProber := level.Allow(logLevelProberValue)
+
 	level.Info(logger).Log("msg", "Starting blackbox_exporter", "version", version.Info())
 	level.Info(logger).Log("build_context", version.BuildContext())
 
@@ -182,7 +186,7 @@ func run() int {
 		sc.Lock()
 		conf := sc.C
 		sc.Unlock()
-		prober.Handler(w, r, conf, logger, rh, *timeoutOffset, nil, moduleUnknownCounter)
+		prober.Handler(w, r, conf, logger, rh, *timeoutOffset, nil, moduleUnknownCounter, logLevelProber)
 	})
 	http.HandleFunc(*routePrefix, func(w http.ResponseWriter, r *http.Request) {
 		w.Header().Set("Content-Type", "text/html")
diff --git a/prober/handler.go b/prober/handler.go
index 1caa2f9..180a076 100644
--- a/prober/handler.go
+++ b/prober/handler.go
@@ -42,8 +42,9 @@ var (
 	}
 )
 
-func Handler(w http.ResponseWriter, r *http.Request, c *config.Config, logger log.Logger,
-	rh *ResultHistory, timeoutOffset float64, params url.Values, moduleUnknownCounter prometheus.Counter) {
+func Handler(w http.ResponseWriter, r *http.Request, c *config.Config, logger log.Logger, rh *ResultHistory, timeoutOffset float64, params url.Values,
+	moduleUnknownCounter prometheus.Counter,
+	logLevelProber level.Option) {
 
 	if params == nil {
 		params = r.URL.Query()
@@ -108,7 +109,7 @@ func Handler(w http.ResponseWriter, r *http.Request, c *config.Config, logger lo
 		}
 	}
 
-	sl := newScrapeLogger(logger, moduleName, target)
+	sl := newScrapeLogger(logger, moduleName, target, logLevelProber)
 	level.Info(sl).Log("msg", "Beginning probe", "probe", module.Prober, "timeout_seconds", timeoutSeconds)
 
 	start := time.Now()
@@ -159,13 +160,15 @@ type scrapeLogger struct {
 	next         log.Logger
 	buffer       bytes.Buffer
 	bufferLogger log.Logger
+	logLevel     level.Option
 }
 
-func newScrapeLogger(logger log.Logger, module string, target string) *scrapeLogger {
+func newScrapeLogger(logger log.Logger, module string, target string, logLevel level.Option) *scrapeLogger {
 	logger = log.With(logger, "module", module, "target", target)
 	sl := &scrapeLogger{
-		next:   logger,
-		buffer: bytes.Buffer{},
+		next:     logger,
+		buffer:   bytes.Buffer{},
+		logLevel: logLevel,
 	}
 	bl := log.NewLogfmtLogger(&sl.buffer)
 	sl.bufferLogger = log.With(bl, "ts", log.DefaultTimestampUTC, "caller", log.Caller(6), "module", module, "target", target)
@@ -174,15 +177,8 @@ func newScrapeLogger(logger log.Logger, module string, target string) *scrapeLog
 
 func (sl scrapeLogger) Log(keyvals ...interface{}) error {
 	sl.bufferLogger.Log(keyvals...)
-	kvs := make([]interface{}, len(keyvals))
-	copy(kvs, keyvals)
-	// Switch level to debug for application output.
-	for i := 0; i < len(kvs); i += 2 {
-		if kvs[i] == level.Key() {
-			kvs[i+1] = level.DebugValue()
-		}
-	}
-	return sl.next.Log(kvs...)
+
+	return level.NewFilter(sl.next, sl.logLevel).Log(keyvals...)
 }
 
 // DebugOutput returns plaintext debug output for a probe.
diff --git a/prober/icmp.go b/prober/icmp.go
index 1f8432a..f780752 100644
--- a/prober/icmp.go
+++ b/prober/icmp.go
@@ -91,7 +91,7 @@ func ProbeICMP(ctx context.Context, target string, module config.Module, registr
 	dstIPAddr, lookupTime, err := chooseProtocol(ctx, module.ICMP.IPProtocol, module.ICMP.IPProtocolFallback, target, registry, logger)
 
 	if err != nil {
-		level.Warn(logger).Log("msg", "Error resolving address", "err", err)
+		level.Error(logger).Log("msg", "Error resolving address", "err", err)
 		return false
 	}
 	durationGaugeVec.WithLabelValues("resolve").Add(lookupTime)


Test patch:
diff --git a/prober/handler_test.go b/prober/handler_test.go
index 885f751..e9897ab 100644
--- a/prober/handler_test.go
+++ b/prober/handler_test.go
@@ -25,6 +25,7 @@ import (
 	"time"
 
 	"github.com/go-kit/log"
+	"github.com/go-kit/log/level"
 	"github.com/prometheus/client_golang/prometheus"
 	pconfig "github.com/prometheus/common/config"
 
@@ -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, log.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil)
+		Handler(w, r, c, log.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, level.AllowNone())
 	})
 
 	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, log.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil)
+		Handler(w, r, c, log.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, level.AllowNone())
 	})
 	handler.ServeHTTP(rr, req)
 
@@ -177,7 +178,7 @@ func TestHostnameParam(t *testing.T) {
 	rr := httptest.NewRecorder()
 
 	handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		Handler(w, r, c, log.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil)
+		Handler(w, r, c, log.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, level.AllowNone())
 	})
 
 	handler.ServeHTTP(rr, req)
@@ -195,7 +196,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, log.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil)
+		Handler(w, r, c, log.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, level.AllowNone())
 	})
 
 	rr = httptest.NewRecorder()
@@ -242,7 +243,7 @@ func TestTCPHostnameParam(t *testing.T) {
 	rr := httptest.NewRecorder()
 
 	handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		Handler(w, r, c, log.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil)
+		Handler(w, r, c, log.NewNopLogger(), &ResultHistory{}, 0.5, nil, nil, level.AllowNone())
 	})
 
 	handler.ServeHTTP(rr, req)