Add request/response body logging to HTTP tracer (#93133)

Adds another logger, `org.elasticsearch.http.HttpBodyTracer`, which logs
the body of every HTTP request and response as well as the usual
summaries.

docs/changelog/93133.yaml

@@ -0,0 +1,5 @@
+pr: 93133
+summary: Add request/response body logging to HTTP tracer
+area: Network
+type: enhancement
+issues: []

docs/reference/modules/network/tracers.asciidoc

@@ -36,6 +36,51 @@ PUT _cluster/settings
 }
 --------------------------------------------------
 
+By default, the tracer logs a summary of each request and response which
+matches these filters. To record the body of each request and response too, set
+the system property `es.insecure_network_trace_enabled` to `true`, and then set
+the levels of both the `org.elasticsearch.http.HttpTracer` and
+`org.elasticsearch.http.HttpBodyTracer` loggers to `TRACE`:
+
+[source,console]
+--------------------------------------------------
+PUT _cluster/settings
+{
+   "persistent" : {
+      "logger.org.elasticsearch.http.HttpTracer" : "TRACE",
+      "logger.org.elasticsearch.http.HttpBodyTracer" : "TRACE"
+   }
+}
+--------------------------------------------------
+
+Each message body is compressed, encoded, and split into chunks to avoid
+truncation:
+
+[source,text]
+----
+[TRACE][o.e.h.HttpBodyTracer     ] [master] [276] response body [part 1]: H4sIAAAAAAAA/9...
+[TRACE][o.e.h.HttpBodyTracer     ] [master] [276] response body [part 2]: 2oJ93QyYLWWhcD...
+[TRACE][o.e.h.HttpBodyTracer     ] [master] [276] response body (gzip compressed, base64-encoded, and split into 2 parts on preceding log lines)
+----
+
+Each chunk is annotated with an internal request ID (`[276]` in this example)
+which you should use to correlate the chunks with the corresponding summary
+lines. To reconstruct the output, base64-decode the data and decompress it
+using `gzip`. For instance, on Unix-like systems:
+
+[source,sh]
+----
+cat httptrace.log | sed -e 's/.*://' | base64 --decode | gzip --decompress
+----
+
+WARNING: HTTP request and response bodies may contain sensitive information
+such as credentials and keys, so HTTP body tracing is disabled by default. You
+must explicitly enable it on each node by setting the system property
+`es.insecure_network_trace_enabled` to `true`. This feature is primarily
+intended for test systems which do not contain any sensitive information. If
+you set this property on a system which contains sensitive information, you
+must protect your logs from unauthorized access.
+
 [[transport-tracer]]
 ===== Transport tracer
 

server/build.gradle

@@ -142,6 +142,10 @@ if (BuildParams.isSnapshotBuild() == false) {
     }
 }
 
