From aff39e4343b617d689d7067979c52d9c68f671ec Mon Sep 17 00:00:00 2001
From: DevMiner <devminer@devminer.xyz>
Date: Wed, 31 Jul 2024 17:06:27 +0200
Subject: [PATCH] refactor(reqlog): print for request and response individually

---
 request_logger.go | 149 ++++++++++++++++++++++++++++------------------
 1 file changed, 92 insertions(+), 57 deletions(-)

diff --git a/request_logger.go b/request_logger.go
index 56ad9cf..c00b50a 100644
--- a/request_logger.go
+++ b/request_logger.go
@@ -11,69 +11,95 @@ import (
 	"go.opentelemetry.io/otel/trace"
 )
 
-const requestBufferSize = 1000
+const reqLoggerBufSize = 1000
 
 func RequestLogger(l zerolog.Logger, requestHeaders, responseHeaders bool) fiber.Handler {
 	type request struct {
-		Method          string
-		Path            string
+		Method         string
+		Path           string
+		Start          time.Time
+		RequestHeaders map[string][]string
+		OtelSpanID     *trace.SpanID
+		SentrySpanID   *sentry.SpanID
+	}
+
+	type response struct {
 		Status          int
+		End             time.Time
 		Duration        time.Duration
-		RequestHeaders  map[string][]string
 		ResponseHeaders map[string][]string
 		OtelSpanID      *trace.SpanID
 		SentrySpanID    *sentry.SpanID
 	}
 
-	reqs := make(chan request, requestBufferSize)
+	reqCh := make(chan request, reqLoggerBufSize)
+	resCh := make(chan response, reqLoggerBufSize)
+
+	formatHeaderAttribute := func(t, k string, v []string, i int) string {
+		attr := fmt.Sprintf("%s.headers.%s", t, k)
+
+		if len(v) != 1 {
+			attr = fmt.Sprintf("%s.%d", attr, i)
+		}
+
+		return attr
+	}
 
 	go func() {
 		for {
-			r := <-reqs
+			select {
+			case r := <-reqCh:
+				l2 := l.Trace().
+					Str("method", r.Method).
+					Str("path", r.Path).
+					Time("start", r.Start)
 
-			l2 := l.Trace().
-				Str("method", r.Method).
-				Str("path", r.Path).
-				Int("status", r.Status).
-				Dur("duration", r.Duration)
+				if r.OtelSpanID != nil {
+					l2 = l2.Str("otel_span_id", r.OtelSpanID.String())
+				}
 
-			if r.OtelSpanID != nil {
-				l2 = l2.Str("otel_span_id", r.OtelSpanID.String())
-			}
+				if r.SentrySpanID != nil {
+					l2 = l2.Str("sentry_span_id", r.SentrySpanID.String())
+				}
 
-			if r.SentrySpanID != nil {
-				l2 = l2.Str("sentry_span_id", r.SentrySpanID.String())
-			}
+				if requestHeaders {
+					for k, v := range r.RequestHeaders {
+						for i, vv := range v {
+							attr := formatHeaderAttribute("request", k, v, i)
 
-			if requestHeaders {
-				for k, v := range r.RequestHeaders {
-					for i, vv := range v {
-						attr := fmt.Sprintf("request.headers.%s", k)
-
-						if len(v) != 1 {
-							attr = fmt.Sprintf("%s.%d", attr, i)
+							l2 = l2.Str(attr, vv)
 						}
-
-						l2 = l2.Str(attr, vv)
 					}
 				}
-			}
 
-			if responseHeaders {
-				for k, v := range r.ResponseHeaders {
-					for i, vv := range v {
-						attr := fmt.Sprintf("response.headers.%s", k)
+				l2.Msg("request")
 
-						if len(v) != 1 {
-							attr = fmt.Sprintf("%s.%d", attr, i)
+			case r := <-resCh:
+				l2 := l.Trace().
+					Int("status", r.Status).
+					Time("end", r.End).
+					Dur("duration", r.Duration)
+
+				if r.OtelSpanID != nil {
+					l2 = l2.Str("otel_span_id", r.OtelSpanID.String())
+				}
+
+				if r.SentrySpanID != nil {
+					l2 = l2.Str("sentry_span_id", r.SentrySpanID.String())
+				}
+
+				if responseHeaders {
+					for k, v := range r.ResponseHeaders {
+						for i, vv := range v {
+							attr := formatHeaderAttribute("response", k, v, i)
+
+							l2 = l2.Str(attr, vv)
 						}
-
-						l2 = l2.Str(attr, vv)
 					}
 				}
-			}
 
-			l2.Msg("request")
+				l2.Msg("response")
+			}
 		}
 	}()
 
@@ -88,26 +114,11 @@ func RequestLogger(l zerolog.Logger, requestHeaders, responseHeaders bool) fiber
 			sentrySpanId = &span.SpanID
 		}
 
-		start := time.Now()
-		err := c.Next()
-		duration := time.Since(start)
-
-		status := c.Response().StatusCode()
-
-		if err != nil {
-			if e, ok := err.(*fiber.Error); ok {
-				status = e.Code
-			} else {
-				status = fiber.StatusInternalServerError
-			}
-		}
-
-		// pushing the request to the logger, so we don't block the requests
+		// pushing the request to the logger, so we don't block the handling
 		req := request{
 			Method:       c.Method(),
 			Path:         c.Path(),
-			Status:       status,
-			Duration:     duration,
+			Start:        time.Now(),
 			OtelSpanID:   otelSpanId,
 			SentrySpanID: sentrySpanId,
 		}
@@ -120,17 +131,41 @@ func RequestLogger(l zerolog.Logger, requestHeaders, responseHeaders bool) fiber
 				}
 			}
 		}
+		reqCh <- req
+
+		start := time.Now()
+		err := c.Next()
+		end := time.Now()
+
+		status := c.Response().StatusCode()
+
+		if err != nil {
+			if e, ok := err.(*fiber.Error); ok {
+				status = e.Code
+			} else {
+				status = fiber.StatusInternalServerError
+			}
+		}
+
+		// pushing the response to the logger, so we don't block the handling
+		res := response{
+			Status:       status,
+			End:          end,
+			Duration:     end.Sub(start),
+			OtelSpanID:   otelSpanId,
+			SentrySpanID: sentrySpanId,
+		}
 
 		if responseHeaders {
-			req.ResponseHeaders = make(map[string][]string)
+			res.ResponseHeaders = make(map[string][]string)
 			for k, v := range c.GetRespHeaders() {
 				for _, vv := range v {
-					req.ResponseHeaders[k] = append(req.ResponseHeaders[k], utils.CopyString(vv))
+					res.ResponseHeaders[k] = append(res.ResponseHeaders[k], utils.CopyString(vv))
 				}
 			}
 		}
 
-		reqs <- req
+		resCh <- res
 
 		return err
 	}