unitel/request_logger.go

package unitel

import (
	"fmt"
	"time"

	"github.com/getsentry/sentry-go"
	"github.com/gofiber/fiber/v2"
	"github.com/gofiber/fiber/v2/utils"
	"github.com/rs/zerolog"
	"go.opentelemetry.io/otel/trace"
)

const reqLoggerBufSize = 1000

func RequestLogger(l zerolog.Logger, requestHeaders, responseHeaders bool) fiber.Handler {
	type request struct {
		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
		ResponseHeaders map[string][]string
		OtelSpanID      *trace.SpanID
		SentrySpanID    *sentry.SpanID
	}

	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 {
			select {
			case r := <-reqCh:
				l2 := l.Trace().
					Str("method", r.Method).
					Str("path", r.Path).
					Time("start", r.Start)

				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 requestHeaders {
					for k, v := range r.RequestHeaders {
						for i, vv := range v {
							attr := formatHeaderAttribute("request", k, v, i)

							l2 = l2.Str(attr, vv)
						}
					}
				}

				l2.Msg("request")

			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.Msg("response")
			}
		}
	}()

	return func(c *fiber.Ctx) error {
		var otelSpanId *trace.SpanID = nil
		if spanId := trace.SpanContextFromContext(c.UserContext()).SpanID(); spanId.IsValid() {
			otelSpanId = &spanId
		}

		var sentrySpanId *sentry.SpanID = nil
		if span := sentry.SpanFromContext(c.UserContext()); span != nil {
			sentrySpanId = &span.SpanID
		}

		// pushing the request to the logger, so we don't block the handling
		req := request{
			Method:       c.Method(),
			Path:         c.Path(),
			Start:        time.Now(),
			OtelSpanID:   otelSpanId,
			SentrySpanID: sentrySpanId,
		}

		if requestHeaders {
			req.RequestHeaders = make(map[string][]string)
			for k, v := range c.GetReqHeaders() {
				for _, vv := range v {
					req.RequestHeaders[k] = append(req.RequestHeaders[k], utils.CopyString(vv))
				}
			}
		}
		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 {
			res.ResponseHeaders = make(map[string][]string)
			for k, v := range c.GetRespHeaders() {
				for _, vv := range v {
					res.ResponseHeaders[k] = append(res.ResponseHeaders[k], utils.CopyString(vv))
				}
			}
		}

		resCh <- res

		return err
	}
}