Skip to content

Commit

Permalink
fix: Don't send durations when they are not from actual capture times (…
Browse files Browse the repository at this point in the history 
…#258)

## Which problem is this PR solving?

- Closes #249 

## Short description of the changes

- refactor duration computation into an extracted function
- test drive timestamp(s) set/unset scenarios

## How to verify that this has the expected result

Duration is only set if both timestamps are present. If one or both are
missing, attributes are added to the event indicating that, and no
duration is set (event timestamp is set to time.now). If both timestamps
are present, calculate the duration and add to the event. We should see
no more negative durations caused by missing timestamps

---------

Co-authored-by: Jamie Danielson <JamieDanielson@users.noreply.github.com>
Co-authored-by: JamieDanielson <jamieedanielson@gmail.com>
Co-authored-by: Mike Goldsmith <goldsmith.mike@gmail.com>
  • Loading branch information
@robbkidd @JamieDanielson @MikeGoldsmith
4 people committed Oct 3, 2023
1 parent 9e60273 commit ea0b9ad
Show file tree
Hide file tree
Showing 2 changed files with 133 additions and 38 deletions.
73 changes: 43 additions & 30 deletions handlers/libhoney_event_handler.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
98 changes: 90 additions & 8 deletions handlers/libhoney_event_handler_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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{
Expand All @@ -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",
Expand Down Expand Up @@ -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",
Expand All @@ -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",
Expand Down Expand Up @@ -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",
Expand Down Expand Up @@ -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:
Expand Down

0 comments on commit ea0b9ad

Please sign in to comment.