weblog: Correctly parse multiple values in nginx upstream_response_ti…

…me (#711)

This commit changes the way how the upstream_response_time field is
parsed in nginx access logs. The field can contain multiple time values
if the request got processed by multiple upstream servers, or if it
passed through an internal redirect between multiple server groups (i.e.
by using the X-Accel-Redirect header).

Previously, only the first encountered value was processed by weblog
plugin, and it only accounted for the ',' separator. If the field contained
the ':' separator, the value was not parsed correctly. With this commit
applied, both of these cases will be handled correctly. Additionaly, the
value reported will be the sum of times from all upstream servers that
handled the request, i.e. the total time the request spent upstream.

Co-authored-by: Jan Kral <jan.kral@4net.tv>

modules/weblog/logline.go

@@ -325,19 +325,30 @@ func (l *logLine) assignReqProcTime(time string) error {
 	return nil
 }
 
+func isUpstreamTimeSeparator(r rune) bool { return r == ',' || r == ':' }
+
 func (l *logLine) assignUpsRespTime(time string) error {
 	if time == hyphen {
 		return nil
 	}
-	// times of several responses are separated by commas and colons.
-	if idx := strings.IndexByte(time, ','); idx >= 0 {
-		time = time[0:idx]
-	}
-	v, err := strconv.ParseFloat(time, 64)
-	if err != nil || !isTimeValid(v) {
-		return fmt.Errorf("assign '%s': %w", time, errBadUpsRespTime)
+
+	// the upstream response time string can contain multiple values, separated
+	// by commas (in case the request was handled by multiple servers), or colons
+	// (in case the request passed between multiple server groups via an internal redirect)
+	// the individual values should be summed up to obtain the correct amount of time
+	// the request spent in upstream
+	var sum float64
+	for _, val := range strings.FieldsFunc(time, isUpstreamTimeSeparator) {
+		val = strings.TrimSpace(val)
+		v, err := strconv.ParseFloat(val, 64)
+		if err != nil || !isTimeValid(v) {
+			return fmt.Errorf("assign '%s': %w", time, errBadUpsRespTime)
+		}
+
+		sum += v
 	}
-	l.upsRespTime = v * timeMultiplier(time)
+
+	l.upsRespTime = sum * timeMultiplier(time)
 	return nil
 }
 

modules/weblog/logline_test.go

@@ -287,7 +287,7 @@ func TestLogLine_Assign(t *testing.T) {
 			cases: []subTest{
 				{input: "100222", wantLine: logLine{web: web{upsRespTime: 100222}}},
 				{input: "100.222", wantLine: logLine{web: web{upsRespTime: 100222000}}},
-				{input: "0.333,0.444,0.555", wantLine: logLine{web: web{upsRespTime: 333000}}},
+				{input: "0.100 , 0.400 : 0.200 ", wantLine: logLine{web: web{upsRespTime: 700000}}},
 				{input: emptyStr, wantLine: emptyLogLine},
 				{input: hyphen, wantLine: emptyLogLine},
 				{input: "-1", wantLine: emptyLogLine, wantErr: errBadUpsRespTime},