Use ECS-compatible format for request logs

internal/server/logging_middleware.go

@@ -2,22 +2,65 @@ package server
 
 import (
 	"bufio"
+	"encoding/json"
 	"errors"
-	"log/slog"
+	"io"
 	"net"
 	"net/http"
+	"strconv"
+	"strings"
 	"time"
 )
 
+type LoggingMiddlewareLine struct {
+	Timestamp string `json:"@timestamp"`
+	Message   string `json:"message"`
+	Client    struct {
+		IP   string `json:"ip"`
+		Port int    `json:"port"`
+	} `json:"client"`
+	Log struct {
+		Level string `json:"level"`
+	} `json:"log"`
+	Event struct {
+		Duration int64 `json:"duration"`
+	} `json:"event"`
+	HTTP struct {
+		Request struct {
+			Method   string `json:"method"`
+			MimeType string `json:"mime_type"`
+			Body     struct {
+				Bytes int64 `json:"bytes"`
+			} `json:"body"`
+		} `json:"request"`
+		Response struct {
+			StatusCode int    `json:"status_code"`
+			MimeType   string `json:"mime_type"`
+			Body       struct {
+				Bytes int64 `json:"bytes"`
+			} `json:"body"`
+		} `json:"response"`
+	} `json:"http"`
+	URL struct {
+		Domain string `json:"domain"`
+		Path   string `json:"path"`
+		Query  string `json:"query"`
+		Scheme string `json:"scheme"`
+	} `json:"url"`
+	UserAgent struct {
+		Original string `json:"original"`
+	} `json:"user_agent"`
+}
+
 type LoggingMiddleware struct {
-	logger *slog.Logger
-	next   http.Handler
+	encoder *json.Encoder
+	next    http.Handler
 }
 
