diff --git a/changelog/fragments/1732279064-Fix-server.address-field-in-HTTP-logs.yaml b/changelog/fragments/1732279064-Fix-server.address-field-in-HTTP-logs.yaml new file mode 100644 index 000000000..9490d0a87 --- /dev/null +++ b/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 diff --git a/internal/pkg/logger/http.go b/internal/pkg/logger/http.go index d4f79f029..ef3861206 100644 --- a/internal/pkg/logger/http.go +++ b/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) diff --git a/internal/pkg/logger/http_test.go b/internal/pkg/logger/http_test.go index 640c2725c..1f2ede0c8 100644 --- a/internal/pkg/logger/http_test.go +++ b/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) }