diff --git a/handlers/libhoney_event_handler.go b/handlers/libhoney_event_handler.go index ee4ef694..6660263c 100644 --- a/handlers/libhoney_event_handler.go +++ b/handlers/libhoney_event_handler.go @@ -86,43 +86,56 @@ 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.event_handled_at", time.Now()) + switch { + 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.response.capture_to_handle.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.request.capture_to_handle.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.request.capture_to_handle.latency_ms", time.Since(httpEvent.RequestTimestamp).Milliseconds()) + honeyEvent.AddField("meta.response.capture_to_handle.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("meta.seqack", event.RequestId) ev.AddField("meta.request.packet_count", event.RequestPacketCount) ev.AddField("meta.response.packet_count", event.ResponsePacketCount) - 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) diff --git a/handlers/libhoney_event_handler_test.go b/handlers/libhoney_event_handler_test.go index 19fc5eaa..b712b482 100644 --- a/handlers/libhoney_event_handler_test.go +++ b/handlers/libhoney_event_handler_test.go @@ -25,6 +25,8 @@ func Test_libhoneyEventHandler_handleEvent(t *testing.T) { testReqTime := time.Now() testReqPacketCount := 2 testRespPacketCount := 3 + testRespTime := testReqTime.Add(3 * time.Millisecond) + httpEvent := assemblers.HttpEvent{ StreamIdent: "c->s:1->2", Request: &http.Request{ @@ -38,7 +40,7 @@ func Test_libhoneyEventHandler_handleEvent(t *testing.T) { ContentLength: 84, }, RequestTimestamp: testReqTime, - ResponseTimestamp: testReqTime.Add(3 * time.Millisecond), + ResponseTimestamp: testRespTime, RequestPacketCount: testReqPacketCount, ResponsePacketCount: testRespPacketCount, SrcIp: "1.2.3.4", @@ -101,9 +103,9 @@ func Test_libhoneyEventHandler_handleEvent(t *testing.T) { attrs := events[0].Data // remove dynamic time-based data before comparing - delete(attrs, "meta.httpEvent_handled_at") - delete(attrs, "meta.httpEvent_request_handled_latency_ms") - delete(attrs, "meta.httpEvent_response_handled_latency_ms") + delete(attrs, "meta.event_handled_at") + delete(attrs, "meta.request.capture_to_handle.latency_ms") + delete(attrs, "meta.response.capture_to_handle.latency_ms") expectedAttrs := map[string]interface{}{ "name": "HTTP GET", @@ -117,7 +119,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", @@ -219,9 +221,9 @@ func Test_libhoneyEventHandler_handleEvent_routed_to_service(t *testing.T) { attrs := events[0].Data // remove dynamic time-based data before comparing - delete(attrs, "meta.httpEvent_handled_at") - delete(attrs, "meta.httpEvent_request_handled_latency_ms") - delete(attrs, "meta.httpEvent_response_handled_latency_ms") + delete(attrs, "meta.event_handled_at") + delete(attrs, "meta.request.capture_to_handle.latency_ms") + delete(attrs, "meta.response.capture_to_handle.latency_ms") expectedAttrs := map[string]interface{}{ "name": "HTTP GET", @@ -254,6 +256,86 @@ func Test_libhoneyEventHandler_handleEvent_routed_to_service(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: