From 6bfb2be1f33cb9588df420e17bb9a1c228e98346 Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Tue, 19 Sep 2023 12:48:51 +0000 Subject: [PATCH 1/2] feat(coderd/httpmw): log start_timestamp for http requests --- coderd/httpmw/logger.go | 13 +++++++++++-- 1 file changed, 11 insertions(+), 2 deletions(-) diff --git a/coderd/httpmw/logger.go b/coderd/httpmw/logger.go index ef0a7560bf4db..589e37c309c18 100644 --- a/coderd/httpmw/logger.go +++ b/coderd/httpmw/logger.go @@ -26,19 +26,28 @@ func Logger(log slog.Logger) func(next http.Handler) http.Handler { slog.F("path", r.URL.Path), slog.F("proto", r.Proto), slog.F("remote_addr", r.RemoteAddr), + // Include the start timestamp in the log so that we have the + // source of truth. There is at least a theoretical chance that + // there can be a delay between `next.ServeHTTP` ending and us + // actually logging the request. This can also be useful when + // filtering logs that started at a certain time (compared to + // trying to compute the value). + slog.F("start_timestamp", start), ) next.ServeHTTP(sw, r) + end := time.Now() + // Don't log successful health check requests. if r.URL.Path == "/api/v2" && sw.Status == http.StatusOK { return } httplog = httplog.With( - slog.F("took", time.Since(start)), + slog.F("took", end.Sub(start)), slog.F("status_code", sw.Status), - slog.F("latency_ms", float64(time.Since(start)/time.Millisecond)), + slog.F("latency_ms", float64(end.Sub(start)/time.Millisecond)), ) // For status codes 400 and higher we From 8869937bb059c45dc04485c3a00d3baec8d5e1cf Mon Sep 17 00:00:00 2001 From: Mathias Fredriksson Date: Tue, 19 Sep 2023 12:59:49 +0000 Subject: [PATCH 2/2] s/_timestamp// --- coderd/httpmw/logger.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/coderd/httpmw/logger.go b/coderd/httpmw/logger.go index 589e37c309c18..79e95cf859d8e 100644 --- a/coderd/httpmw/logger.go +++ b/coderd/httpmw/logger.go @@ -32,7 +32,7 @@ func Logger(log slog.Logger) func(next http.Handler) http.Handler { // actually logging the request. This can also be useful when // filtering logs that started at a certain time (compared to // trying to compute the value). - slog.F("start_timestamp", start), + slog.F("start", start), ) next.ServeHTTP(sw, r)