From def43cd9cac72247d7370dad08771e1b4bffebef Mon Sep 17 00:00:00 2001 From: Rein Krul Date: Mon, 8 Jun 2026 12:06:48 +0200 Subject: [PATCH 1/4] feat(http): add http.client.log for logging outgoing HTTP requests Adds a configurable log level for outgoing HTTP requests/responses made by the node, mirroring http.log for incoming traffic. Reuses the existing http.LogLevel enum (nothing/metadata/metadata-and-body) and defaults to nothing. Wired up in http.configureClient() via a transport-wrapping hook on the http client package. Assisted by AI --- docs/pages/deployment/server_options.rst | 3 +- http/client/client.go | 15 ++- http/clientlogger.go | 83 +++++++++++++ http/clientlogger_test.go | 152 +++++++++++++++++++++++ http/cmd/cmd.go | 1 + http/config.go | 10 ++ http/engine.go | 7 ++ http/engine_test.go | 39 ++++++ 8 files changed, 306 insertions(+), 4 deletions(-) create mode 100644 http/clientlogger.go create mode 100644 http/clientlogger_test.go diff --git a/docs/pages/deployment/server_options.rst b/docs/pages/deployment/server_options.rst index e6c5f3d304..21d1ba7c91 100755 --- a/docs/pages/deployment/server_options.rst +++ b/docs/pages/deployment/server_options.rst @@ -36,6 +36,7 @@ http.clientipheader X-Forwarded-For Case-sensitive HTTP Header that contains the client IP used for audit logs. For the X-Forwarded-For header only link-local, loopback, and private IPs are excluded. Switch to X-Real-IP or a custom header if you see your own proxy/infra in the logs. http.log metadata What to log about HTTP requests. Options are 'nothing', 'metadata' (log request method, URI, IP and response code), and 'metadata-and-body' (log the request and response body, in addition to the metadata). When debug vebosity is set the authorization headers are also logged when the request is fully logged. http.cache.maxbytes 10485760 HTTP client maximum size of the response cache in bytes. If 0, the HTTP client does not cache responses. + http.client.log nothing What to log about outgoing HTTP requests made by the node. Options are 'nothing', 'metadata' (log request method, URI and response code), and 'metadata-and-body' (log the request and response body, in addition to the metadata). When debug vebosity is set the request and response headers are also logged. http.internal.address 127.0.0.1:8081 Address and port the server will be listening to for internal-facing endpoints. http.internal.auth.audience Expected audience for JWT tokens (default: hostname) http.internal.auth.authorizedkeyspath Path to an authorized_keys file for trusted JWT signers @@ -70,5 +71,5 @@ tracing.servicename Service name reported to the tracing backend. Defaults to 'nuts-node'. **policy** policy.directory ./config/policy Directory to read policy files from. Policy files are JSON files that contain a scope to PresentationDefinition mapping. - policy.authzen.endpoint Base URL of the AuthZen PDP endpoint. Required when any credential profile uses scope_policy 'dynamic'. + policy.authzen.endpoint Base URL of the AuthZen PDP endpoint. Required when any credential profile uses scope_policy 'dynamic'; the node refuses to start if such a profile is configured but this flag is empty. ======================================== =================================================================================================================================================================================================================================================================================================================================================================================================================================================================== ============================================================================================================================================================================================================================================================================================================================================ diff --git a/http/client/client.go b/http/client/client.go index 2c9e4308df..8857c1317f 100644 --- a/http/client/client.go +++ b/http/client/client.go @@ -55,6 +55,10 @@ func httpSpanName(_ string, r *http.Request) string { // StrictMode is a flag that can be set to true to enable strict mode for the HTTP client. var StrictMode bool +// RequestLogger, when set, wraps the transport of every HTTP client created by this package to log +// outgoing requests and their responses. It is left nil (no logging) by default. +var RequestLogger func(http.RoundTripper) http.RoundTripper + // DefaultMaxHttpResponseSize is a default maximum size of an HTTP response body that will be read. // Very large or unbounded HTTP responses can cause denial-of-service, so it's good to limit how much data is read. // This of course heavily depends on the use case, but 1MB is a reasonable default. @@ -81,15 +85,20 @@ func New(timeout time.Duration) *StrictHTTPClient { } } -// getTransport wraps the given transport with OpenTelemetry instrumentation if tracing is enabled. +// getTransport wraps the given transport with request logging (if enabled) and OpenTelemetry +// instrumentation (if tracing is enabled). func getTransport(base http.RoundTripper) http.RoundTripper { + transport := base + if RequestLogger != nil { + transport = RequestLogger(transport) + } if tracing.Enabled() { - return otelhttp.NewTransport(base, + return otelhttp.NewTransport(transport, otelhttp.WithSpanNameFormatter(httpSpanName), otelhttp.WithTracerProvider(tracing.GetTracerProvider()), ) } - return base + return transport } // NewWithCache creates a new HTTP client with the given timeout. diff --git a/http/clientlogger.go b/http/clientlogger.go new file mode 100644 index 0000000000..33d55c6734 --- /dev/null +++ b/http/clientlogger.go @@ -0,0 +1,83 @@ +/* + * Copyright (C) 2024 Nuts community + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with this program. If not, see . + * + */ + +package http + +import ( + "bytes" + "io" + "net/http" + + "github.com/sirupsen/logrus" +) + +// clientRequestLogger is an http.RoundTripper that logs outgoing HTTP requests and their responses. +// It mirrors the server-side request/body logging: metadata is always logged, bodies only when logBody is set. +type clientRequestLogger struct { + transport http.RoundTripper + logger *logrus.Entry + logBody bool +} + +func (c *clientRequestLogger) RoundTrip(request *http.Request) (*http.Response, error) { + fields := logrus.Fields{ + "method": request.Method, + "uri": request.URL.String(), + } + if c.logger.Logger.Level >= logrus.DebugLevel { + fields["headers"] = request.Header + } + c.logger.WithFields(fields).Info("HTTP client request") + + if c.logBody && request.Body != nil && isLoggableContentType(request.Header.Get("Content-Type")) { + body, err := io.ReadAll(request.Body) + _ = request.Body.Close() + if err != nil { + return nil, err + } + request.Body = io.NopCloser(bytes.NewReader(body)) + c.logger.Infof("HTTP client request body: %s", string(body)) + } + + response, err := c.transport.RoundTrip(request) + if err != nil { + c.logger.WithFields(logrus.Fields{ + "method": request.Method, + "uri": request.URL.String(), + }).WithError(err).Info("HTTP client request failed") + return nil, err + } + + c.logger.WithFields(logrus.Fields{ + "method": request.Method, + "uri": request.URL.String(), + "status": response.StatusCode, + }).Info("HTTP client response") + + if c.logBody && response.Body != nil && isLoggableContentType(response.Header.Get("Content-Type")) { + body, err := io.ReadAll(response.Body) + _ = response.Body.Close() + if err != nil { + return nil, err + } + response.Body = io.NopCloser(bytes.NewReader(body)) + c.logger.Infof("HTTP client response body: %s", string(body)) + } + + return response, nil +} diff --git a/http/clientlogger_test.go b/http/clientlogger_test.go new file mode 100644 index 0000000000..b71260fc31 --- /dev/null +++ b/http/clientlogger_test.go @@ -0,0 +1,152 @@ +/* + * Copyright (C) 2024 Nuts community + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with this program. If not, see . + * + */ + +package http + +import ( + "errors" + "io" + "net/http" + "strings" + "testing" + + "github.com/sirupsen/logrus" + "github.com/sirupsen/logrus/hooks/test" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// roundTripperFunc adapts a function to an http.RoundTripper. +type roundTripperFunc func(*http.Request) (*http.Response, error) + +func (f roundTripperFunc) RoundTrip(r *http.Request) (*http.Response, error) { + return f(r) +} + +func Test_clientRequestLogger(t *testing.T) { + newRequest := func(t *testing.T, body string) *http.Request { + req, err := http.NewRequest(http.MethodPost, "https://example.com/foo", strings.NewReader(body)) + require.NoError(t, err) + req.Header.Set("Content-Type", "application/json") + return req + } + jsonResponse := func(body string) *http.Response { + header := http.Header{} + header.Set("Content-Type", "application/json") + return &http.Response{ + StatusCode: http.StatusOK, + Header: header, + Body: io.NopCloser(strings.NewReader(body)), + } + } + + t.Run("metadata only", func(t *testing.T) { + logger, hook := test.NewNullLogger() + transport := roundTripperFunc(func(r *http.Request) (*http.Response, error) { + return jsonResponse(`{"hello":"world"}`), nil + }) + sut := &clientRequestLogger{transport: transport, logger: logger.WithFields(logrus.Fields{}), logBody: false} + + response, err := sut.RoundTrip(newRequest(t, `{"foo":"bar"}`)) + + require.NoError(t, err) + // Body is left intact for the caller + responseBody, _ := io.ReadAll(response.Body) + assert.Equal(t, `{"hello":"world"}`, string(responseBody)) + // Only request and response metadata is logged, no bodies + require.Len(t, hook.Entries, 2) + assert.Equal(t, "HTTP client request", hook.Entries[0].Message) + assert.Equal(t, http.MethodPost, hook.Entries[0].Data["method"]) + assert.Equal(t, "https://example.com/foo", hook.Entries[0].Data["uri"]) + assert.Equal(t, "HTTP client response", hook.Entries[1].Message) + assert.Equal(t, http.StatusOK, hook.Entries[1].Data["status"]) + }) + + t.Run("metadata and body", func(t *testing.T) { + logger, hook := test.NewNullLogger() + var sentBody string + transport := roundTripperFunc(func(r *http.Request) (*http.Response, error) { + // Request body must still be readable by the actual transport + b, _ := io.ReadAll(r.Body) + sentBody = string(b) + return jsonResponse(`{"hello":"world"}`), nil + }) + sut := &clientRequestLogger{transport: transport, logger: logger.WithFields(logrus.Fields{}), logBody: true} + + response, err := sut.RoundTrip(newRequest(t, `{"foo":"bar"}`)) + + require.NoError(t, err) + assert.Equal(t, `{"foo":"bar"}`, sentBody) + responseBody, _ := io.ReadAll(response.Body) + assert.Equal(t, `{"hello":"world"}`, string(responseBody)) + require.Len(t, hook.Entries, 4) + assert.Equal(t, "HTTP client request", hook.Entries[0].Message) + assert.Equal(t, "HTTP client request body: {\"foo\":\"bar\"}", hook.Entries[1].Message) + assert.Equal(t, "HTTP client response", hook.Entries[2].Message) + assert.Equal(t, "HTTP client response body: {\"hello\":\"world\"}", hook.Entries[3].Message) + }) + + t.Run("body not logged for non-loggable content type", func(t *testing.T) { + logger, hook := test.NewNullLogger() + transport := roundTripperFunc(func(r *http.Request) (*http.Response, error) { + header := http.Header{} + header.Set("Content-Type", "application/octet-stream") + return &http.Response{StatusCode: http.StatusOK, Header: header, Body: io.NopCloser(strings.NewReader("binary"))}, nil + }) + req := newRequest(t, "binary") + req.Header.Set("Content-Type", "application/octet-stream") + sut := &clientRequestLogger{transport: transport, logger: logger.WithFields(logrus.Fields{}), logBody: true} + + _, err := sut.RoundTrip(req) + + require.NoError(t, err) + // Only metadata is logged + require.Len(t, hook.Entries, 2) + assert.Equal(t, "HTTP client request", hook.Entries[0].Message) + assert.Equal(t, "HTTP client response", hook.Entries[1].Message) + }) + + t.Run("debug level logs headers", func(t *testing.T) { + logger, hook := test.NewNullLogger() + logger.SetLevel(logrus.DebugLevel) + transport := roundTripperFunc(func(r *http.Request) (*http.Response, error) { + return jsonResponse(`{}`), nil + }) + sut := &clientRequestLogger{transport: transport, logger: logger.WithFields(logrus.Fields{}), logBody: false} + + _, err := sut.RoundTrip(newRequest(t, "")) + + require.NoError(t, err) + assert.Contains(t, hook.Entries[0].Data, "headers") + }) + + t.Run("transport error is logged and returned", func(t *testing.T) { + logger, hook := test.NewNullLogger() + transport := roundTripperFunc(func(r *http.Request) (*http.Response, error) { + return nil, errors.New("connection refused") + }) + sut := &clientRequestLogger{transport: transport, logger: logger.WithFields(logrus.Fields{}), logBody: false} + + _, err := sut.RoundTrip(newRequest(t, "")) + + require.Error(t, err) + require.Len(t, hook.Entries, 2) + assert.Equal(t, "HTTP client request", hook.Entries[0].Message) + assert.Equal(t, "HTTP client request failed", hook.Entries[1].Message) + }) +} diff --git a/http/cmd/cmd.go b/http/cmd/cmd.go index 1721738ebc..0f7caf9af9 100644 --- a/http/cmd/cmd.go +++ b/http/cmd/cmd.go @@ -35,6 +35,7 @@ func FlagSet() *pflag.FlagSet { flags.String("http.internal.auth.audience", defs.Internal.Auth.Audience, "Expected audience for JWT tokens (default: hostname)") flags.String("http.internal.auth.authorizedkeyspath", defs.Internal.Auth.AuthorizedKeysPath, "Path to an authorized_keys file for trusted JWT signers") flags.String("http.log", string(defs.Log), fmt.Sprintf("What to log about HTTP requests. Options are '%s', '%s' (log request method, URI, IP and response code), and '%s' (log the request and response body, in addition to the metadata). When debug vebosity is set the authorization headers are also logged when the request is fully logged.", http.LogNothingLevel, http.LogMetadataLevel, http.LogMetadataAndBodyLevel)) + flags.String("http.client.log", string(defs.Client.Log), fmt.Sprintf("What to log about outgoing HTTP requests made by the node. Options are '%s', '%s' (log request method, URI and response code), and '%s' (log the request and response body, in addition to the metadata). When debug vebosity is set the request and response headers are also logged.", http.LogNothingLevel, http.LogMetadataLevel, http.LogMetadataAndBodyLevel)) flags.String("http.clientipheader", defs.ClientIPHeaderName, "Case-sensitive HTTP Header that contains the client IP used for audit logs. For the X-Forwarded-For header only link-local, loopback, and private IPs are excluded. Switch to X-Real-IP or a custom header if you see your own proxy/infra in the logs.") flags.Int("http.cache.maxbytes", defs.ResponseCacheSize, "HTTP client maximum size of the response cache in bytes. If 0, the HTTP client does not cache responses.") diff --git a/http/config.go b/http/config.go index 35cd5d7477..a95e6cb6a3 100644 --- a/http/config.go +++ b/http/config.go @@ -22,6 +22,9 @@ package http func DefaultConfig() Config { return Config{ Log: LogMetadataLevel, + Client: ClientConfig{ + Log: LogNothingLevel, + }, Internal: InternalConfig{ Address: "127.0.0.1:8081", }, @@ -37,6 +40,7 @@ func DefaultConfig() Config { type Config struct { // Log specifies what should be logged of HTTP requests. Log LogLevel `koanf:"log"` + Client ClientConfig `koanf:"client"` Public PublicConfig `koanf:"public"` Internal InternalConfig `koanf:"internal"` // ResponseCacheSize is the maximum number of bytes cached by HTTP clients. @@ -44,6 +48,12 @@ type Config struct { ClientIPHeaderName string `koanf:"clientipheader"` } +// ClientConfig contains the configuration for outgoing HTTP requests made by the node. +type ClientConfig struct { + // Log specifies what should be logged of outgoing HTTP requests. + Log LogLevel `koanf:"log"` +} + // PublicConfig contains the configuration for outside-facing HTTP endpoints. type PublicConfig struct { // Address holds the interface address the HTTP service must be bound to, in the format of `interface:port` (e.g. localhost:5555). diff --git a/http/engine.go b/http/engine.go index d2c1533056..b5e477f164 100644 --- a/http/engine.go +++ b/http/engine.go @@ -100,6 +100,13 @@ func (h *Engine) Configure(serverConfig core.ServerConfig) error { func (h *Engine) configureClient(serverConfig core.ServerConfig) { client.StrictMode = serverConfig.Strictmode + // Configure logging of outgoing HTTP requests/responses, if enabled. + if h.config.Client.Log != LogNothingLevel { + logBody := h.config.Client.Log == LogMetadataAndBodyLevel + client.RequestLogger = func(transport http.RoundTripper) http.RoundTripper { + return &clientRequestLogger{transport: transport, logger: log.Logger(), logBody: logBody} + } + } // Configure the HTTP caching client, if enabled. Set it to http.DefaultTransport so it can be used by any subsystem. if h.config.ResponseCacheSize > 0 { client.DefaultCachingTransport = client.NewCachingTransport(client.SafeHttpTransport, h.config.ResponseCacheSize) diff --git a/http/engine_test.go b/http/engine_test.go index 31d36d5e11..fe2f8cd86f 100644 --- a/http/engine_test.go +++ b/http/engine_test.go @@ -36,6 +36,7 @@ import ( "github.com/lestrrat-go/jwx/v2/jwk" "github.com/lestrrat-go/jwx/v2/jwt" "github.com/nuts-foundation/nuts-node/core" + "github.com/nuts-foundation/nuts-node/http/client" "github.com/nuts-foundation/nuts-node/http/log" "github.com/nuts-foundation/nuts-node/test" "github.com/sirupsen/logrus" @@ -243,6 +244,44 @@ func TestEngine_Configure(t *testing.T) { }) } +func TestEngine_configureClient(t *testing.T) { + t.Run("logging disabled by default", func(t *testing.T) { + client.RequestLogger = nil + t.Cleanup(func() { client.RequestLogger = nil }) + engine := New(func() {}, nil) + + engine.configureClient(*core.NewServerConfig()) + + assert.Nil(t, client.RequestLogger) + }) + t.Run("logging enabled", func(t *testing.T) { + client.RequestLogger = nil + t.Cleanup(func() { client.RequestLogger = nil }) + engine := New(func() {}, nil) + engine.config.Client.Log = LogMetadataAndBodyLevel + + engine.configureClient(*core.NewServerConfig()) + + require.NotNil(t, client.RequestLogger) + wrapped := client.RequestLogger(http.DefaultTransport) + logger, ok := wrapped.(*clientRequestLogger) + require.True(t, ok) + assert.True(t, logger.logBody) + }) + t.Run("metadata only does not log bodies", func(t *testing.T) { + client.RequestLogger = nil + t.Cleanup(func() { client.RequestLogger = nil }) + engine := New(func() {}, nil) + engine.config.Client.Log = LogMetadataLevel + + engine.configureClient(*core.NewServerConfig()) + + require.NotNil(t, client.RequestLogger) + logger := client.RequestLogger(http.DefaultTransport).(*clientRequestLogger) + assert.False(t, logger.logBody) + }) +} + func TestEngine_LoggingMiddleware(t *testing.T) { output := new(bytes.Buffer) logrus.StandardLogger().AddHook(&writer.Hook{ From 80f0cda59b0dd1483fa07452daa1b8a7f43688fe Mon Sep 17 00:00:00 2001 From: Rein Krul Date: Mon, 8 Jun 2026 14:37:09 +0200 Subject: [PATCH 2/4] fix(http): apply client request logging at request time The logging transport wrapper was decided when the HTTP client was created. Engines that build their clients before the HTTP engine is configured (e.g. auth's OpenID4VCI client) never got the wrapper, since client.RequestLogger was still nil at construction. The HTTP engine is registered/configured last, so http.client.log had no effect on those clients. Always install a thin loggingTransport indirection in getTransport that reads RequestLogger per request, mirroring how StrictMode is read at request time. Clients created before logging is configured now log. Assisted by AI --- http/client/client.go | 26 ++++++++++++++++------ http/client/client_test.go | 44 ++++++++++++++++++++++++++++++++++---- 2 files changed, 60 insertions(+), 10 deletions(-) diff --git a/http/client/client.go b/http/client/client.go index 8857c1317f..b0fdee0ce4 100644 --- a/http/client/client.go +++ b/http/client/client.go @@ -55,8 +55,11 @@ func httpSpanName(_ string, r *http.Request) string { // StrictMode is a flag that can be set to true to enable strict mode for the HTTP client. var StrictMode bool -// RequestLogger, when set, wraps the transport of every HTTP client created by this package to log +// RequestLogger wraps the transport of HTTP clients created by this package to log // outgoing requests and their responses. It is left nil (no logging) by default. +// It is read at request time (not when the client is created), because clients are often created +// before the HTTP engine configures it: the HTTP engine is configured last, while other engines +// create their HTTP clients earlier. var RequestLogger func(http.RoundTripper) http.RoundTripper // DefaultMaxHttpResponseSize is a default maximum size of an HTTP response body that will be read. @@ -85,13 +88,12 @@ func New(timeout time.Duration) *StrictHTTPClient { } } -// getTransport wraps the given transport with request logging (if enabled) and OpenTelemetry +// getTransport wraps the given transport with request logging and OpenTelemetry // instrumentation (if tracing is enabled). func getTransport(base http.RoundTripper) http.RoundTripper { - transport := base - if RequestLogger != nil { - transport = RequestLogger(transport) - } + // Always install the logging indirection so RequestLogger can be configured after the client + // is created: whether to log is decided per request, not when the client is created. + transport := http.RoundTripper(&loggingTransport{base: base}) if tracing.Enabled() { return otelhttp.NewTransport(transport, otelhttp.WithSpanNameFormatter(httpSpanName), @@ -101,6 +103,18 @@ func getTransport(base http.RoundTripper) http.RoundTripper { return transport } +// loggingTransport applies the configured RequestLogger (if any) at request time. +type loggingTransport struct { + base http.RoundTripper +} + +func (l *loggingTransport) RoundTrip(request *http.Request) (*http.Response, error) { + if logger := RequestLogger; logger != nil { + return logger(l.base).RoundTrip(request) + } + return l.base.RoundTrip(request) +} + // NewWithCache creates a new HTTP client with the given timeout. // It uses the DefaultCachingTransport as the underlying transport. func NewWithCache(timeout time.Duration) *StrictHTTPClient { diff --git a/http/client/client_test.go b/http/client/client_test.go index 1a1b01366c..0564ff39be 100644 --- a/http/client/client_test.go +++ b/http/client/client_test.go @@ -81,7 +81,7 @@ func TestStrictHTTPClient(t *testing.T) { client := NewWithTLSConfig(time.Second, &tls.Config{ InsecureSkipVerify: true, }) - ts := client.client.Transport.(*http.Transport) + ts := client.client.Transport.(*loggingTransport).base.(*http.Transport) assert.True(t, ts.TLSClientConfig.InsecureSkipVerify) }) }) @@ -215,14 +215,16 @@ func TestGetTransport(t *testing.T) { assert.NotEqual(t, SafeHttpTransport, transport) }) - t.Run("returns base transport when tracing disabled", func(t *testing.T) { + t.Run("wraps base in logging transport when tracing disabled", func(t *testing.T) { original := tracing.Enabled() tracing.SetEnabled(false) t.Cleanup(func() { tracing.SetEnabled(original) }) transport := getTransport(SafeHttpTransport) - assert.Equal(t, SafeHttpTransport, transport) + logging, ok := transport.(*loggingTransport) + require.True(t, ok) + assert.Equal(t, SafeHttpTransport, logging.base) }) } @@ -245,6 +247,40 @@ func TestNew(t *testing.T) { client := New(time.Second) - assert.Equal(t, SafeHttpTransport, client.client.Transport) + logging, ok := client.client.Transport.(*loggingTransport) + require.True(t, ok) + assert.Equal(t, SafeHttpTransport, logging.base) }) } + +func TestRequestLogger_setAfterClientCreation(t *testing.T) { + // Clients are created before the HTTP engine sets RequestLogger, so logging must take effect + // for clients that already exist when RequestLogger is configured. + originalTracing := tracing.Enabled() + tracing.SetEnabled(false) + t.Cleanup(func() { tracing.SetEnabled(originalTracing) }) + t.Cleanup(func() { RequestLogger = nil }) + StrictMode = false + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + })) + t.Cleanup(server.Close) + + // Create the client first, while RequestLogger is still nil. + RequestLogger = nil + client := New(time.Second) + + // Now configure the logger, as the HTTP engine does later during startup. + var invoked atomic.Bool + RequestLogger = func(base http.RoundTripper) http.RoundTripper { + invoked.Store(true) + return base + } + + httpRequest, _ := http.NewRequest(http.MethodGet, server.URL, nil) + _, err := client.Do(httpRequest) + + require.NoError(t, err) + assert.True(t, invoked.Load(), "RequestLogger should be applied to clients created before it was set") +} From 8da80e0334bb2ad3e7d480cf6c8ce209f3f38295 Mon Sep 17 00:00:00 2001 From: Rein Krul Date: Mon, 8 Jun 2026 16:20:11 +0200 Subject: [PATCH 3/4] refactor(http): simplify http.client.log header logging Make the log level the single control instead of also depending on the global debug verbosity: - Log request and response headers at both 'metadata' and 'metadata-and-body' (previously headers required debug verbosity). - Mask credential-bearing request headers (Authorization, Proxy-Authorization) so they don't leak into the logs. Response WWW-Authenticate is a challenge, not a credential, so it is not masked. Assisted by AI --- docs/pages/deployment/server_options.rst | 2 +- http/clientlogger.go | 45 +++++++++++++++++------- http/clientlogger_test.go | 42 ++++++++++++++-------- http/cmd/cmd.go | 3 +- 4 files changed, 63 insertions(+), 29 deletions(-) diff --git a/docs/pages/deployment/server_options.rst b/docs/pages/deployment/server_options.rst index 21d1ba7c91..e7904a6982 100755 --- a/docs/pages/deployment/server_options.rst +++ b/docs/pages/deployment/server_options.rst @@ -36,7 +36,7 @@ http.clientipheader X-Forwarded-For Case-sensitive HTTP Header that contains the client IP used for audit logs. For the X-Forwarded-For header only link-local, loopback, and private IPs are excluded. Switch to X-Real-IP or a custom header if you see your own proxy/infra in the logs. http.log metadata What to log about HTTP requests. Options are 'nothing', 'metadata' (log request method, URI, IP and response code), and 'metadata-and-body' (log the request and response body, in addition to the metadata). When debug vebosity is set the authorization headers are also logged when the request is fully logged. http.cache.maxbytes 10485760 HTTP client maximum size of the response cache in bytes. If 0, the HTTP client does not cache responses. - http.client.log nothing What to log about outgoing HTTP requests made by the node. Options are 'nothing', 'metadata' (log request method, URI and response code), and 'metadata-and-body' (log the request and response body, in addition to the metadata). When debug vebosity is set the request and response headers are also logged. + http.client.log nothing What to log about outgoing HTTP requests made by the node. Options are 'nothing', 'metadata' (log request/response method, URI, status and headers), and 'metadata-and-body' (also log the request/response body). Sensitive headers (e.g. Authorization) are masked. http.internal.address 127.0.0.1:8081 Address and port the server will be listening to for internal-facing endpoints. http.internal.auth.audience Expected audience for JWT tokens (default: hostname) http.internal.auth.authorizedkeyspath Path to an authorized_keys file for trusted JWT signers diff --git a/http/clientlogger.go b/http/clientlogger.go index 33d55c6734..e5803af658 100644 --- a/http/clientlogger.go +++ b/http/clientlogger.go @@ -26,8 +26,18 @@ import ( "github.com/sirupsen/logrus" ) +// maskedHeaders are HTTP headers whose values are replaced with a placeholder when logging, +// to avoid leaking credentials into the logs. +var maskedHeaders = map[string]struct{}{ + "Authorization": {}, + "Proxy-Authorization": {}, +} + +const maskedHeaderValue = "[MASKED]" + // clientRequestLogger is an http.RoundTripper that logs outgoing HTTP requests and their responses. -// It mirrors the server-side request/body logging: metadata is always logged, bodies only when logBody is set. +// Metadata (method, URI, status, headers) is always logged; bodies are logged only when logBody is set. +// Sensitive headers are masked, see maskedHeaders. type clientRequestLogger struct { transport http.RoundTripper logger *logrus.Entry @@ -35,14 +45,11 @@ type clientRequestLogger struct { } func (c *clientRequestLogger) RoundTrip(request *http.Request) (*http.Response, error) { - fields := logrus.Fields{ - "method": request.Method, - "uri": request.URL.String(), - } - if c.logger.Logger.Level >= logrus.DebugLevel { - fields["headers"] = request.Header - } - c.logger.WithFields(fields).Info("HTTP client request") + c.logger.WithFields(logrus.Fields{ + "method": request.Method, + "uri": request.URL.String(), + "headers": maskHeaders(request.Header), + }).Info("HTTP client request") if c.logBody && request.Body != nil && isLoggableContentType(request.Header.Get("Content-Type")) { body, err := io.ReadAll(request.Body) @@ -64,9 +71,10 @@ func (c *clientRequestLogger) RoundTrip(request *http.Request) (*http.Response, } c.logger.WithFields(logrus.Fields{ - "method": request.Method, - "uri": request.URL.String(), - "status": response.StatusCode, + "method": request.Method, + "uri": request.URL.String(), + "status": response.StatusCode, + "headers": maskHeaders(response.Header), }).Info("HTTP client response") if c.logBody && response.Body != nil && isLoggableContentType(response.Header.Get("Content-Type")) { @@ -81,3 +89,16 @@ func (c *clientRequestLogger) RoundTrip(request *http.Request) (*http.Response, return response, nil } + +// maskHeaders returns a copy of the given headers with the values of sensitive headers masked. +func maskHeaders(header http.Header) http.Header { + masked := make(http.Header, len(header)) + for name, values := range header { + if _, ok := maskedHeaders[http.CanonicalHeaderKey(name)]; ok { + masked[name] = []string{maskedHeaderValue} + continue + } + masked[name] = values + } + return masked +} diff --git a/http/clientlogger_test.go b/http/clientlogger_test.go index b71260fc31..fa907c8790 100644 --- a/http/clientlogger_test.go +++ b/http/clientlogger_test.go @@ -68,13 +68,38 @@ func Test_clientRequestLogger(t *testing.T) { // Body is left intact for the caller responseBody, _ := io.ReadAll(response.Body) assert.Equal(t, `{"hello":"world"}`, string(responseBody)) - // Only request and response metadata is logged, no bodies + // Request and response metadata (incl. headers) is logged, but no bodies require.Len(t, hook.Entries, 2) assert.Equal(t, "HTTP client request", hook.Entries[0].Message) assert.Equal(t, http.MethodPost, hook.Entries[0].Data["method"]) assert.Equal(t, "https://example.com/foo", hook.Entries[0].Data["uri"]) + assert.Contains(t, hook.Entries[0].Data, "headers") assert.Equal(t, "HTTP client response", hook.Entries[1].Message) assert.Equal(t, http.StatusOK, hook.Entries[1].Data["status"]) + assert.Contains(t, hook.Entries[1].Data, "headers") + }) + + t.Run("masks sensitive headers", func(t *testing.T) { + logger, hook := test.NewNullLogger() + transport := roundTripperFunc(func(r *http.Request) (*http.Response, error) { + header := http.Header{} + header.Set("Content-Type", "application/json") + header.Set("WWW-Authenticate", "Bearer realm=\"example\"") + return &http.Response{StatusCode: http.StatusUnauthorized, Header: header, Body: io.NopCloser(strings.NewReader("{}"))}, nil + }) + req := newRequest(t, "{}") + req.Header.Set("Authorization", "Bearer super-secret-token") + sut := &clientRequestLogger{transport: transport, logger: logger.WithFields(logrus.Fields{}), logBody: false} + + _, err := sut.RoundTrip(req) + + require.NoError(t, err) + requestHeaders := hook.Entries[0].Data["headers"].(http.Header) + assert.Equal(t, []string{"[MASKED]"}, requestHeaders["Authorization"]) + assert.Equal(t, "application/json", requestHeaders.Get("Content-Type")) + // Response WWW-Authenticate is a challenge, not a credential, so it is not masked. + responseHeaders := hook.Entries[1].Data["headers"].(http.Header) + assert.Equal(t, "Bearer realm=\"example\"", responseHeaders.Get("WWW-Authenticate")) }) t.Run("metadata and body", func(t *testing.T) { @@ -96,6 +121,7 @@ func Test_clientRequestLogger(t *testing.T) { assert.Equal(t, `{"hello":"world"}`, string(responseBody)) require.Len(t, hook.Entries, 4) assert.Equal(t, "HTTP client request", hook.Entries[0].Message) + assert.Contains(t, hook.Entries[0].Data, "headers") assert.Equal(t, "HTTP client request body: {\"foo\":\"bar\"}", hook.Entries[1].Message) assert.Equal(t, "HTTP client response", hook.Entries[2].Message) assert.Equal(t, "HTTP client response body: {\"hello\":\"world\"}", hook.Entries[3].Message) @@ -121,20 +147,6 @@ func Test_clientRequestLogger(t *testing.T) { assert.Equal(t, "HTTP client response", hook.Entries[1].Message) }) - t.Run("debug level logs headers", func(t *testing.T) { - logger, hook := test.NewNullLogger() - logger.SetLevel(logrus.DebugLevel) - transport := roundTripperFunc(func(r *http.Request) (*http.Response, error) { - return jsonResponse(`{}`), nil - }) - sut := &clientRequestLogger{transport: transport, logger: logger.WithFields(logrus.Fields{}), logBody: false} - - _, err := sut.RoundTrip(newRequest(t, "")) - - require.NoError(t, err) - assert.Contains(t, hook.Entries[0].Data, "headers") - }) - t.Run("transport error is logged and returned", func(t *testing.T) { logger, hook := test.NewNullLogger() transport := roundTripperFunc(func(r *http.Request) (*http.Response, error) { diff --git a/http/cmd/cmd.go b/http/cmd/cmd.go index 0f7caf9af9..a7896a80ad 100644 --- a/http/cmd/cmd.go +++ b/http/cmd/cmd.go @@ -20,6 +20,7 @@ package cmd import ( "fmt" + "github.com/nuts-foundation/nuts-node/http" "github.com/spf13/pflag" ) @@ -35,7 +36,7 @@ func FlagSet() *pflag.FlagSet { flags.String("http.internal.auth.audience", defs.Internal.Auth.Audience, "Expected audience for JWT tokens (default: hostname)") flags.String("http.internal.auth.authorizedkeyspath", defs.Internal.Auth.AuthorizedKeysPath, "Path to an authorized_keys file for trusted JWT signers") flags.String("http.log", string(defs.Log), fmt.Sprintf("What to log about HTTP requests. Options are '%s', '%s' (log request method, URI, IP and response code), and '%s' (log the request and response body, in addition to the metadata). When debug vebosity is set the authorization headers are also logged when the request is fully logged.", http.LogNothingLevel, http.LogMetadataLevel, http.LogMetadataAndBodyLevel)) - flags.String("http.client.log", string(defs.Client.Log), fmt.Sprintf("What to log about outgoing HTTP requests made by the node. Options are '%s', '%s' (log request method, URI and response code), and '%s' (log the request and response body, in addition to the metadata). When debug vebosity is set the request and response headers are also logged.", http.LogNothingLevel, http.LogMetadataLevel, http.LogMetadataAndBodyLevel)) + flags.String("http.client.log", string(defs.Client.Log), fmt.Sprintf("What to log about outgoing HTTP requests made by the node. Options are '%s', '%s' (log request/response method, URI, status and headers), and '%s' (also log the request/response body). Sensitive headers (e.g. Authorization) are masked.", http.LogNothingLevel, http.LogMetadataLevel, http.LogMetadataAndBodyLevel)) flags.String("http.clientipheader", defs.ClientIPHeaderName, "Case-sensitive HTTP Header that contains the client IP used for audit logs. For the X-Forwarded-For header only link-local, loopback, and private IPs are excluded. Switch to X-Real-IP or a custom header if you see your own proxy/infra in the logs.") flags.Int("http.cache.maxbytes", defs.ResponseCacheSize, "HTTP client maximum size of the response cache in bytes. If 0, the HTTP client does not cache responses.") From bd39e7a4e9c0d86630b963b625530bd882e4b7eb Mon Sep 17 00:00:00 2001 From: Rein Krul Date: Tue, 9 Jun 2026 09:17:01 +0200 Subject: [PATCH 4/4] refactor(http): move client request logging into http/client package Relocate the outgoing-request logger from the http package to http/client, where the rest of the client transport code lives, and address naming: - The round tripper is now loggingTransport (it logs both request and response), gated by client.LogRequests / client.LogRequestBodies which are read at request time. This replaces the clientRequestLogger type and the RequestLogger func indirection. - Extract the loggable-content-types list to http/log.IsLoggableContentType as the single source of truth, used by both the client logger and the server-side body logger (previously duplicated). Assisted by AI --- http/client/client.go | 25 +-- http/client/client_test.go | 34 ++-- .../requestlogger.go} | 48 ++++-- .../requestlogger_test.go} | 145 +++++++++++------- http/engine.go | 13 +- http/engine_test.go | 36 ++--- http/log/contenttype.go | 35 +++++ http/requestlogger.go | 21 +-- 8 files changed, 201 insertions(+), 156 deletions(-) rename http/{clientlogger.go => client/requestlogger.go} (58%) rename http/{clientlogger_test.go => client/requestlogger_test.go} (60%) create mode 100644 http/log/contenttype.go diff --git a/http/client/client.go b/http/client/client.go index b0fdee0ce4..dad66e1681 100644 --- a/http/client/client.go +++ b/http/client/client.go @@ -55,13 +55,6 @@ func httpSpanName(_ string, r *http.Request) string { // StrictMode is a flag that can be set to true to enable strict mode for the HTTP client. var StrictMode bool -// RequestLogger wraps the transport of HTTP clients created by this package to log -// outgoing requests and their responses. It is left nil (no logging) by default. -// It is read at request time (not when the client is created), because clients are often created -// before the HTTP engine configures it: the HTTP engine is configured last, while other engines -// create their HTTP clients earlier. -var RequestLogger func(http.RoundTripper) http.RoundTripper - // DefaultMaxHttpResponseSize is a default maximum size of an HTTP response body that will be read. // Very large or unbounded HTTP responses can cause denial-of-service, so it's good to limit how much data is read. // This of course heavily depends on the use case, but 1MB is a reasonable default. @@ -88,11 +81,11 @@ func New(timeout time.Duration) *StrictHTTPClient { } } -// getTransport wraps the given transport with request logging and OpenTelemetry +// getTransport wraps the given transport with request/response logging and OpenTelemetry // instrumentation (if tracing is enabled). func getTransport(base http.RoundTripper) http.RoundTripper { - // Always install the logging indirection so RequestLogger can be configured after the client - // is created: whether to log is decided per request, not when the client is created. + // Always install the logging transport so logging can be enabled after the client is created: + // whether to log is decided per request (see loggingTransport), not when the client is created. transport := http.RoundTripper(&loggingTransport{base: base}) if tracing.Enabled() { return otelhttp.NewTransport(transport, @@ -103,18 +96,6 @@ func getTransport(base http.RoundTripper) http.RoundTripper { return transport } -// loggingTransport applies the configured RequestLogger (if any) at request time. -type loggingTransport struct { - base http.RoundTripper -} - -func (l *loggingTransport) RoundTrip(request *http.Request) (*http.Response, error) { - if logger := RequestLogger; logger != nil { - return logger(l.base).RoundTrip(request) - } - return l.base.RoundTrip(request) -} - // NewWithCache creates a new HTTP client with the given timeout. // It uses the DefaultCachingTransport as the underlying transport. func NewWithCache(timeout time.Duration) *StrictHTTPClient { diff --git a/http/client/client_test.go b/http/client/client_test.go index 0564ff39be..09b53068f7 100644 --- a/http/client/client_test.go +++ b/http/client/client_test.go @@ -30,6 +30,8 @@ import ( "time" "github.com/nuts-foundation/nuts-node/tracing" + "github.com/sirupsen/logrus" + "github.com/sirupsen/logrus/hooks/test" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -253,34 +255,36 @@ func TestNew(t *testing.T) { }) } -func TestRequestLogger_setAfterClientCreation(t *testing.T) { - // Clients are created before the HTTP engine sets RequestLogger, so logging must take effect - // for clients that already exist when RequestLogger is configured. +func TestLogging_enabledAfterClientCreation(t *testing.T) { + // Clients are created before the HTTP engine enables logging, so logging must take effect + // for clients that already exist when LogRequests is set. originalTracing := tracing.Enabled() tracing.SetEnabled(false) t.Cleanup(func() { tracing.SetEnabled(originalTracing) }) - t.Cleanup(func() { RequestLogger = nil }) + t.Cleanup(func() { LogRequests = false }) StrictMode = false + LogRequests = false server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) })) t.Cleanup(server.Close) - // Create the client first, while RequestLogger is still nil. - RequestLogger = nil - client := New(time.Second) + // Create the client first, while logging is still disabled. + httpClient := New(time.Second) - // Now configure the logger, as the HTTP engine does later during startup. - var invoked atomic.Bool - RequestLogger = func(base http.RoundTripper) http.RoundTripper { - invoked.Store(true) - return base - } + // Now enable logging, as the HTTP engine does later during startup. + hook := test.NewLocal(logrus.StandardLogger()) + LogRequests = true httpRequest, _ := http.NewRequest(http.MethodGet, server.URL, nil) - _, err := client.Do(httpRequest) + _, err := httpClient.Do(httpRequest) require.NoError(t, err) - assert.True(t, invoked.Load(), "RequestLogger should be applied to clients created before it was set") + messages := make([]string, 0, len(hook.AllEntries())) + for _, entry := range hook.AllEntries() { + messages = append(messages, entry.Message) + } + assert.Contains(t, messages, "HTTP client request", "logging should apply to clients created before it was enabled") + assert.Contains(t, messages, "HTTP client response") } diff --git a/http/clientlogger.go b/http/client/requestlogger.go similarity index 58% rename from http/clientlogger.go rename to http/client/requestlogger.go index e5803af658..ad8ec54272 100644 --- a/http/clientlogger.go +++ b/http/client/requestlogger.go @@ -16,16 +16,27 @@ * */ -package http +package client import ( "bytes" "io" "net/http" + "github.com/nuts-foundation/nuts-node/http/log" "github.com/sirupsen/logrus" ) +// These flags control logging of outgoing HTTP requests and responses. They are read at request time +// (not when a client is created), because clients are often created before the HTTP engine configures +// logging: the HTTP engine is configured last, while other engines create their HTTP clients earlier. +var ( + // LogRequests enables logging of outgoing request and response metadata (method, URI, status, headers). + LogRequests bool + // LogRequestBodies additionally logs request and response bodies. It has no effect unless LogRequests is set. + LogRequestBodies bool +) + // maskedHeaders are HTTP headers whose values are replaced with a placeholder when logging, // to avoid leaking credentials into the logs. var maskedHeaders = map[string]struct{}{ @@ -35,56 +46,59 @@ var maskedHeaders = map[string]struct{}{ const maskedHeaderValue = "[MASKED]" -// clientRequestLogger is an http.RoundTripper that logs outgoing HTTP requests and their responses. -// Metadata (method, URI, status, headers) is always logged; bodies are logged only when logBody is set. -// Sensitive headers are masked, see maskedHeaders. -type clientRequestLogger struct { - transport http.RoundTripper - logger *logrus.Entry - logBody bool +// loggingTransport logs outgoing HTTP requests and their responses, according to LogRequests and +// LogRequestBodies. It is installed on every client created by this package; whether anything is +// logged is decided per request. +type loggingTransport struct { + base http.RoundTripper } -func (c *clientRequestLogger) RoundTrip(request *http.Request) (*http.Response, error) { - c.logger.WithFields(logrus.Fields{ +func (l *loggingTransport) RoundTrip(request *http.Request) (*http.Response, error) { + if !LogRequests { + return l.base.RoundTrip(request) + } + logger := log.Logger() + + logger.WithFields(logrus.Fields{ "method": request.Method, "uri": request.URL.String(), "headers": maskHeaders(request.Header), }).Info("HTTP client request") - if c.logBody && request.Body != nil && isLoggableContentType(request.Header.Get("Content-Type")) { + if LogRequestBodies && request.Body != nil && log.IsLoggableContentType(request.Header.Get("Content-Type")) { body, err := io.ReadAll(request.Body) _ = request.Body.Close() if err != nil { return nil, err } request.Body = io.NopCloser(bytes.NewReader(body)) - c.logger.Infof("HTTP client request body: %s", string(body)) + logger.Infof("HTTP client request body: %s", string(body)) } - response, err := c.transport.RoundTrip(request) + response, err := l.base.RoundTrip(request) if err != nil { - c.logger.WithFields(logrus.Fields{ + logger.WithFields(logrus.Fields{ "method": request.Method, "uri": request.URL.String(), }).WithError(err).Info("HTTP client request failed") return nil, err } - c.logger.WithFields(logrus.Fields{ + logger.WithFields(logrus.Fields{ "method": request.Method, "uri": request.URL.String(), "status": response.StatusCode, "headers": maskHeaders(response.Header), }).Info("HTTP client response") - if c.logBody && response.Body != nil && isLoggableContentType(response.Header.Get("Content-Type")) { + if LogRequestBodies && response.Body != nil && log.IsLoggableContentType(response.Header.Get("Content-Type")) { body, err := io.ReadAll(response.Body) _ = response.Body.Close() if err != nil { return nil, err } response.Body = io.NopCloser(bytes.NewReader(body)) - c.logger.Infof("HTTP client response body: %s", string(body)) + logger.Infof("HTTP client response body: %s", string(body)) } return response, nil diff --git a/http/clientlogger_test.go b/http/client/requestlogger_test.go similarity index 60% rename from http/clientlogger_test.go rename to http/client/requestlogger_test.go index fa907c8790..023cd8c854 100644 --- a/http/clientlogger_test.go +++ b/http/client/requestlogger_test.go @@ -16,7 +16,7 @@ * */ -package http +package client import ( "errors" @@ -38,7 +38,10 @@ func (f roundTripperFunc) RoundTrip(r *http.Request) (*http.Response, error) { return f(r) } -func Test_clientRequestLogger(t *testing.T) { +func TestLoggingTransport(t *testing.T) { + hook := test.NewLocal(logrus.StandardLogger()) + t.Cleanup(func() { LogRequests = false; LogRequestBodies = false }) + newRequest := func(t *testing.T, body string) *http.Request { req, err := http.NewRequest(http.MethodPost, "https://example.com/foo", strings.NewReader(body)) require.NoError(t, err) @@ -55,12 +58,27 @@ func Test_clientRequestLogger(t *testing.T) { } } + t.Run("disabled: nothing is logged", func(t *testing.T) { + hook.Reset() + LogRequests = false + LogRequestBodies = false + sut := &loggingTransport{base: roundTripperFunc(func(_ *http.Request) (*http.Response, error) { + return jsonResponse(`{"hello":"world"}`), nil + })} + + _, err := sut.RoundTrip(newRequest(t, `{"foo":"bar"}`)) + + require.NoError(t, err) + assert.Empty(t, hook.AllEntries()) + }) + t.Run("metadata only", func(t *testing.T) { - logger, hook := test.NewNullLogger() - transport := roundTripperFunc(func(r *http.Request) (*http.Response, error) { + hook.Reset() + LogRequests = true + LogRequestBodies = false + sut := &loggingTransport{base: roundTripperFunc(func(_ *http.Request) (*http.Response, error) { return jsonResponse(`{"hello":"world"}`), nil - }) - sut := &clientRequestLogger{transport: transport, logger: logger.WithFields(logrus.Fields{}), logBody: false} + })} response, err := sut.RoundTrip(newRequest(t, `{"foo":"bar"}`)) @@ -69,96 +87,105 @@ func Test_clientRequestLogger(t *testing.T) { responseBody, _ := io.ReadAll(response.Body) assert.Equal(t, `{"hello":"world"}`, string(responseBody)) // Request and response metadata (incl. headers) is logged, but no bodies - require.Len(t, hook.Entries, 2) - assert.Equal(t, "HTTP client request", hook.Entries[0].Message) - assert.Equal(t, http.MethodPost, hook.Entries[0].Data["method"]) - assert.Equal(t, "https://example.com/foo", hook.Entries[0].Data["uri"]) - assert.Contains(t, hook.Entries[0].Data, "headers") - assert.Equal(t, "HTTP client response", hook.Entries[1].Message) - assert.Equal(t, http.StatusOK, hook.Entries[1].Data["status"]) - assert.Contains(t, hook.Entries[1].Data, "headers") + entries := hook.AllEntries() + require.Len(t, entries, 2) + assert.Equal(t, "HTTP client request", entries[0].Message) + assert.Equal(t, http.MethodPost, entries[0].Data["method"]) + assert.Equal(t, "https://example.com/foo", entries[0].Data["uri"]) + assert.Contains(t, entries[0].Data, "headers") + assert.Equal(t, "HTTP client response", entries[1].Message) + assert.Equal(t, http.StatusOK, entries[1].Data["status"]) + assert.Contains(t, entries[1].Data, "headers") + }) + + t.Run("metadata and body", func(t *testing.T) { + hook.Reset() + LogRequests = true + LogRequestBodies = true + var sentBody string + sut := &loggingTransport{base: roundTripperFunc(func(r *http.Request) (*http.Response, error) { + // Request body must still be readable by the actual transport + b, _ := io.ReadAll(r.Body) + sentBody = string(b) + return jsonResponse(`{"hello":"world"}`), nil + })} + + response, err := sut.RoundTrip(newRequest(t, `{"foo":"bar"}`)) + + require.NoError(t, err) + assert.Equal(t, `{"foo":"bar"}`, sentBody) + responseBody, _ := io.ReadAll(response.Body) + assert.Equal(t, `{"hello":"world"}`, string(responseBody)) + entries := hook.AllEntries() + require.Len(t, entries, 4) + assert.Equal(t, "HTTP client request", entries[0].Message) + assert.Contains(t, entries[0].Data, "headers") + assert.Equal(t, "HTTP client request body: {\"foo\":\"bar\"}", entries[1].Message) + assert.Equal(t, "HTTP client response", entries[2].Message) + assert.Equal(t, "HTTP client response body: {\"hello\":\"world\"}", entries[3].Message) }) t.Run("masks sensitive headers", func(t *testing.T) { - logger, hook := test.NewNullLogger() - transport := roundTripperFunc(func(r *http.Request) (*http.Response, error) { + hook.Reset() + LogRequests = true + LogRequestBodies = false + sut := &loggingTransport{base: roundTripperFunc(func(_ *http.Request) (*http.Response, error) { header := http.Header{} header.Set("Content-Type", "application/json") header.Set("WWW-Authenticate", "Bearer realm=\"example\"") return &http.Response{StatusCode: http.StatusUnauthorized, Header: header, Body: io.NopCloser(strings.NewReader("{}"))}, nil - }) + })} req := newRequest(t, "{}") req.Header.Set("Authorization", "Bearer super-secret-token") - sut := &clientRequestLogger{transport: transport, logger: logger.WithFields(logrus.Fields{}), logBody: false} _, err := sut.RoundTrip(req) require.NoError(t, err) - requestHeaders := hook.Entries[0].Data["headers"].(http.Header) + entries := hook.AllEntries() + requestHeaders := entries[0].Data["headers"].(http.Header) assert.Equal(t, []string{"[MASKED]"}, requestHeaders["Authorization"]) assert.Equal(t, "application/json", requestHeaders.Get("Content-Type")) // Response WWW-Authenticate is a challenge, not a credential, so it is not masked. - responseHeaders := hook.Entries[1].Data["headers"].(http.Header) + responseHeaders := entries[1].Data["headers"].(http.Header) assert.Equal(t, "Bearer realm=\"example\"", responseHeaders.Get("WWW-Authenticate")) }) - t.Run("metadata and body", func(t *testing.T) { - logger, hook := test.NewNullLogger() - var sentBody string - transport := roundTripperFunc(func(r *http.Request) (*http.Response, error) { - // Request body must still be readable by the actual transport - b, _ := io.ReadAll(r.Body) - sentBody = string(b) - return jsonResponse(`{"hello":"world"}`), nil - }) - sut := &clientRequestLogger{transport: transport, logger: logger.WithFields(logrus.Fields{}), logBody: true} - - response, err := sut.RoundTrip(newRequest(t, `{"foo":"bar"}`)) - - require.NoError(t, err) - assert.Equal(t, `{"foo":"bar"}`, sentBody) - responseBody, _ := io.ReadAll(response.Body) - assert.Equal(t, `{"hello":"world"}`, string(responseBody)) - require.Len(t, hook.Entries, 4) - assert.Equal(t, "HTTP client request", hook.Entries[0].Message) - assert.Contains(t, hook.Entries[0].Data, "headers") - assert.Equal(t, "HTTP client request body: {\"foo\":\"bar\"}", hook.Entries[1].Message) - assert.Equal(t, "HTTP client response", hook.Entries[2].Message) - assert.Equal(t, "HTTP client response body: {\"hello\":\"world\"}", hook.Entries[3].Message) - }) - t.Run("body not logged for non-loggable content type", func(t *testing.T) { - logger, hook := test.NewNullLogger() - transport := roundTripperFunc(func(r *http.Request) (*http.Response, error) { + hook.Reset() + LogRequests = true + LogRequestBodies = true + sut := &loggingTransport{base: roundTripperFunc(func(_ *http.Request) (*http.Response, error) { header := http.Header{} header.Set("Content-Type", "application/octet-stream") return &http.Response{StatusCode: http.StatusOK, Header: header, Body: io.NopCloser(strings.NewReader("binary"))}, nil - }) + })} req := newRequest(t, "binary") req.Header.Set("Content-Type", "application/octet-stream") - sut := &clientRequestLogger{transport: transport, logger: logger.WithFields(logrus.Fields{}), logBody: true} _, err := sut.RoundTrip(req) require.NoError(t, err) // Only metadata is logged - require.Len(t, hook.Entries, 2) - assert.Equal(t, "HTTP client request", hook.Entries[0].Message) - assert.Equal(t, "HTTP client response", hook.Entries[1].Message) + entries := hook.AllEntries() + require.Len(t, entries, 2) + assert.Equal(t, "HTTP client request", entries[0].Message) + assert.Equal(t, "HTTP client response", entries[1].Message) }) t.Run("transport error is logged and returned", func(t *testing.T) { - logger, hook := test.NewNullLogger() - transport := roundTripperFunc(func(r *http.Request) (*http.Response, error) { + hook.Reset() + LogRequests = true + LogRequestBodies = false + sut := &loggingTransport{base: roundTripperFunc(func(_ *http.Request) (*http.Response, error) { return nil, errors.New("connection refused") - }) - sut := &clientRequestLogger{transport: transport, logger: logger.WithFields(logrus.Fields{}), logBody: false} + })} _, err := sut.RoundTrip(newRequest(t, "")) require.Error(t, err) - require.Len(t, hook.Entries, 2) - assert.Equal(t, "HTTP client request", hook.Entries[0].Message) - assert.Equal(t, "HTTP client request failed", hook.Entries[1].Message) + entries := hook.AllEntries() + require.Len(t, entries, 2) + assert.Equal(t, "HTTP client request", entries[0].Message) + assert.Equal(t, "HTTP client request failed", entries[1].Message) }) } diff --git a/http/engine.go b/http/engine.go index b5e477f164..2a77526af8 100644 --- a/http/engine.go +++ b/http/engine.go @@ -100,12 +100,13 @@ func (h *Engine) Configure(serverConfig core.ServerConfig) error { func (h *Engine) configureClient(serverConfig core.ServerConfig) { client.StrictMode = serverConfig.Strictmode - // Configure logging of outgoing HTTP requests/responses, if enabled. - if h.config.Client.Log != LogNothingLevel { - logBody := h.config.Client.Log == LogMetadataAndBodyLevel - client.RequestLogger = func(transport http.RoundTripper) http.RoundTripper { - return &clientRequestLogger{transport: transport, logger: log.Logger(), logBody: logBody} - } + // Configure logging of outgoing HTTP requests/responses. + switch h.config.Client.Log { + case LogMetadataLevel: + client.LogRequests = true + case LogMetadataAndBodyLevel: + client.LogRequests = true + client.LogRequestBodies = true } // Configure the HTTP caching client, if enabled. Set it to http.DefaultTransport so it can be used by any subsystem. if h.config.ResponseCacheSize > 0 { diff --git a/http/engine_test.go b/http/engine_test.go index fe2f8cd86f..2cfd340641 100644 --- a/http/engine_test.go +++ b/http/engine_test.go @@ -245,40 +245,38 @@ func TestEngine_Configure(t *testing.T) { } func TestEngine_configureClient(t *testing.T) { + reset := func() { client.LogRequests = false; client.LogRequestBodies = false } t.Run("logging disabled by default", func(t *testing.T) { - client.RequestLogger = nil - t.Cleanup(func() { client.RequestLogger = nil }) + reset() + t.Cleanup(reset) engine := New(func() {}, nil) engine.configureClient(*core.NewServerConfig()) - assert.Nil(t, client.RequestLogger) + assert.False(t, client.LogRequests) + assert.False(t, client.LogRequestBodies) }) - t.Run("logging enabled", func(t *testing.T) { - client.RequestLogger = nil - t.Cleanup(func() { client.RequestLogger = nil }) + t.Run("metadata logs requests but not bodies", func(t *testing.T) { + reset() + t.Cleanup(reset) engine := New(func() {}, nil) - engine.config.Client.Log = LogMetadataAndBodyLevel + engine.config.Client.Log = LogMetadataLevel engine.configureClient(*core.NewServerConfig()) - require.NotNil(t, client.RequestLogger) - wrapped := client.RequestLogger(http.DefaultTransport) - logger, ok := wrapped.(*clientRequestLogger) - require.True(t, ok) - assert.True(t, logger.logBody) + assert.True(t, client.LogRequests) + assert.False(t, client.LogRequestBodies) }) - t.Run("metadata only does not log bodies", func(t *testing.T) { - client.RequestLogger = nil - t.Cleanup(func() { client.RequestLogger = nil }) + t.Run("metadata-and-body logs requests and bodies", func(t *testing.T) { + reset() + t.Cleanup(reset) engine := New(func() {}, nil) - engine.config.Client.Log = LogMetadataLevel + engine.config.Client.Log = LogMetadataAndBodyLevel engine.configureClient(*core.NewServerConfig()) - require.NotNil(t, client.RequestLogger) - logger := client.RequestLogger(http.DefaultTransport).(*clientRequestLogger) - assert.False(t, logger.logBody) + assert.True(t, client.LogRequests) + assert.True(t, client.LogRequestBodies) }) } diff --git a/http/log/contenttype.go b/http/log/contenttype.go new file mode 100644 index 0000000000..e199b5f1fc --- /dev/null +++ b/http/log/contenttype.go @@ -0,0 +1,35 @@ +/* + * Copyright (C) 2024 Nuts community + * + * This program is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with this program. If not, see . + * + */ + +package log + +import "mime" + +// IsLoggableContentType returns true for content types whose body is safe and useful to log as text. +// It is the single source of truth for both client- and server-side HTTP body logging. +func IsLoggableContentType(contentType string) bool { + mediaType, _, _ := mime.ParseMediaType(contentType) + switch mediaType { + case "application/json", + "application/did+json", + "application/vc+json", + "application/x-www-form-urlencoded": + return true + } + return false +} diff --git a/http/requestlogger.go b/http/requestlogger.go index 9a30299b27..c35573d41c 100644 --- a/http/requestlogger.go +++ b/http/requestlogger.go @@ -22,8 +22,8 @@ import ( "github.com/labstack/echo/v4" "github.com/labstack/echo/v4/middleware" "github.com/nuts-foundation/nuts-node/core" + "github.com/nuts-foundation/nuts-node/http/log" "github.com/sirupsen/logrus" - "mime" ) // requestLoggerMiddleware returns middleware that logs metadata of HTTP requests. @@ -65,30 +65,15 @@ func bodyLoggerMiddleware(skipper middleware.Skipper, logger *logrus.Entry) echo return middleware.BodyDumpWithConfig(middleware.BodyDumpConfig{ Handler: func(e echo.Context, request []byte, response []byte) { requestContentType := e.Request().Header.Get("Content-Type") - if isLoggableContentType(requestContentType) { + if log.IsLoggableContentType(requestContentType) { logger.Infof("HTTP request body: %s", string(request)) } responseContentType := e.Response().Header().Get("Content-Type") - if isLoggableContentType(responseContentType) { + if log.IsLoggableContentType(responseContentType) { logger.Infof("HTTP response body: %s", string(response)) } }, Skipper: skipper, }) } - -func isLoggableContentType(contentType string) bool { - mediaType, _, _ := mime.ParseMediaType(contentType) - switch mediaType { - case "application/json": - fallthrough - case "application/did+json": - fallthrough - case "application/vc+json": - fallthrough - case "application/x-www-form-urlencoded": - return true - } - return false -}