fix: Don't send durations when they are not from actual capture times

handlers/libhoney_event_handler.go

@@ -86,40 +86,53 @@ func initLibhoney(config config.Config, version string) func() {
 	return libhoney.Close
 }
 
+// setTimestampsAndDurationIfValid sets time-related fields in the emitted telemetry
+// about the request/response cycle.
+//
+// It only sets timestamps if they are present in the captured event, and only
+// computes and includes durations for which there are correct timestamps to based them upon.
+func setTimestampsAndDurationIfValid(honeyEvent *libhoney.Event, httpEvent assemblers.HttpEvent) {
+	honeyEvent.AddField("meta.httpEvent_handled_at", time.Now())
+	switch true {
+	case httpEvent.RequestTimestamp.IsZero() && httpEvent.ResponseTimestamp.IsZero():
+		// no request or response, which is weird, but let's send what we do know
+		honeyEvent.AddField("meta.timestamps_missing", "request, response")
+		honeyEvent.Timestamp = time.Now()
+
+	case httpEvent.RequestTimestamp.IsZero():
+		// no request
+		honeyEvent.AddField("meta.timestamps_missing", "request")
+		// but we have a response
+		honeyEvent.Timestamp = httpEvent.ResponseTimestamp
+		honeyEvent.AddField("http.response.timestamp", httpEvent.ResponseTimestamp)
+		honeyEvent.AddField("meta.httpEvent_response_handled_latency_ms", time.Since(httpEvent.ResponseTimestamp).Milliseconds())
+
+	case httpEvent.ResponseTimestamp.IsZero(): // have request, no response
+		// no response
+		honeyEvent.AddField("meta.timestamps_missing", "response")
+		// but we have a request
+		honeyEvent.Timestamp = httpEvent.RequestTimestamp
+		honeyEvent.AddField("http.request.timestamp", httpEvent.RequestTimestamp)
+		honeyEvent.AddField("meta.httpEvent_request_handled_latency_ms", time.Since(httpEvent.RequestTimestamp).Milliseconds())
+
+	default: // the happiest of paths, we have both request and response
+		honeyEvent.Timestamp = httpEvent.RequestTimestamp
+		honeyEvent.AddField("http.request.timestamp", httpEvent.RequestTimestamp)
+		honeyEvent.AddField("http.response.timestamp", httpEvent.ResponseTimestamp)
+		honeyEvent.AddField("meta.httpEvent_request_handled_latency_ms", time.Since(httpEvent.RequestTimestamp).Milliseconds())
+		honeyEvent.AddField("meta.httpEvent_response_handled_latency_ms", time.Since(httpEvent.ResponseTimestamp).Milliseconds())
+		honeyEvent.AddField("duration_ms", httpEvent.ResponseTimestamp.Sub(httpEvent.RequestTimestamp).Milliseconds())
+	}
+}
+
+// handleEvent transforms a captured httpEvent into a libhoney event and sends it
 func (handler *libhoneyEventHandler) handleEvent(event assemblers.HttpEvent) {
-	// create libhoney event
-	ev := libhoney.NewEvent()
+	// the telemetry event to send
+	var ev *libhoney.Event = libhoney.NewEvent()
 
-	// calculate event duration
-	// TODO: This is a hack to work around a bug that results in the response timestamp sometimes
-	// being zero which causes the event duration to be negative.
-	if event.RequestTimestamp.IsZero() {
-		log.Debug().
-			Str("stream_ident", event.StreamIdent).
-			Int64("request_id", event.RequestId).
-			Msg("Request timestamp is zero")
-		ev.AddField("http.request.timestamp_missing", true)
-		event.RequestTimestamp = time.Now()
-	}
-	if event.ResponseTimestamp.IsZero() {
-		log.Debug().
-			Str("stream_ident", event.StreamIdent).
-			Int64("request_id", event.RequestId).
-			Msg("Response timestamp is zero")
-		ev.AddField("http.response.timestamp_missing", true)
-		event.ResponseTimestamp = time.Now()
-	}
-	eventDuration := event.ResponseTimestamp.Sub(event.RequestTimestamp)
+	setTimestampsAndDurationIfValid(ev, event)
 
-	// common attributes
-	ev.Timestamp = event.RequestTimestamp
-	ev.AddField("meta.httpEvent_handled_at", time.Now())
-	ev.AddField("meta.httpEvent_request_handled_latency_ms", time.Since(event.RequestTimestamp).Milliseconds())
-	ev.AddField("meta.httpEvent_response_handled_latency_ms", time.Since(event.ResponseTimestamp).Milliseconds())
 	ev.AddField("meta.stream.ident", event.StreamIdent)
-	ev.AddField("duration_ms", eventDuration.Milliseconds())
-	ev.AddField("http.request.timestamp", event.RequestTimestamp)
-	ev.AddField("http.response.timestamp", event.ResponseTimestamp)
 
 	ev.AddField(string(semconv.ClientSocketAddressKey), event.SrcIp)
 	ev.AddField(string(semconv.ServerSocketAddressKey), event.DstIp)

handlers/libhoney_event_handler_test.go

@@ -23,6 +23,8 @@ func Test_libhoneyEventHandler_handleEvent(t *testing.T) {
 
 	// Test Data - an assembled HTTP Event
 	testReqTime := time.Now()
+	testRespTime := testReqTime.Add(3 * time.Millisecond)
+
 	httpEvent := assemblers.HttpEvent{
 		StreamIdent: "c->s:1->2",
 		Request: &http.Request{
@@ -36,7 +38,7 @@ func Test_libhoneyEventHandler_handleEvent(t *testing.T) {
 			ContentLength: 84,
 		},
 		RequestTimestamp:  testReqTime,
-		ResponseTimestamp: testReqTime.Add(3 * time.Millisecond),
+		ResponseTimestamp: testRespTime,
 		SrcIp:             "1.2.3.4",
 		DstIp:             "5.6.7.8",
 	}
@@ -110,7 +112,7 @@ func Test_libhoneyEventHandler_handleEvent(t *testing.T) {
 		"url.path":                       "/check?teapot=true",
 		"http.request.body.size":         int64(42),
 		"http.request.timestamp":         testReqTime,
-		"http.response.timestamp":        testReqTime.Add(3 * time.Millisecond),
+		"http.response.timestamp":        testRespTime,
 		"http.response.status_code":      418,
 		"http.response.body.size":        int64(84),
 		"error":                          "HTTP client error",
@@ -127,6 +129,86 @@ func Test_libhoneyEventHandler_handleEvent(t *testing.T) {
 	assert.Equal(t, expectedAttrs, attrs)
 }
 
+func Test_reportingTimesAndDurations(t *testing.T) {
+	// Do you remember the 21st night of September?
+	var aRealRequestTime time.Time = time.Date(1978, time.September, 21, 11, 30, 0, 0, time.UTC)
+	// ... a response little bit later ...
+	var aRealResponseTime time.Time = aRealRequestTime.Add(3 * time.Millisecond)
+	// an expectation of 'nowish' for scenarios where the code under test defaults to time.Now()
+	var nowish time.Time = time.Now()
+
+	testCases := []struct {
+		desc                string
+		reqTime             time.Time
+		respTime            time.Time
+		expectToSetDuration bool
+		// empty if duration is expected, list of missing timestamps otherwise
+		expectedTimestampsMissing string
+		expectedDuration          int64
+		expectedTelemetryTime     time.Time
+	}{
+		{
+			desc:                  "happy path!",
+			reqTime:               aRealRequestTime,
+			respTime:              aRealResponseTime,
+			expectToSetDuration:   true,
+			expectedDuration:      3,
+			expectedTelemetryTime: aRealRequestTime,
+		},
+		{
+			desc:                      "missing request timestamp",
+			reqTime:                   time.Time{},
+			respTime:                  aRealResponseTime,
+			expectToSetDuration:       false,
+			expectedTimestampsMissing: "request",
+			expectedTelemetryTime:     aRealResponseTime,
+		},
+		{
+			desc:                      "missing response timestamp",
+			reqTime:                   aRealRequestTime,
+			respTime:                  time.Time{},
+			expectToSetDuration:       false,
+			expectedTimestampsMissing: "response",
+			expectedTelemetryTime:     aRealRequestTime,
+		},
+		{
+			desc:                      "missing both timestamps",
+			reqTime:                   time.Time{},
+			respTime:                  time.Time{},
+			expectToSetDuration:       false,
+			expectedTimestampsMissing: "request, response",
+			expectedTelemetryTime:     nowish,
+		},
+	}
+	for _, tC := range testCases {
+		t.Run(tC.desc, func(t *testing.T) {
+			ev := libhoney.NewEvent()
+			httpEvent := assemblers.HttpEvent{
+				RequestTimestamp:  tC.reqTime,
+				ResponseTimestamp: tC.respTime,
+			}
+
+			setTimestampsAndDurationIfValid(ev, httpEvent)
+
+			if tC.expectedTelemetryTime != nowish {
+				assert.Equal(t, tC.expectedTelemetryTime, ev.Timestamp)
+			} else {
+				assert.WithinDuration(
+					t, tC.expectedTelemetryTime, ev.Timestamp, 10*time.Millisecond,
+					"a real failure should be wildly wrong, close failures might be a slow test suite and this assertion could use a rethink",
+				)
+			}
+
+			if tC.expectToSetDuration {
+				assert.Equal(t, ev.Fields()["duration_ms"], tC.expectedDuration)
+			} else {
+				assert.Equal(t, ev.Fields()["meta.timestamps_missing"], tC.expectedTimestampsMissing)
+				assert.Nil(t, ev.Fields()["duration_ms"])
+			}
+		})
+	}
+}
+
 // setupTestLibhoney configures a Libhoney with a mock transmission for testing.
 //
 // Events sent can be found on the mock transmission: