Bogus probe_http_duration_seconds{phase="tls"} values if more than one redirect

[dswarbrick]

Host operating system: output of uname -a

Linux ber-prom1 4.19.0-5-amd64 #1 SMP Debian 4.19.37-3 (2019-05-15) x86_64 GNU/Linux

blackbox_exporter version: output of blackbox_exporter -version

blackbox_exporter, version 0.14.0+ds (branch: debian/sid, revision: 0.14.0+ds-1~ionos1)
  build user:       [email protected]
  build date:       20190606-12:27:16
  go version:       go1.11.6

What is the blackbox.yml module config.

  http:
    prober: http
    http:
      preferred_ip_protocol: ip4
      headers:
        User-Agent: blackbox_exporter

What is the prometheus.yml scrape config.

- job_name: blackbox-http
  metrics_path: /probe
  params:
    module: [http]
  file_sd_configs:
  - files:
    - targets/http.yml
  relabel_configs:
  - source_labels: [__address__]
    target_label: __param_target
  - source_labels: [__param_target]
    target_label: instance
  - target_label: __address__
    replacement: localhost:9115

What logging output did you get from adding &debug=true to the probe URL?

Logs for the probe:
ts=2019-06-11T09:52:35.312192849Z caller=main.go:118 module=http target=http://backup.profitbricks.com level=info msg="Beginning probe" probe=http timeout_seconds=9.5
ts=2019-06-11T09:52:35.312481462Z caller=utils.go:42 module=http target=http://backup.profitbricks.com level=info msg="Resolving target address" ip_protocol=ip4
ts=2019-06-11T09:52:35.31408387Z caller=utils.go:75 module=http target=http://backup.profitbricks.com level=info msg="Resolved target address" ip=81.169.163.183
ts=2019-06-11T09:52:35.314177504Z caller=http.go:349 module=http target=http://backup.profitbricks.com level=info msg="Making HTTP request" url=http://[81.169.163.183] host=backup.profitbricks.com
ts=2019-06-11T09:52:35.322419932Z caller=http.go:305 module=http target=http://backup.profitbricks.com level=info msg="Received redirect" url=https://backup.profitbricks.com/
ts=2019-06-11T09:52:35.368116592Z caller=http.go:305 module=http target=http://backup.profitbricks.com level=info msg="Received redirect" url=https://backup.profitbricks.com/login
ts=2019-06-11T09:52:35.372833104Z caller=http.go:368 module=http target=http://backup.profitbricks.com level=info msg="Received HTTP response" status_code=200
ts=2019-06-11T09:52:35.372982027Z caller=http.go:450 module=http target=http://backup.profitbricks.com level=info msg="Response timings for roundtrip" roundtrip=0 start=2019-06-11T09:52:35.3143691Z dnsDone=2019-06-11T09:52:35.3143691Z connectDone=2019-06-11T09:52:35.317677152Z gotConn=2019-06-11T09:52:35.317781443Z responseStart=2019-06-11T09:52:35.322316442Z end=0001-01-01T00:00:00Z
ts=2019-06-11T09:52:35.37304789Z caller=http.go:450 module=http target=http://backup.profitbricks.com level=info msg="Response timings for roundtrip" roundtrip=1 start=2019-06-11T09:52:35.322653911Z dnsDone=2019-06-11T09:52:35.324076565Z connectDone=2019-06-11T09:52:35.326945021Z gotConn=2019-06-11T09:52:35.348920664Z responseStart=2019-06-11T09:52:35.367977698Z end=0001-01-01T00:00:00Z
ts=2019-06-11T09:52:35.373103652Z caller=http.go:450 module=http target=http://backup.profitbricks.com level=info msg="Response timings for roundtrip" roundtrip=2 start=0001-01-01T00:00:00Z dnsDone=0001-01-01T00:00:00Z connectDone=0001-01-01T00:00:00Z gotConn=2019-06-11T09:52:35.368227122Z responseStart=2019-06-11T09:52:35.372754298Z end=2019-06-11T09:52:35.372946033Z
ts=2019-06-11T09:52:35.373181375Z caller=main.go:129 module=http target=http://backup.profitbricks.com level=info msg="Probe succeeded" duration_seconds=0.060882068