-func NewLoggingMiddleware(logger *slog.Logger, next http.Handler) *LoggingMiddleware {
+func NewLoggingMiddleware(w io.Writer, next http.Handler) *LoggingMiddleware {
 	return &LoggingMiddleware{
-		logger: logger,
-		next:   next,
+		encoder: json.NewEncoder(w),
+		next:    next,
 	}
 }
 
@@ -31,23 +74,52 @@ func (h *LoggingMiddleware) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	userAgent := r.Header.Get("User-Agent")
 	reqContent := r.Header.Get("Content-Type")
 	respContent := writer.Header().Get("Content-Type")
-	remoteAddr := r.Header.Get("X-Forwarded-For")
-	if remoteAddr == "" {
-		remoteAddr = r.RemoteAddr
+
+	clientIP, clientPort := h.determineClientIPAndPort(r)
+
+	line := LoggingMiddlewareLine{
+		Timestamp: started.Format(time.RFC3339),
+		Message:   "Request",
+	}
+
+	line.Log.Level = "INFO"
+	line.Client.IP = clientIP
+	line.Client.Port = clientPort
+	line.Event.Duration = elapsed.Nanoseconds()
+	line.HTTP.Request.Body.Bytes = r.ContentLength
+	line.HTTP.Request.Method = r.Method
+	line.HTTP.Request.MimeType = reqContent
+	line.HTTP.Response.Body.Bytes = writer.bytesWritten
+	line.HTTP.Response.MimeType = respContent
+	line.HTTP.Response.StatusCode = writer.statusCode
+	line.URL.Domain = r.Host
+	line.URL.Path = r.URL.Path
+	line.URL.Query = r.URL.RawQuery
+	line.URL.Scheme = r.URL.Scheme
+
+	line.UserAgent.Original = userAgent
+
+	h.encoder.Encode(line)
+}
+
+func (h *LoggingMiddleware) determineClientIPAndPort(r *http.Request) (string, int) {
+	ip, portStr, err := net.SplitHostPort(r.RemoteAddr)
+	if err != nil {
+		portStr = "0"
+	}
+
+	port, err := strconv.Atoi(portStr)
+	if err != nil {
+		port = 0
+	}
+
+	forwardedIP := strings.Split(r.Header.Get("X-Forwarded-For"), ",")[0]
+
+	if forwardedIP != "" {
+		return forwardedIP, port
 	}
 
-	h.logger.Info("Request",
-		"path", r.URL.Path,
-		"status", writer.statusCode,
-		"dur", elapsed.Milliseconds(),
-		"method", r.Method,
-		"req_content_length", r.ContentLength,
-		"req_content_type", reqContent,
-		"resp_content_length", writer.bytesWritten,
-		"resp_content_type", respContent,
-		"remote_addr", remoteAddr,
-		"user_agent", userAgent,
-		"query", r.URL.RawQuery)
+	return ip, port
 }
 
 type responseWriter struct {

internal/server/logging_middleware_test.go

@@ -4,7 +4,6 @@ import (
 	"bytes"
 	"encoding/json"
 	"fmt"
-	"log/slog"
 	"net/http"
 	"net/http/httptest"
 	"strings"
@@ -16,44 +15,41 @@ import (
 
 func TestMiddleware_LoggingMiddleware(t *testing.T) {
 	out := &strings.Builder{}
-	logger := slog.New(slog.NewJSONHandler(out, nil))
-	middleware := NewLoggingMiddleware(logger, http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+	middleware := NewLoggingMiddleware(out, http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		w.Header().Set("Content-Type", "text/html")
 		w.WriteHeader(http.StatusCreated)
 		fmt.Fprintln(w, "goodbye")
 	}))
 
-	req := httptest.NewRequest("POST", "/somepath?q=ok", bytes.NewReader([]byte("hello")))
-	req.Header.Set("X-Forwarded-For", "192.168.1.1")
+	req := httptest.NewRequest("POST", "http://example.com/somepath?q=ok", bytes.NewReader([]byte("hello")))
+	req.Header.Set("X-Forwarded-For", "192.168.1.1, 10.1.1.1")
 	req.Header.Set("User-Agent", "Robot/1")
 	req.Header.Set("Content-Type", "application/json")
 
 	middleware.ServeHTTP(httptest.NewRecorder(), req)
 
-	logline := struct {
-		Path              string `json:"path"`
-		Method            string `json:"method"`
-		Status            int    `json:"status"`
-		RemoteAddr        string `json:"remote_addr"`
-		UserAgent         string `json:"user_agent"`
-		ReqContentLength  int64  `json:"req_content_length"`
-		ReqContentType    string `json:"req_content_type"`
-		RespContentLength int64  `json:"resp_content_length"`
-		RespContentType   string `json:"resp_content_type"`
-		Query             string `json:"query"`
-	}{}
+	var logline LoggingMiddlewareLine
 
 	err := json.NewDecoder(strings.NewReader(out.String())).Decode(&logline)
 	require.NoError(t, err)
 
-	assert.Equal(t, "/somepath", logline.Path)
-	assert.Equal(t, "POST", logline.Method)
-	assert.Equal(t, http.StatusCreated, logline.Status)
-	assert.Equal(t, "192.168.1.1", logline.RemoteAddr)
-	assert.Equal(t, "Robot/1", logline.UserAgent)
-	assert.Equal(t, "application/json", logline.ReqContentType)
-	assert.Equal(t, "text/html", logline.RespContentType)
-	assert.Equal(t, "q=ok", logline.Query)
-	assert.Equal(t, int64(5), logline.ReqContentLength)
-	assert.Equal(t, int64(8), logline.RespContentLength)
+	assert.Equal(t, "Request", logline.Message)
+	assert.Equal(t, "INFO", logline.Log.Level)
+
+	assert.Equal(t, "http", logline.URL.Scheme)
+	assert.Equal(t, "example.com", logline.URL.Domain)
+	assert.Equal(t, "/somepath", logline.URL.Path)
+	assert.Equal(t, "q=ok", logline.URL.Query)
+	assert.Equal(t, "Robot/1", logline.UserAgent.Original)
+
+	assert.Equal(t, "192.168.1.1", logline.Client.IP)
+	assert.Equal(t, 1234, logline.Client.Port)
+
+	assert.Equal(t, "POST", logline.HTTP.Request.Method)
+	assert.Equal(t, "application/json", logline.HTTP.Request.MimeType)
+	assert.Equal(t, int64(5), logline.HTTP.Request.Body.Bytes)
+
+	assert.Equal(t, http.StatusCreated, logline.HTTP.Response.StatusCode)
+	assert.Equal(t, "text/html", logline.HTTP.Response.MimeType)
+	assert.Equal(t, int64(8), logline.HTTP.Response.Body.Bytes)
 }

internal/server/server.go

@@ -7,6 +7,7 @@ import (
 	"fmt"
 	"log/slog"
 	"net/http"
+	"os"
 	"time"
 
 	"golang.org/x/crypto/acme"
@@ -85,5 +86,5 @@ func (s *Server) startCommandHandler() {
 }
 
 func (s *Server) buildHandler() http.Handler {
-	return NewLoggingMiddleware(slog.Default(), s.router)
+	return NewLoggingMiddleware(os.Stdout, s.router)
 }