From 770937bbb659f028590269e560afafc8254d68a7 Mon Sep 17 00:00:00 2001 From: Robb Kidd Date: Wed, 30 Aug 2023 14:47:25 -0400 Subject: [PATCH] chore: log when we've got an event where time's gone wobbly (#137) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Which problem is this PR solving? - In service to debugging #114 ## Short description of the changes - added log output to assist debugging what makes an HTTP event appear to have been responded to before the request was sent 😁 --- assemblers/http_reader.go | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/assemblers/http_reader.go b/assemblers/http_reader.go index 41dba9ae..4cebe98c 100644 --- a/assemblers/http_reader.go +++ b/assemblers/http_reader.go @@ -91,12 +91,22 @@ func (h *httpReader) run(wg *sync.WaitGroup) { } func (h *httpReader) processEvent(ident string, entry *entry) { + eventDuration := entry.responseTimestamp.Sub(entry.requestTimestamp) + if eventDuration < 0 { // the response came in before the request? wat? + // logging the weirdness for now so we can debug in environments with production loads + log.Debug(). + Str("ident", ident). + Int64("duration_ns", int64(eventDuration)). + Int64("duration_ms", eventDuration.Milliseconds()). + Msg("Time has gotten weird for this event.") + } + h.parent.events <- HttpEvent{ RequestId: ident, Request: entry.request, Response: entry.response, Timestamp: entry.requestTimestamp, - Duration: entry.responseTimestamp.Sub(entry.requestTimestamp), + Duration: eventDuration, SrcIp: h.srcIp, DstIp: h.dstIp, }