Metrics that would have been returned:
# HELP probe_dns_lookup_time_seconds Returns the time taken for probe dns lookup in seconds
# TYPE probe_dns_lookup_time_seconds gauge
probe_dns_lookup_time_seconds 0.001537687
# HELP probe_duration_seconds Returns how long the probe took to complete in seconds
# TYPE probe_duration_seconds gauge
probe_duration_seconds 0.060882068
# HELP probe_failed_due_to_regex Indicates if probe failed due to regex
# TYPE probe_failed_due_to_regex gauge
probe_failed_due_to_regex 0
# HELP probe_http_content_length Length of http content response
# TYPE probe_http_content_length gauge
probe_http_content_length 3275
# HELP probe_http_duration_seconds Duration of http request by phase, summed over all redirects
# TYPE probe_http_duration_seconds gauge
probe_http_duration_seconds{phase="connect"} 0.006280786
probe_http_duration_seconds{phase="processing"} 0.028119333
probe_http_duration_seconds{phase="resolve"} 0.0029604230000000002
probe_http_duration_seconds{phase="tls"} 9.223372036879622e+09
probe_http_duration_seconds{phase="transfer"} 0.000191637
# HELP probe_http_last_modified_timestamp_seconds Returns the Last-Modified HTTP response header in unixtime
# TYPE probe_http_last_modified_timestamp_seconds gauge
probe_http_last_modified_timestamp_seconds 1.555515177e+09
# HELP probe_http_redirects The number of redirects
# TYPE probe_http_redirects gauge
probe_http_redirects 2
# HELP probe_http_ssl Indicates if SSL was used for the final redirect
# TYPE probe_http_ssl gauge
probe_http_ssl 1
# HELP probe_http_status_code Response HTTP status code
# TYPE probe_http_status_code gauge
probe_http_status_code 200
# HELP probe_http_version Returns the version of HTTP of the probe response
# TYPE probe_http_version gauge
probe_http_version 1.1
# HELP probe_ip_protocol Specifies whether probe ip protocol is IP4 or IP6
# TYPE probe_ip_protocol gauge
probe_ip_protocol 4
# HELP probe_ssl_earliest_cert_expiry Returns earliest SSL cert expiry in unixtime
# TYPE probe_ssl_earliest_cert_expiry gauge
probe_ssl_earliest_cert_expiry 1.5943824e+09
# HELP probe_success Displays whether or not the probe was a success
# TYPE probe_success gauge
probe_success 1



Module configuration:
prober: http
http:
  preferred_ip_protocol: ip4
  ip_protocol_fallback: true
  headers:
    User-Agent: blackbox_exporter
tcp:
  ip_protocol_fallback: true
icmp:
  ip_protocol_fallback: true
dns:
  ip_protocol_fallback: true

What did you do that produced an error?

n/a

What did you expect to see?

probe_http_duration_seconds{phase="tls"} in the same vicinity as the other phases.

What did you see instead?

Extremely high probe_http_duration_seconds{phase="tls"} values (> 290 years).

It seems that if the probed URL does more than a single redirect, the probe_http_duration_seconds{phase="tls"} value is bogus. A double-redirect is likely to occur if e.g. probing a non-HTTPS URL, with the intention of checking that it performs the expected redirect to an HTTPS URL. However, if that URL also performs a redirect (e.g. due to invalid session / redirect to login page), the probe_http_duration_seconds{phase="tls"} value is sky high.

If the first redirect is omitted by scraping the HTTPS URL directly (and only getting a single "login page" redirect), the probe_http_duration_seconds{phase="tls"} values are sane.

[efenex]

same!

[fdamken]

Any updates on this? Combined with prometheus/prometheus#5097, it's tricky to deal with alerting rules on long probe durations if a single service fails in the tls phase due to this issue.