diff --git a/CHANGELOG.md b/CHANGELOG.md index 4d5a2233..23d8b933 100644 --- a/CHANGELOG.md +++ b/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] diff --git a/README.md b/README.md index 76e89a8f..8e0edc86 100644 --- a/README.md +++ b/README.md @@ -52,12 +52,9 @@ Note that the TLS and basic authentication settings affect all HTTP endpoints: ### 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. +The blackbox_exporter has a primary structured logger that is used for logs related to the application itself. +The blackbox_exporter also maintains a second, fully independent structured logger that is used specifically for logging related to the probers (`http`, `tcp`, `icmp`, `dns`, `grpc`) and their output. +The scrape probe logger defaults to `info` level filtering, similar to the primary logger. > _Note_ > @@ -70,100 +67,76 @@ modules: prober: http # generate probe -curl "http://localhost:9115/probe?target=prometheus.io&module=http_2xx" +curl -sL "http://localhost:9115/probe?target=prometheus.io&module=http_2xx&debug=true" ```
-Example output with `--log.level=info` and `--log.prober=debug` (default) - -```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..." +Example stderr and debug module output with `--log.prober=info` (default) + +```shell +~ $ ./blackbox_exporter --config.file ./blackbox.yml +time=2025-09-09T00:58:02.557-04:00 level=INFO source=main.go:95 msg="Starting blackbox_exporter" version="(version=0.27.0, branch=feat/make-scrape-logger-independent, revision=47e27d09847edf2ade2732b50663c37ed8177485)" +time=2025-09-09T00:58:02.557-04:00 level=INFO source=main.go:96 msg="(go=go1.24.4, platform=linux/amd64, user=tjhop@contraband, date=20250909-04:57:55, tags=unknown)" +time=2025-09-09T00:58:02.557-04:00 level=INFO source=main.go:108 msg="Loaded config file" +time=2025-09-09T00:58:02.558-04:00 level=INFO source=tls_config.go:347 msg="Listening on" address=[::]:9115 +time=2025-09-09T00:58:02.558-04:00 level=INFO source=tls_config.go:350 msg="TLS is disabled." http2=false address=[::]:9115 +time=2025-09-09T00:58:06.756-04:00 level=WARN source=http.go:490 msg="Received redirect" module=http_2xx target=prometheus.io location=https://prometheus.io/ +^Ctime=2025-09-09T00:58:12.257-04:00 level=INFO source=main.go:290 msg="Received SIGTERM, exiting gracefully..." ``` -
-
-Example output with `--log.level=info` and `--log.prober=info` +```shell +~ $ curl -sL "http://localhost:9115/probe?target=prometheus.io&module=http_2xx&debug=true" | sed '/Metrics that would have been returned/q' +Logs for the probe: +time=2025-09-09T00:58:06.756-04:00 level=WARN source=http.go:490 msg="Received redirect" module=http_2xx target=prometheus.io location=https://prometheus.io/ -```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..." + + +Metrics that would have been returned: ```
-Example output with `--log.level=debug` and `--log.prober=info` - -```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..." +Example stderr and debug module output with `--log.prober=debug` + +```shell +~ $ ./blackbox_exporter --config.file ./blackbox.yml --log.prober=debug +time=2025-09-09T00:58:21.483-04:00 level=INFO source=main.go:95 msg="Starting blackbox_exporter" version="(version=0.27.0, branch=feat/make-scrape-logger-independent, revision=47e27d09847edf2ade2732b50663c37ed8177485)" +time=2025-09-09T00:58:21.483-04:00 level=INFO source=main.go:96 msg="(go=go1.24.4, platform=linux/amd64, user=tjhop@contraband, date=20250909-04:57:55, tags=unknown)" +time=2025-09-09T00:58:21.483-04:00 level=INFO source=main.go:108 msg="Loaded config file" +time=2025-09-09T00:58:21.484-04:00 level=INFO source=tls_config.go:347 msg="Listening on" address=[::]:9115 +time=2025-09-09T00:58:21.484-04:00 level=INFO source=tls_config.go:350 msg="TLS is disabled." http2=false address=[::]:9115 +time=2025-09-09T00:58:26.604-04:00 level=DEBUG source=handler.go:116 msg="Beginning probe" module=http_2xx target=prometheus.io probe=http timeout_seconds=119.5 +time=2025-09-09T00:58:26.604-04:00 level=DEBUG source=utils.go:61 msg="Resolving target address" module=http_2xx target=prometheus.io target=prometheus.io ip_protocol=ip4 +time=2025-09-09T00:58:26.605-04:00 level=DEBUG source=utils.go:96 msg="Resolved target address" module=http_2xx target=prometheus.io target=prometheus.io ip=104.21.60.220 +time=2025-09-09T00:58:26.605-04:00 level=DEBUG source=http.go:209 msg="Making HTTP request" module=http_2xx target=prometheus.io url=http://104.21.60.220 host=prometheus.io +time=2025-09-09T00:58:26.645-04:00 level=WARN source=http.go:490 msg="Received redirect" module=http_2xx target=prometheus.io location=https://prometheus.io/ +time=2025-09-09T00:58:26.645-04:00 level=DEBUG source=http.go:209 msg="Making HTTP request" module=http_2xx target=prometheus.io url=https://prometheus.io/ host="" +time=2025-09-09T00:58:26.645-04:00 level=DEBUG source=http.go:224 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-09-09T00:58:26.765-04:00 level=DEBUG source=http.go:590 msg="Received HTTP response" module=http_2xx target=prometheus.io status_code=200 +time=2025-09-09T00:58:26.800-04:00 level=DEBUG source=http.go:721 msg="Response timings for roundtrip" module=http_2xx target=prometheus.io roundtrip=0 start=2025-09-09T00:58:26.605-04:00 dnsDone=2025-09-09T00:58:26.605-04:00 connectDone=2025-09-09T00:58:26.619-04:00 gotConn=2025-09-09T00:58:26.619-04:00 responseStart=2025-09-09T00:58:26.645-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-09-09T00:58:26.800-04:00 level=DEBUG source=http.go:721 msg="Response timings for roundtrip" module=http_2xx target=prometheus.io roundtrip=1 start=2025-09-09T00:58:26.645-04:00 dnsDone=2025-09-09T00:58:26.646-04:00 connectDone=2025-09-09T00:58:26.656-04:00 gotConn=2025-09-09T00:58:26.717-04:00 responseStart=2025-09-09T00:58:26.765-04:00 tlsStart=2025-09-09T00:58:26.657-04:00 tlsDone=2025-09-09T00:58:26.717-04:00 end=2025-09-09T00:58:26.800-04:00 +time=2025-09-09T00:58:26.801-04:00 level=DEBUG source=handler.go:127 msg="Probe succeeded" module=http_2xx target=prometheus.io duration_seconds=0.196876958 +^Ctime=2025-09-09T00:58:32.471-04:00 level=INFO source=main.go:290 msg="Received SIGTERM, exiting gracefully..." ``` -
+```shell +~ $ curl -sL "http://localhost:9115/probe?target=prometheus.io&module=http_2xx&debug=true" | sed '/Metrics that would have been returned/q' +Logs for the probe: +time=2025-09-09T00:58:26.604-04:00 level=DEBUG source=handler.go:116 msg="Beginning probe" module=http_2xx target=prometheus.io probe=http timeout_seconds=119.5 +time=2025-09-09T00:58:26.604-04:00 level=DEBUG source=utils.go:61 msg="Resolving target address" module=http_2xx target=prometheus.io target=prometheus.io ip_protocol=ip4 +time=2025-09-09T00:58:26.605-04:00 level=DEBUG source=utils.go:96 msg="Resolved target address" module=http_2xx target=prometheus.io target=prometheus.io ip=104.21.60.220 +time=2025-09-09T00:58:26.605-04:00 level=DEBUG source=http.go:209 msg="Making HTTP request" module=http_2xx target=prometheus.io url=http://104.21.60.220 host=prometheus.io +time=2025-09-09T00:58:26.645-04:00 level=WARN source=http.go:490 msg="Received redirect" module=http_2xx target=prometheus.io location=https://prometheus.io/ +time=2025-09-09T00:58:26.645-04:00 level=DEBUG source=http.go:209 msg="Making HTTP request" module=http_2xx target=prometheus.io url=https://prometheus.io/ host="" +time=2025-09-09T00:58:26.645-04:00 level=DEBUG source=http.go:224 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-09-09T00:58:26.765-04:00 level=DEBUG source=http.go:590 msg="Received HTTP response" module=http_2xx target=prometheus.io status_code=200 +time=2025-09-09T00:58:26.800-04:00 level=DEBUG source=http.go:721 msg="Response timings for roundtrip" module=http_2xx target=prometheus.io roundtrip=0 start=2025-09-09T00:58:26.605-04:00 dnsDone=2025-09-09T00:58:26.605-04:00 connectDone=2025-09-09T00:58:26.619-04:00 gotConn=2025-09-09T00:58:26.619-04:00 responseStart=2025-09-09T00:58:26.645-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-09-09T00:58:26.800-04:00 level=DEBUG source=http.go:721 msg="Response timings for roundtrip" module=http_2xx target=prometheus.io roundtrip=1 start=2025-09-09T00:58:26.645-04:00 dnsDone=2025-09-09T00:58:26.646-04:00 connectDone=2025-09-09T00:58:26.656-04:00 gotConn=2025-09-09T00:58:26.717-04:00 responseStart=2025-09-09T00:58:26.765-04:00 tlsStart=2025-09-09T00:58:26.657-04:00 tlsDone=2025-09-09T00:58:26.717-04:00 end=2025-09-09T00:58:26.800-04:00 +time=2025-09-09T00:58:26.801-04:00 level=DEBUG source=handler.go:127 msg="Probe succeeded" module=http_2xx target=prometheus.io duration_seconds=0.196876958 -
-Example output with `--log.level=debug` and `--log.prober=debug` -```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..." + +Metrics that would have been returned: ```
diff --git a/main.go b/main.go index 19897f55..84cebfd9 100644 --- a/main.go +++ b/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("").String() routePrefix = kingpin.Flag("web.route-prefix", "Prefix for the internal routes of web endpoints. Defaults to path of --web.external-url.").PlaceHolder("").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") diff --git a/prober/dns.go b/prober/dns.go index 3d301b9b..4b2e7566 100644 --- a/prober/dns.go +++ b/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 diff --git a/prober/handler.go b/prober/handler.go index 00e85d77..75545d38 100644 --- a/prober/handler.go +++ b/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,10 +201,10 @@ 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, } } @@ -217,42 +212,36 @@ func (sl *scrapeLogger) WithAttrs(attrs []slog.Attr) slog.Handler { // 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{} diff --git a/prober/handler_test.go b/prober/handler_test.go index f5a00a31..598b6820 100644 --- a/prober/handler_test.go +++ b/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) diff --git a/prober/http.go b/prober/http.go index 666d474f..41b9942d 100644 --- a/prober/http.go +++ b/prober/http.go @@ -206,7 +206,7 @@ func newTransport(rt, noServerName http.RoundTripper, logger *slog.Logger) *tran // RoundTrip switches to a new trace, then runs embedded RoundTripper. func (t *transport) RoundTrip(req *http.Request) (*http.Response, error) { - t.logger.Info("Making HTTP request", "url", req.URL.String(), "host", req.Host) + t.logger.Debug("Making HTTP request", "url", req.URL.String(), "host", req.Host) trace := &roundTripTrace{} if req.URL.Scheme == "https" { trace.tls = true @@ -221,13 +221,13 @@ func (t *transport) RoundTrip(req *http.Request) (*http.Response, error) { if t.firstHost != req.URL.Host { // This is a redirect to something other than the initial host, // so TLS ServerName should not be set. - t.logger.Info("Address does not match first address, not sending TLS ServerName", "first", t.firstHost, "address", req.URL.Host) + t.logger.Debug("Address does not match first address, not sending TLS ServerName", "first", t.firstHost, "address", req.URL.Host) // For HTTP/3, NoServerNameTransport might be nil as we don't create a serverless transport if t.NoServerNameTransport != nil { return t.NoServerNameTransport.RoundTrip(req) } // If NoServerNameTransport is nil, fall back to the normal Transport - t.logger.Info("No serverless transport available, using standard transport") + t.logger.Debug("No serverless transport available, using standard transport") } return t.Transport.RoundTrip(req) @@ -487,10 +487,10 @@ func ProbeHTTP(ctx context.Context, target string, module config.Module, registr client.Transport = tt client.CheckRedirect = func(r *http.Request, via []*http.Request) error { - logger.Info("Received redirect", "location", r.Response.Header.Get("Location")) + logger.Warn("Received redirect", "location", r.Response.Header.Get("Location")) redirects = len(via) if redirects > 10 || !httpConfig.HTTPClientConfig.FollowRedirects { - logger.Info("Not following redirect") + logger.Warn("Not following redirect") return errors.New("don't follow redirects") } return nil @@ -587,7 +587,7 @@ func ProbeHTTP(ctx context.Context, target string, module config.Module, registr } else { requestErrored := (err != nil) - logger.Info("Received HTTP response", "status_code", resp.StatusCode) + logger.Debug("Received HTTP response", "status_code", resp.StatusCode) if len(httpConfig.ValidStatusCodes) != 0 { for _, code := range httpConfig.ValidStatusCodes { if resp.StatusCode == code { @@ -596,13 +596,13 @@ func ProbeHTTP(ctx context.Context, target string, module config.Module, registr } } if !success { - logger.Info("Invalid HTTP response status code", "status_code", resp.StatusCode, + logger.Error("Invalid HTTP response status code", "status_code", resp.StatusCode, "valid_status_codes", fmt.Sprintf("%v", httpConfig.ValidStatusCodes)) } } else if 200 <= resp.StatusCode && resp.StatusCode < 300 { success = true } else { - logger.Info("Invalid HTTP response status code, wanted 2xx", "status_code", resp.StatusCode) + logger.Error("Invalid HTTP response status code, wanted 2xx", "status_code", resp.StatusCode) } if success && (len(httpConfig.FailIfHeaderMatchesRegexp) > 0 || len(httpConfig.FailIfHeaderNotMatchesRegexp) > 0) { @@ -620,7 +620,7 @@ func ProbeHTTP(ctx context.Context, target string, module config.Module, registr if httpConfig.Compression != "" { dec, err := getDecompressionReader(httpConfig.Compression, resp.Body) if err != nil { - logger.Info("Failed to get decompressor for HTTP response body", "err", err) + logger.Error("Failed to get decompressor for HTTP response body", "err", err) success = false } else if dec != nil { // Since we are replacing the original resp.Body with the decoder, we need to make sure @@ -631,7 +631,7 @@ func ProbeHTTP(ctx context.Context, target string, module config.Module, registr if err != nil { // At this point we cannot really do anything with this error, but log // it in case it contains useful information as to what's the problem. - logger.Info("Error while closing response from server", "err", err) + logger.Error("Error while closing response from server", "err", err) } }(resp.Body) @@ -670,7 +670,7 @@ func ProbeHTTP(ctx context.Context, target string, module config.Module, registr if !requestErrored { _, err = io.Copy(io.Discard, byteCounter) if err != nil { - logger.Info("Failed to read HTTP response body", "err", err) + logger.Error("Failed to read HTTP response body", "err", err) success = false } @@ -680,7 +680,7 @@ func ProbeHTTP(ctx context.Context, target string, module config.Module, registr // We have already read everything we could from the server, maybe even uncompressed the // body. The error here might be either a decompression error or a TCP error. Log it in // case it contains useful information as to what's the problem. - logger.Info("Error while closing response from server", "error", err.Error()) + logger.Error("Error while closing response from server", "error", err.Error()) } } @@ -718,7 +718,7 @@ func ProbeHTTP(ctx context.Context, target string, module config.Module, registr tt.mu.Lock() defer tt.mu.Unlock() for i, trace := range tt.traces { - logger.Info( + logger.Debug( "Response timings for roundtrip", "roundtrip", i, "start", trace.start, diff --git a/prober/icmp.go b/prober/icmp.go index 2f07e6b0..92f32032 100644 --- a/prober/icmp.go +++ b/prober/icmp.go @@ -101,11 +101,11 @@ func ProbeICMP(ctx context.Context, target string, module config.Module, registr logger.Error("Error parsing source ip address", "srcIP", module.ICMP.SourceIPAddress) return false } - logger.Info("Using source address", "srcIP", srcIP) + logger.Debug("Using source address", "srcIP", srcIP) } setupStart := time.Now() - logger.Info("Creating socket") + logger.Debug("Creating socket") privileged := true // Unprivileged sockets are supported on Darwin and Linux only. @@ -123,7 +123,7 @@ func ProbeICMP(ctx context.Context, target string, module config.Module, registr // "udp" here means unprivileged -- not the protocol "udp". icmpConn, err = icmp.ListenPacket("udp6", srcIP.String()) if err != nil { - logger.Debug("Unable to do unprivileged listen on socket, will attempt privileged", "err", err) + logger.Error("Unable to do unprivileged listen on socket, will attempt privileged", "err", err) } else { privileged = false } @@ -139,7 +139,7 @@ func ProbeICMP(ctx context.Context, target string, module config.Module, registr defer icmpConn.Close() if err := icmpConn.IPv6PacketConn().SetControlMessage(ipv6.FlagHopLimit, true); err != nil { - logger.Debug("Failed to set Control Message for retrieving Hop Limit", "err", err) + logger.Error("Failed to set Control Message for retrieving Hop Limit", "err", err) hopLimitFlagSet = false } } else { @@ -168,14 +168,14 @@ func ProbeICMP(ctx context.Context, target string, module config.Module, registr defer v4RawConn.Close() if err := v4RawConn.SetControlMessage(ipv4.FlagTTL, true); err != nil { - logger.Debug("Failed to set Control Message for retrieving TTL", "err", err) + logger.Error("Failed to set Control Message for retrieving TTL", "err", err) hopLimitFlagSet = false } } else { if tryUnprivileged { icmpConn, err = icmp.ListenPacket("udp4", srcIP.String()) if err != nil { - logger.Debug("Unable to do unprivileged listen on socket, will attempt privileged", "err", err) + logger.Error("Unable to do unprivileged listen on socket, will attempt privileged", "err", err) } else { privileged = false } @@ -191,7 +191,7 @@ func ProbeICMP(ctx context.Context, target string, module config.Module, registr defer icmpConn.Close() if err := icmpConn.IPv4PacketConn().SetControlMessage(ipv4.FlagTTL, true); err != nil { - logger.Debug("Failed to set Control Message for retrieving TTL", "err", err) + logger.Error("Failed to set Control Message for retrieving TTL", "err", err) hopLimitFlagSet = false } } @@ -215,7 +215,7 @@ func ProbeICMP(ctx context.Context, target string, module config.Module, registr Seq: int(getICMPSequence()), Data: data, } - logger.Info("Creating ICMP packet", "seq", body.Seq, "id", body.ID) + logger.Debug("Creating ICMP packet", "seq", body.Seq, "id", body.ID) wm := icmp.Message{ Type: requestType, Code: 0, @@ -229,7 +229,7 @@ func ProbeICMP(ctx context.Context, target string, module config.Module, registr } durationGaugeVec.WithLabelValues("setup").Add(time.Since(setupStart).Seconds()) - logger.Info("Writing out packet") + logger.Debug("Writing out packet") rttStart := time.Now() if icmpConn != nil { @@ -303,7 +303,7 @@ func ProbeICMP(ctx context.Context, target string, module config.Module, registr logger.Error("Error setting socket deadline", "err", err) return } - logger.Info("Waiting for reply packets") + logger.Debug("Waiting for reply packets") for { var n int var peer net.Addr @@ -368,7 +368,7 @@ func ProbeICMP(ctx context.Context, target string, module config.Module, registr hopLimitGauge.Set(hopLimit) registry.MustRegister(hopLimitGauge) } - logger.Info("Found matching reply packet") + logger.Debug("Found matching reply packet") return true } } diff --git a/prober/tcp.go b/prober/tcp.go index f2f1396d..7d94d88c 100644 --- a/prober/tcp.go +++ b/prober/tcp.go @@ -54,14 +54,14 @@ func dialTCP(ctx context.Context, target string, module config.Module, registry logger.Error("Error parsing source ip address", "srcIP", module.TCP.SourceIPAddress) return nil, fmt.Errorf("error parsing source ip address: %s", module.TCP.SourceIPAddress) } - logger.Info("Using local address", "srcIP", srcIP) + logger.Debug("Using local address", "srcIP", srcIP) dialer.LocalAddr = &net.TCPAddr{IP: srcIP} } dialTarget = net.JoinHostPort(ip.String(), port) if !module.TCP.TLS { - logger.Info("Dialing TCP without TLS") + logger.Debug("Dialing TCP without TLS") return dialer.DialContext(ctx, dialProtocol, dialTarget) } tlsConfig, err := pconfig.NewTLSConfig(&module.TCP.TLSConfig) @@ -83,7 +83,7 @@ func dialTCP(ctx context.Context, target string, module config.Module, registry timeoutDeadline, _ := ctx.Deadline() dialer.Deadline = timeoutDeadline - logger.Info("Dialing TCP with TLS") + logger.Debug("Dialing TCP with TLS") return tls.DialWithDialer(dialer, dialProtocol, dialTarget, tlsConfig) } @@ -132,7 +132,7 @@ func ProbeTCP(ctx context.Context, target string, module config.Module, registry return false } defer conn.Close() - logger.Info("Successfully dialed") + logger.Debug("Successfully dialed") // Set a deadline to prevent the following code from blocking forever. // If a deadline cannot be set, better fail the probe by returning an error @@ -151,7 +151,7 @@ func ProbeTCP(ctx context.Context, target string, module config.Module, registry } scanner := bufio.NewScanner(conn) for i, qr := range module.TCP.QueryResponse { - logger.Info("Processing query response entry", "entry_number", i) + logger.Debug("Processing query response entry", "entry_number", i) send := qr.Send if qr.Expect.Regexp != nil { var match []int @@ -160,7 +160,7 @@ func ProbeTCP(ctx context.Context, target string, module config.Module, registry logger.Debug("Read line", "line", scanner.Text()) match = qr.Expect.FindSubmatchIndex(scanner.Bytes()) if match != nil { - logger.Info("Regexp matched", "regexp", qr.Expect.Regexp, "line", scanner.Text()) + logger.Debug("Regexp matched", "regexp", qr.Expect.Regexp, "line", scanner.Text()) break } } @@ -206,7 +206,7 @@ func ProbeTCP(ctx context.Context, target string, module config.Module, registry logger.Error("TLS Handshake (client) failed", "err", err) return false } - logger.Info("TLS Handshake (client) succeeded.") + logger.Debug("TLS Handshake (client) succeeded.") conn = net.Conn(tlsConn) scanner = bufio.NewScanner(conn) diff --git a/prober/utils.go b/prober/utils.go index 3dc4153c..2bc10097 100644 --- a/prober/utils.go +++ b/prober/utils.go @@ -58,7 +58,7 @@ func chooseProtocol(ctx context.Context, IPProtocol string, fallbackIPProtocol b fallbackProtocol = "ip6" } - logger.Info("Resolving target address", "target", target, "ip_protocol", IPProtocol) + logger.Debug("Resolving target address", "target", target, "ip_protocol", IPProtocol) resolveStart := time.Now() defer func() { @@ -71,7 +71,7 @@ func chooseProtocol(ctx context.Context, IPProtocol string, fallbackIPProtocol b ips, err := resolver.LookupIP(ctx, IPProtocol, target) if err == nil { for _, ip := range ips { - logger.Info("Resolved target address", "target", target, "ip", ip.String()) + logger.Debug("Resolved target address", "target", target, "ip", ip.String()) probeIPProtocolGauge.Set(protocolToGauge[IPProtocol]) probeIPAddrHash.Set(ipHash(ip)) return &net.IPAddr{IP: ip}, lookupTime, nil @@ -93,7 +93,7 @@ func chooseProtocol(ctx context.Context, IPProtocol string, fallbackIPProtocol b switch IPProtocol { case "ip4": if ip.IP.To4() != nil { - logger.Info("Resolved target address", "target", target, "ip", ip.String()) + logger.Debug("Resolved target address", "target", target, "ip", ip.String()) probeIPProtocolGauge.Set(4) probeIPAddrHash.Set(ipHash(ip.IP)) return &ip, lookupTime, nil @@ -104,7 +104,7 @@ func chooseProtocol(ctx context.Context, IPProtocol string, fallbackIPProtocol b case "ip6": if ip.IP.To4() == nil { - logger.Info("Resolved target address", "target", target, "ip", ip.String()) + logger.Debug("Resolved target address", "target", target, "ip", ip.String()) probeIPProtocolGauge.Set(6) probeIPAddrHash.Set(ipHash(ip.IP)) return &ip, lookupTime, nil @@ -127,7 +127,7 @@ func chooseProtocol(ctx context.Context, IPProtocol string, fallbackIPProtocol b probeIPProtocolGauge.Set(6) } probeIPAddrHash.Set(ipHash(fallback.IP)) - logger.Info("Resolved target address", "target", target, "ip", fallback.String()) + logger.Debug("Resolved target address", "target", target, "ip", fallback.String()) return fallback, lookupTime, nil }