Correctly handle $upstream_response_time values with multiple measure…

…ments (#221)

* Add failing test case for #217

* Correctly handle $upstream_response_time values with multiple measurements

* Refactor to reduce duplication

features/issues.feature

@@ -25,3 +25,13 @@ Feature: Various issues reported in the bug tracker remain solved
       28.90.74.145 - - [17/Jan/2020:10:18:11 +0000] "GET /category/finance HTTP/1.1" 200 83 "/category/books?from=20" "Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)" 5175 1477 8842
       """
     Then the exporter should report value 1 for metric test_http_response_count_total{method="GET",status="200"}
+
+  Scenario: Issue 217: Multiple response time values
+    Given a running exporter listening with configuration file "test-config-issue217.yaml"
+    When the following HTTP request is logged to "access.log"
+      """
+      www.example.com 10.0.0.1 - - [27/Oct/2021:06:00:14 +0200] "GET /websocket HTTP/1.1" 200 552 "-" "SomeUserAgentString" 0.000 "1.000, 0.250, 2.000, 0.750" . TLSv1.3/TLS_AES_256_GCM_SHA384 1234567890 www.example.com
+      www.example.com 10.0.0.2 - - [27/Oct/2021:06:00:15 +0200] "GET /websocket HTTP/1.1" 200 552 "-" "AnotherUserAgent" 0.000 "1.000, 0.250, 2.000, 0.750" . TLSv1.3/TLS_AES_256_GCM_SHA384 1234567890 www.example.com
+      www.example.com 10.0.0.3 - - [27/Oct/2021:06:00:15 +0200] "GET /websocket HTTP/1.1" 200 150 "-" "SomeUserAgentString" 0.001 "1.000, 0.250, 2.000, 0.750" . TLSv1.3/TLS_AES_256_GCM_SHA384 1234567890 www.example.com
+      """
+    Then the exporter should report value 12 for metric test_http_upstream_time_seconds_sum{method="GET",status="200"}

features/test-config-issue217.yaml

@@ -0,0 +1,10 @@
+enable_experimental: true
+
+listen:
+  port: 4040
+
+namespaces:
+  - name: test
+    format: "$server_name $remote_addr - $remote_user [$time_local] \"$request\" $status $body_bytes_sent \"$http_referer\" \"$http_user_agent\" $request_time \"$upstream_response_time\" $pipe $ssl_protocol/$ssl_cipher $request_id $host"
+    source_files:
+      - .behave-sandbox/access.log

main.go

@@ -23,6 +23,7 @@ import (
 	"os"
 	"os/signal"
 	"strconv"
+	"strings"
 	"sync"
 	"syscall"
 
@@ -400,36 +401,74 @@ func processSource(nsCfg config.NamespaceConfig, t tail.Follower, parser parser.
 
 		metrics.countTotal.WithLabelValues(labelValues...).Inc()
 
-		if bytes, ok := floatFromFields(fields, "body_bytes_sent"); ok {
-			metrics.responseBytesTotal.WithLabelValues(notCounterValues...).Add(bytes)
+		if v, ok := observeMetrics(fields, "body_bytes_sent", floatFromFields, metrics.parseErrorsTotal); ok {
+			metrics.responseBytesTotal.WithLabelValues(notCounterValues...).Add(v)
 		}
 
-		if bytes, ok := floatFromFields(fields, "request_length"); ok {
-			metrics.requestBytesTotal.WithLabelValues(notCounterValues...).Add(bytes)
+		if v, ok := observeMetrics(fields, "request_length", floatFromFields, metrics.parseErrorsTotal); ok {
+			metrics.requestBytesTotal.WithLabelValues(notCounterValues...).Add(v)
 		}
 
-		if upstreamTime, ok := floatFromFields(fields, "upstream_response_time"); ok {
-			metrics.upstreamSeconds.WithLabelValues(notCounterValues...).Observe(upstreamTime)
-			metrics.upstreamSecondsHist.WithLabelValues(notCounterValues...).Observe(upstreamTime)
+		if v, ok := observeMetrics(fields, "upstream_response_time", floatFromFieldsMulti, metrics.parseErrorsTotal); ok {
+			metrics.upstreamSeconds.WithLabelValues(notCounterValues...).Observe(v)
+			metrics.upstreamSecondsHist.WithLabelValues(notCounterValues...).Observe(v)
 		}
 
-		if responseTime, ok := floatFromFields(fields, "request_time"); ok {
-			metrics.responseSeconds.WithLabelValues(notCounterValues...).Observe(responseTime)
-			metrics.responseSecondsHist.WithLabelValues(notCounterValues...).Observe(responseTime)
+		if v, ok := observeMetrics(fields, "request_time", floatFromFields, metrics.parseErrorsTotal); ok {
+			metrics.responseSeconds.WithLabelValues(notCounterValues...).Observe(v)
+			metrics.responseSecondsHist.WithLabelValues(notCounterValues...).Observe(v)
 		}
 	}
 }
 
-func floatFromFields(fields map[string]string, name string) (float64, bool) {
+func observeMetrics(fields map[string]string, name string, extractor func(map[string]string, string) (float64, bool, error), parseErrors prometheus.Counter) (float64, bool) {
+	if observation, ok, err := extractor(fields, name); ok {
+		return observation, true
+	} else if err != nil {
+		fmt.Printf("error while parsing $%s: %v\n", name, err)
+		parseErrors.Inc()
+	}
+
+	return 0, false
+}
+
+func floatFromFieldsMulti(fields map[string]string, name string) (float64, bool, error) {
+	f, ok, err := floatFromFields(fields, name)
+	if err == nil {
+		return f, ok, nil
+	}
+
+	val, ok := fields[name]
+	if !ok {
+		return 0, false, nil
+	}
+
+	sum := float64(0)
+
+	for _, v := range strings.Split(val, ",") {
+		v = strings.TrimSpace(v)
+
+		f, err := strconv.ParseFloat(v, 64)
+		if err != nil {
+			return 0, false, fmt.Errorf("value '%s' could not be parsed into float", val)
+		}
+
+		sum += f
+	}
+
+	return sum, true, nil
+}
+
+func floatFromFields(fields map[string]string, name string) (float64, bool, error) {
 	val, ok := fields[name]
 	if !ok {
-		return 0, false
+		return 0, false, nil
 	}
 
 	f, err := strconv.ParseFloat(val, 64)
 	if err != nil {
-		return 0, false
+		return 0, false, fmt.Errorf("value '%s' could not be parsed into float", val)
 	}
 
-	return f, true
+	return f, true, nil
 }