+tasks.named("test").configure {
+    systemProperty 'es.insecure_network_trace_enabled', 'true'
+}
+
 tasks.named("thirdPartyAudit").configure {
     ignoreMissingClasses(
             // from com.fasterxml.jackson.dataformat.yaml.YAMLMapper (jackson-dataformat-yaml)

server/src/main/java/org/elasticsearch/common/ReferenceDocs.java

@@ -36,6 +36,7 @@ public enum ReferenceDocs {
     SHARD_LOCK_TROUBLESHOOTING,
     CONCURRENT_REPOSITORY_WRITERS,
     ARCHIVE_INDICES,
+    HTTP_TRACER,
     // this comment keeps the ';' on the next line so every entry above has a trailing ',' which makes the diff for adding new links cleaner
     ;
 

server/src/main/java/org/elasticsearch/http/DefaultRestChannel.java

@@ -21,6 +21,8 @@
 import org.elasticsearch.core.Releasable;
 import org.elasticsearch.core.Releasables;
 import org.elasticsearch.rest.AbstractRestChannel;
+import org.elasticsearch.rest.ChunkedRestResponseBody;
+import org.elasticsearch.rest.LoggingChunkedRestResponseBody;
 import org.elasticsearch.rest.RestChannel;
 import org.elasticsearch.rest.RestRequest;
 import org.elasticsearch.rest.RestResponse;
@@ -113,7 +115,20 @@ public void sendResponse(RestResponse restResponse) {
         try {
             final HttpResponse httpResponse;
             if (isHeadRequest == false && restResponse.isChunked()) {
-                httpResponse = httpRequest.createResponse(restResponse.status(), restResponse.chunkedContent());
+                ChunkedRestResponseBody chunkedContent = restResponse.chunkedContent();
+                if (httpLogger != null && httpLogger.isBodyTracerEnabled()) {
+                    final var loggerStream = httpLogger.openResponseBodyLoggingStream(request.getRequestId());
+                    toClose.add(() -> {
+                        try {
+                            loggerStream.close();
+                        } catch (Exception e) {
+                            assert false : e; // nothing much to go wrong here
+                        }
+                    });
+                    chunkedContent = new LoggingChunkedRestResponseBody(chunkedContent, loggerStream);
+                }
+
+                httpResponse = httpRequest.createResponse(restResponse.status(), chunkedContent);
             } else {
                 final BytesReference content = restResponse.content();
                 if (content instanceof Releasable) {
@@ -122,6 +137,15 @@ public void sendResponse(RestResponse restResponse) {
                 toClose.add(this::releaseOutputBuffer);
 
                 BytesReference finalContent = isHeadRequest ? BytesArray.EMPTY : content;
+
+                if (httpLogger != null && httpLogger.isBodyTracerEnabled()) {
+                    try (var responseBodyLoggingStream = httpLogger.openResponseBodyLoggingStream(request.getRequestId())) {
+                        finalContent.writeTo(responseBodyLoggingStream);
+                    } catch (Exception e) {
+                        assert false : e; // nothing much to go wrong here
+                    }
+                }
+
                 httpResponse = httpRequest.createResponse(restResponse.status(), finalContent);
             }
             corsHandler.setCorsResponseHeaders(httpRequest, httpResponse);

server/src/main/java/org/elasticsearch/http/HttpBodyTracer.java

@@ -0,0 +1,55 @@
+/*
+ * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
+ * or more contributor license agreements. Licensed under the Elastic License
+ * 2.0 and the Server Side Public License, v 1; you may not use this file except
+ * in compliance with, at your election, the Elastic License 2.0 or the Server
+ * Side Public License, v 1.
+ */
+
+package org.elasticsearch.http;
+
+import org.apache.logging.log4j.Level;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
+import org.elasticsearch.common.ReferenceDocs;
+import org.elasticsearch.common.logging.ChunkedLoggingStream;
+import org.elasticsearch.transport.NetworkTraceFlag;
+
+import java.io.OutputStream;
+
+class HttpBodyTracer {
+    private static final Logger logger = LogManager.getLogger(HttpBodyTracer.class);
+
+    public static boolean isEnabled() {
+        return logger.isTraceEnabled();
+    }
+
+    enum Type {
+        REQUEST("request"),
+        RESPONSE("response");
+
+        final String text;
+
+        Type(String text) {
+            this.text = text;
+        }
+    }
+
+    static OutputStream getBodyOutputStream(long requestId, Type type) {
+        try {
+            if (NetworkTraceFlag.TRACE_ENABLED) {
+                return ChunkedLoggingStream.create(
+                    logger,
+                    Level.TRACE,
+                    "[" + requestId + "] " + type.text + " body",
+                    ReferenceDocs.HTTP_TRACER
+                );
+            } else {
+                logger.trace("set system property [{}] to [true] to enable HTTP body tracing", NetworkTraceFlag.PROPERTY_NAME);
+            }
+        } catch (Exception e) {
+            assert false : e; // nothing really to go wrong here
+        }
+        return OutputStream.nullOutputStream();
+    }
+}

server/src/main/java/org/elasticsearch/http/HttpTracer.java

@@ -20,6 +20,7 @@
 import org.elasticsearch.tasks.Task;
 import org.elasticsearch.transport.TransportService;
 
+import java.io.OutputStream;
 import java.util.List;
 
 import static org.elasticsearch.core.Strings.format;
@@ -75,11 +76,23 @@ HttpTracer maybeLogRequest(RestRequest restRequest, @Nullable Exception e) {
                 ),
                 e
             );
+            if (isBodyTracerEnabled()) {
+                try (var stream = HttpBodyTracer.getBodyOutputStream(restRequest.getRequestId(), HttpBodyTracer.Type.REQUEST)) {
+                    restRequest.content().writeTo(stream);
+                } catch (Exception e2) {
+                    assert false : e2; // no real IO here
+                }
+            }
+
             return this;
         }
         return null;
     }
 
+    boolean isBodyTracerEnabled() {
+        return HttpBodyTracer.isEnabled();
+    }
+
     /**
      * Logs the response to a request that was logged by {@link #maybeLogRequest(RestRequest, Exception)}.
      *
@@ -120,4 +133,8 @@ private void setTracerLogInclude(List<String> tracerLogInclude) {
     private void setTracerLogExclude(List<String> tracerLogExclude) {
         this.tracerLogExclude = tracerLogExclude.toArray(Strings.EMPTY_ARRAY);
     }
+
+    OutputStream openResponseBodyLoggingStream(long requestId) {
+        return HttpBodyTracer.getBodyOutputStream(requestId, HttpBodyTracer.Type.RESPONSE);
+    }
 }

server/src/main/java/org/elasticsearch/rest/LoggingChunkedRestResponseBody.java

@@ -0,0 +1,49 @@
+/*
+ * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
+ * or more contributor license agreements. Licensed under the Elastic License
+ * 2.0 and the Server Side Public License, v 1; you may not use this file except
+ * in compliance with, at your election, the Elastic License 2.0 or the Server
+ * Side Public License, v 1.
+ */
+
+package org.elasticsearch.rest;
+
+import org.apache.lucene.util.BytesRef;
+import org.elasticsearch.common.bytes.ReleasableBytesReference;
+import org.elasticsearch.common.recycler.Recycler;
+
+import java.io.IOException;
+import java.io.OutputStream;
+
+public class LoggingChunkedRestResponseBody implements ChunkedRestResponseBody {
+
+    private final ChunkedRestResponseBody inner;
+    private final OutputStream loggerStream;
+
+    public LoggingChunkedRestResponseBody(ChunkedRestResponseBody inner, OutputStream loggerStream) {
+        this.inner = inner;
+        this.loggerStream = loggerStream;
+    }
+
+    @Override
+    public boolean isDone() {
+        return inner.isDone();
+    }
+
+    @Override
+    public ReleasableBytesReference encodeChunk(int sizeHint, Recycler<BytesRef> recycler) throws IOException {
+        var chunk = inner.encodeChunk(sizeHint, recycler);
+        try {
+            chunk.writeTo(loggerStream);
+        } catch (Exception e) {
+            assert false : e; // nothing really to go wrong here
+        }
+
+        return chunk;
+    }
+
+    @Override
+    public String getResponseContentTypeString() {
+        return inner.getResponseContentTypeString();
+    }
+}

server/src/main/java/org/elasticsearch/transport/NetworkTraceFlag.java

@@ -0,0 +1,35 @@
+/*
+ * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
+ * or more contributor license agreements. Licensed under the Elastic License
+ * 2.0 and the Server Side Public License, v 1; you may not use this file except
+ * in compliance with, at your election, the Elastic License 2.0 or the Server
+ * Side Public License, v 1.
+ */
+
+package org.elasticsearch.transport;
+
+import org.elasticsearch.common.Strings;
+
+public class NetworkTraceFlag {
+
+    private NetworkTraceFlag() {
+        // no instances;
+    }
+
+    public static final String PROPERTY_NAME = "es.insecure_network_trace_enabled";
+
+    public static final boolean TRACE_ENABLED;
+
+    static {
+        final var propertyValue = System.getProperty(PROPERTY_NAME);
+        if (propertyValue == null) {
+            TRACE_ENABLED = false;
+        } else if ("true".equals(propertyValue)) {
+            TRACE_ENABLED = true;
+        } else {
+            throw new IllegalArgumentException(
+                Strings.format("system property [%s] may only be set to [true], but was [%s]", PROPERTY_NAME, propertyValue)
+            );
+        }
+    }
+}

server/src/main/resources/org/elasticsearch/common/reference-docs-links.json

@@ -5,5 +5,6 @@
   "LAGGING_NODE_TROUBLESHOOTING": "cluster-fault-detection.html#_diagnosing_lagging_nodes",
   "SHARD_LOCK_TROUBLESHOOTING": "cluster-fault-detection.html#_diagnosing_shardlockobtainfailedexception_failures",
   "CONCURRENT_REPOSITORY_WRITERS": "add-repository.html",
-  "ARCHIVE_INDICES": "archive-indices.html"
+  "ARCHIVE_INDICES": "archive-indices.html",
+  "HTTP_TRACER": "modules-network.html#http-rest-request-tracer"
 }

server/src/test/java/org/elasticsearch/cluster/coordination/LagDetectorTests.java

@@ -250,14 +250,17 @@ public void testLagDetection() {
         assertThat(failedNodes, empty()); // nodes added after a lag detector was started are also ignored
     }
 
-    @TestLogging(reason = "testing LagDetector logging", value = "org.elasticsearch.cluster.coordination.LagDetector:DEBUG")
+    // literal name because it appears in the docs so must not be changed without care
+    private static final String LOGGER_NAME = "org.elasticsearch.cluster.coordination.LagDetector";
+
+    @TestLogging(reason = "testing LagDetector logging", value = LOGGER_NAME + ":DEBUG")
     public void testHotThreadsChunkedLoggingEncoding() {
         final var node = new DiscoveryNode("test", buildNewFakeTransportAddress(), Version.CURRENT);
         final var expectedBody = randomUnicodeOfLengthBetween(1, 20000);
         assertEquals(
             expectedBody,
             ChunkedLoggingStreamTests.getDecodedLoggedBody(
-                LogManager.getLogger(LagDetector.class),
+                LogManager.getLogger(LOGGER_NAME),
                 Level.DEBUG,
                 "hot threads from node ["
                     + node.descriptionWithoutAttributes()

server/src/test/java/org/elasticsearch/http/AbstractHttpServerTransportTests.java

@@ -364,16 +364,13 @@ public HttpStats stats() {
                     .build()
             );
             MockLogAppender appender = new MockLogAppender();
-            final String traceLoggerName = "org.elasticsearch.http.HttpTracer";
-            try {
-                appender.start();
-                Loggers.addAppender(LogManager.getLogger(traceLoggerName), appender);
+            try (var ignored = appender.capturing(HttpTracer.class)) {
 
                 final String opaqueId = UUIDs.randomBase64UUID(random());
                 appender.addExpectation(
                     new MockLogAppender.PatternSeenEventExpectation(
                         "received request",
-                        traceLoggerName,
+                        HttpTracerTests.HTTP_TRACER_LOGGER,
                         Level.TRACE,
                         "\\[\\d+\\]\\[" + opaqueId + "\\]\\[OPTIONS\\]\\[/internal/test\\] received request from \\[.*"
                     )
@@ -384,7 +381,7 @@ public HttpStats stats() {
                 appender.addExpectation(
                     new MockLogAppender.PatternSeenEventExpectation(
                         "sent response",
-                        traceLoggerName,
+                        HttpTracerTests.HTTP_TRACER_LOGGER,
                         Level.TRACE,
                         "\\[\\d+\\]\\["
                             + opaqueId
@@ -399,7 +396,7 @@ public HttpStats stats() {
                 appender.addExpectation(
                     new MockLogAppender.UnseenEventExpectation(
                         "received other request",
-                        traceLoggerName,
+                        HttpTracerTests.HTTP_TRACER_LOGGER,
                         Level.TRACE,
                         "\\[\\d+\\]\\[" + opaqueId + "\\]\\[OPTIONS\\]\\[/internal/testNotSeen\\] received request from \\[.*"
                     )
@@ -420,7 +417,9 @@ public HttpStats stats() {
                     .withInboundException(inboundException)
                     .build();
 
-                transport.incomingRequest(fakeRestRequest.getHttpRequest(), fakeRestRequest.getHttpChannel());
+                try (var httpChannel = fakeRestRequest.getHttpChannel()) {
+                    transport.incomingRequest(fakeRestRequest.getHttpRequest(), httpChannel);
+                }
 
                 final Exception inboundExceptionExcludedPath;
                 if (randomBoolean()) {
@@ -437,11 +436,10 @@ public HttpStats stats() {
                     .withInboundException(inboundExceptionExcludedPath)
                     .build();
 
-                transport.incomingRequest(fakeRestRequestExcludedPath.getHttpRequest(), fakeRestRequestExcludedPath.getHttpChannel());
+                try (var httpChannel = fakeRestRequestExcludedPath.getHttpChannel()) {
+                    transport.incomingRequest(fakeRestRequestExcludedPath.getHttpRequest(), httpChannel);
+                }
                 appender.assertAllExpectationsMatched();
-            } finally {
-                Loggers.removeAppender(LogManager.getLogger(traceLoggerName), appender);
-                appender.stop();
             }
         }
     }