feat(http): add http.client.log for logging outgoing HTTP requests

docs/pages/deployment/configuration.rst

@@ -94,6 +94,7 @@ requesting an access token from another node on ``/n2n/auth/v1/accesstoken`` doe
 ``auth.accesstokenlifespan`` is always 60 seconds,
 json-ld context can only be downloaded from trusted domains configured in ``jsonld.contexts.remoteallowlist``,
 ``http.log=metadata-and-body`` is not allowed and is changed to ``metadata`` at startup (request and response bodies on the OAuth endpoints contain credentials, which must not be written to logs),
+``http.client.log=metadata-and-body`` is not allowed and is changed to ``metadata`` at startup (request and response bodies on outgoing HTTP calls can contain credentials, which must not be written to logs),
 and the ``internalratelimiter`` is always on.
 
 Interacting with remote Nuts nodes requires HTTPS: it will refuse to connect to plain HTTP endpoints when in strict mode.

docs/pages/deployment/server_options.rst

@@ -38,6 +38,7 @@
     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.allowedinternalcidrs              []                                                                                                                                                                                                                                                                                                                                                                                                                                                                       IP ranges (CIDR notation, e.g. 10.0.0.0/8) exempted from the strict-mode SSRF guard, which otherwise blocks outbound requests to non-public networks. Use to permit internal flows that legitimately target a private address, such as an internal credential offering or an internal OAuth user flow. Leave empty to block all non-public addresses.                                                          
     http.client.deniedcidrs                       []                                                                                                                                                                                                                                                                                                                                                                                                                                                                       IP ranges (CIDR notation) that outbound HTTP requests must never target in strict mode, in addition to the built-in blocked ranges (non-public addresses and cloud metadata endpoints). Use for publicly routable ranges that are internal-only in your infrastructure. Takes precedence over http.client.allowedinternalcidrs.                                                                                
+    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. In strictmode, 'metadata-and-body' is not allowed and is changed to 'metadata' at startup.                                               
     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                                                                                                                                                                                                                                                                                                                                                        

http/client/client.go

@@ -113,15 +113,19 @@ 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/response logging and OpenTelemetry
+// instrumentation (if tracing is enabled).
 func getTransport(base http.RoundTripper) http.RoundTripper {
+	// 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(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.

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"
 )
@@ -83,7 +85,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)
 		})
 	})
@@ -349,14 +351,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)
 	})
 }
 
@@ -379,6 +383,42 @@ 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 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() { 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 logging is still disabled.
+	httpClient := New(time.Second)
+
+	// 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 := httpClient.Do(httpRequest)
+
+	require.NoError(t, err)
+	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")
+}

http/client/requestlogger.go

@@ -0,0 +1,118 @@
+/*
+ * 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 <https://www.gnu.org/licenses/>.
+ *
+ */
+
+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{}{
+	"Authorization":       {},
+	"Proxy-Authorization": {},
+}
+
+const maskedHeaderValue = "[MASKED]"
+
+// 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 (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 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))
+		logger.Infof("HTTP client request body: %s", string(body))
+	}
+
+	response, err := l.base.RoundTrip(request)
+	if err != nil {
+		logger.WithFields(logrus.Fields{
+			"method": request.Method,
+			"uri":    request.URL.String(),
+		}).WithError(err).Info("HTTP client request failed")
+		return nil, err
+	}
+
+	logger.WithFields(logrus.Fields{
+		"method":  request.Method,
+		"uri":     request.URL.String(),
+		"status":  response.StatusCode,
+		"headers": maskHeaders(response.Header),
+	}).Info("HTTP client response")
+
+	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))
+		logger.Infof("HTTP client response body: %s", string(body))
+	}
+
+	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
+}