Fix server.address field in HTTP logs (#4142)

* Fix server.address field in HTTP logs, fix request log condition

Author: michel-laterman

changelog/fragments/1732279064-Fix-server.address-field-in-HTTP-logs.yaml

@@ -0,0 +1,32 @@
+# Kind can be one of:
+# - breaking-change: a change to previously-documented behavior
+# - deprecation: functionality that is being removed in a later release
+# - bug-fix: fixes a problem in a previous version
+# - enhancement: extends functionality but does not break or fix existing behavior
+# - feature: new functionality
+# - known-issue: problems that we are aware of in a given version
+# - security: impacts on the security of a product or a user’s deployment.
+# - upgrade: important information for someone upgrading from a prior version
+# - other: does not fit into any of the other categories
+kind: bug-fix
+
+# Change summary; a 80ish characters long description of the change.
+summary: Fix server.address field in HTTP logs
+
+# Long description; in case the summary is not enough to describe the change
+# this field accommodate a description without length limits.
+# NOTE: This field will be rendered only for breaking-change and known-issue kinds at the moment.
+#description:
+
+# Affected component; usually one of "elastic-agent", "fleet-server", "filebeat", "metricbeat", "auditbeat", "all", etc.
+component: fleet-server
+
+# PR URL; optional; the PR number that added the changeset.
+# If not present is automatically filled by the tooling finding the PR where this changelog fragment has been added.
+# NOTE: the tooling supports backports, so it's able to fill the original PR number instead of the backport PR number.
+# Please provide it if you are adding a fragment for a different PR.
+#pr: https://github.com/owner/repo/1234
+
+# Issue URL; optional; the GitHub issue related to this changeset (either closes or is part of).
+# If not present is automatically filled by the tooling with the issue linked to the PR number.
+#issue: https://github.com/owner/repo/1234

internal/pkg/logger/http.go

@@ -216,7 +216,11 @@ func Middleware(next http.Handler) http.Handler {
 		w.Header().Set(HeaderRequestID, reqID)
 
 		// get the server bound addr from the req ctx
-		addr, _ := r.Context().Value(http.LocalAddrContextKey).(string)
+		var addr string
+		netAddr, ok := r.Context().Value(http.LocalAddrContextKey).(net.Addr)
+		if ok {
+			addr = netAddr.String()
+		}
 
 		// Add trace correlation fields
 		ctx := r.Context()
@@ -250,13 +254,13 @@ func Middleware(next http.Handler) http.Handler {
 		next.ServeHTTP(wrCounter, r)
 		httpMeta(r, e)
 
-		if zlog.Debug().Enabled() || (wrCounter.statusCode < 200 && wrCounter.statusCode >= 300) {
+		// Write an info level log line for each HTTP request if debug is enabled, or a non-2XX status is returned.
+		if zlog.Debug().Enabled() || (wrCounter.statusCode < 200 || wrCounter.statusCode >= 300) {
 			e.Uint64(ECSHTTPRequestBodyBytes, rdCounter.Count())
 			e.Uint64(ECSHTTPResponseBodyBytes, wrCounter.Count())
 			e.Int(ECSHTTPResponseCode, wrCounter.statusCode)
 			e.Int64(ECSEventDuration, time.Since(start).Nanoseconds())
-
-			e.Msgf("%d HTTP Request", wrCounter.statusCode)
+			e.Msg("HTTP Request")
 		}
 	}
 	return http.HandlerFunc(fn)

internal/pkg/logger/http_test.go

@@ -5,37 +5,55 @@
 package logger
 
 import (
+	"bytes"
 	"context"
+	"encoding/json"
+	"net"
 	"net/http"
 	"net/http/httptest"
 	"testing"
 	"time"
 
+	"github.com/rs/zerolog"
 	"github.com/stretchr/testify/require"
-
-	testlog "github.com/elastic/fleet-server/v7/internal/pkg/testing/log"
 )
 
 func TestMiddleware(t *testing.T) {
-	ctx := testlog.SetLogger(t).WithContext(context.Background())
 	h := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		ts, ok := CtxStartTime(r.Context())
 		require.True(t, ok, "expected context to have start time")
 		require.False(t, ts.Equal(time.Time{}), "expected start time to be non-zero")
 
-		w.WriteHeader(http.StatusOK)
+		w.WriteHeader(http.StatusBadRequest)
 		_, _ = w.Write([]byte(`hello, world`))
 	})
 
-	w := httptest.NewRecorder()
-	req := httptest.NewRequest("GET", "/", nil).WithContext(ctx)
-
-	Middleware(h).ServeHTTP(w, req)
-	res := w.Result()
+	var b bytes.Buffer
+	logger := zerolog.New(&b).Level(zerolog.InfoLevel)
+	ctx := logger.WithContext(context.Background())
+
+	srv := httptest.NewUnstartedServer(Middleware(h))
+	srv.Config.BaseContext = func(_ net.Listener) context.Context {
+		return ctx
+	}
+	srv.Start()
+	defer srv.Close()
+	reqCtx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+	req, err := http.NewRequestWithContext(reqCtx, "GET", srv.URL, nil)
+	require.NoError(t, err)
+
+	res, err := srv.Client().Do(req)
+	require.NoError(t, err)
 	res.Body.Close()
-	require.Equal(t, http.StatusOK, res.StatusCode)
+	require.Equal(t, http.StatusBadRequest, res.StatusCode)
 	_, ok := res.Header[HeaderRequestID]
 	require.True(t, ok, "expected to have a request ID")
-	reqID := req.Header.Get(HeaderRequestID)
-	require.NotEmpty(t, reqID)
+
+	var obj map[string]any
+	err = json.Unmarshal(b.Bytes(), &obj)
+	require.NoError(t, err)
+	v, ok := obj[ECSServerAddress]
+	require.Truef(t, ok, "expected to find key: %s in %v", ECSServerAddress, obj)
+	require.NotEmpty(t, v)
 }