Add trace.id to request trace logs (elastic#91772)

This adds trace.id, extracted from traceparent header, so its present in the request trace log. It is already included in response trace logs via the threadcontext, but that is not set at request log time.

docs/changelog/91772.yaml

@@ -0,0 +1,5 @@
+pr: 91772
+summary: Add `trace.id` to request trace logs
+area: Infra/Core
+type: bug
+issues: [88174]

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

@@ -16,6 +16,7 @@
 import org.elasticsearch.core.Nullable;
 import org.elasticsearch.rest.RestRequest;
 import org.elasticsearch.rest.RestResponse;
+import org.elasticsearch.rest.RestUtils;
 import org.elasticsearch.tasks.Task;
 import org.elasticsearch.transport.TransportService;
 
@@ -33,6 +34,11 @@ class HttpTracer {
     private volatile String[] tracerLogInclude;
     private volatile String[] tracerLogExclude;
 
+    // for testing
+    HttpTracer() {
+        tracerLogInclude = tracerLogExclude = new String[0];
+    }
+
     HttpTracer(Settings settings, ClusterSettings clusterSettings) {
 
         setTracerLogInclude(HttpTransportSettings.SETTING_HTTP_TRACE_LOG_INCLUDE.get(settings));
@@ -55,14 +61,17 @@ class HttpTracer {
     @Nullable
     HttpTracer maybeLogRequest(RestRequest restRequest, @Nullable Exception e) {
         if (logger.isTraceEnabled() && TransportService.shouldTraceAction(restRequest.uri(), tracerLogInclude, tracerLogExclude)) {
+            // trace.id in the response log is included from threadcontext, which isn't set at request log time
+            // so include it here as part of the message
             logger.trace(
                 () -> format(
-                    "[%s][%s][%s][%s] received request from [%s]",
+                    "[%s][%s][%s][%s] received request from [%s]%s",
                     restRequest.getRequestId(),
                     restRequest.header(Task.X_OPAQUE_ID_HTTP_HEADER),
                     restRequest.method(),
                     restRequest.uri(),
-                    restRequest.getHttpChannel()
+                    restRequest.getHttpChannel(),
+                    RestUtils.extractTraceId(restRequest.header(Task.TRACE_PARENT_HTTP_HEADER)).map(t -> " trace.id: " + t).orElse("")
                 ),
                 e
             );
@@ -89,6 +98,7 @@ void logResponse(
         long requestId,
         boolean success
     ) {
+        // trace id is included in the ThreadContext for the response
         logger.trace(
             () -> format(
                 "[%s][%s][%s][%s][%s] sent response to [%s] success [%s]",

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

@@ -44,6 +44,7 @@
 import java.util.List;
 import java.util.Locale;
 import java.util.Map;
+import java.util.Optional;
 import java.util.Set;
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.function.Supplier;
@@ -561,8 +562,9 @@ private void copyRestHeaders(RestRequest request, ThreadContext threadContext) {
                     throw new IllegalArgumentException("multiple values for single-valued header [" + name + "].");
                 } else if (name.equals(Task.TRACE_PARENT_HTTP_HEADER)) {
                     String traceparent = distinctHeaderValues.get(0);
-                    if (traceparent.length() >= 55) {
-                        threadContext.putHeader(Task.TRACE_ID, traceparent.substring(3, 35));
+                    Optional<String> traceId = RestUtils.extractTraceId(traceparent);
+                    if (traceId.isPresent()) {
+                        threadContext.putHeader(Task.TRACE_ID, traceId.get());
                         threadContext.putTransient("parent_" + Task.TRACE_PARENT_HTTP_HEADER, traceparent);
                     }
                 } else if (name.equals(Task.TRACE_STATE)) {

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

@@ -16,6 +16,7 @@
 import java.nio.charset.StandardCharsets;
 import java.util.Arrays;
 import java.util.Map;
+import java.util.Optional;
 import java.util.regex.Pattern;
 
 public class RestUtils {
@@ -236,6 +237,18 @@ public static String[] corsSettingAsArray(String corsSetting) {
         if (Strings.isNullOrEmpty(corsSetting)) {
             return new String[0];
         }
-        return Arrays.asList(corsSetting.split(",")).stream().map(String::trim).toArray(size -> new String[size]);
+        return Arrays.stream(corsSetting.split(",")).map(String::trim).toArray(String[]::new);
     }
+
+    /**
+     * Extract the trace id from the specified traceparent string.
+     * @see <a href="https://www.w3.org/TR/trace-context/#traceparent-header">W3 traceparent spec</a>
+     *
+     * @param traceparent   The value from the {@code traceparent} HTTP header
+     * @return  The trace id from the traceparent string, or {@code Optional.empty()} if it is not present.
+     */
+    public static Optional<String> extractTraceId(String traceparent) {
+        return traceparent != null && traceparent.length() >= 55 ? Optional.of(traceparent.substring(3, 35)) : Optional.empty();
+    }
+
 }

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

@@ -0,0 +1,86 @@
+/*
+ * 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.elasticsearch.common.logging.Loggers;
+import org.elasticsearch.rest.RestRequest;
+import org.elasticsearch.rest.RestResponse;
+import org.elasticsearch.rest.RestStatus;
+import org.elasticsearch.tasks.Task;
+import org.elasticsearch.test.ESTestCase;
+import org.elasticsearch.test.MockLogAppender;
+import org.elasticsearch.test.junit.annotations.TestLogging;
+import org.elasticsearch.test.rest.FakeRestRequest;
+import org.elasticsearch.xcontent.NamedXContentRegistry;
+
+import java.net.InetSocketAddress;
+import java.util.List;
+import java.util.Map;
+
+public class HttpTracerTests extends ESTestCase {
+
+    @TestLogging(reason = "Get HttpTracer to output trace logs", value = "org.elasticsearch.http.HttpTracer:TRACE")
+    public void testLogging() {
+        String httpTracerLog = HttpTracer.class.getName();
+
+        MockLogAppender appender = new MockLogAppender();
+        try {
+            appender.start();
+            Loggers.addAppender(LogManager.getLogger(httpTracerLog), appender);
+
+            appender.addExpectation(
+                new MockLogAppender.PatternSeenEventExpectation(
+                    "request log",
+                    httpTracerLog,
+                    Level.TRACE,
+                    "\\[1]\\[idHeader]\\[GET]\\[uri] received request from \\[.*] trace.id: 4bf92f3577b34da6a3ce929d0e0e4736"
+                )
+            );
+            appender.addExpectation(
+                new MockLogAppender.PatternSeenEventExpectation(
+                    "response log",
+                    httpTracerLog,
+                    Level.TRACE,
+                    "\\[1]\\[idHeader]\\[ACCEPTED]\\[text/plain; charset=UTF-8]\\[length] sent response to \\[.*] success \\[true]"
+                )
+            );
+
+            RestRequest request = new FakeRestRequest.Builder(new NamedXContentRegistry(List.of())).withMethod(RestRequest.Method.GET)
+                .withPath("uri")
+                .withHeaders(
+                    Map.of(
+                        Task.X_OPAQUE_ID_HTTP_HEADER,
+                        List.of("idHeader"),
+                        "traceparent",
+                        List.of("00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01")
+                    )
+                )
+                .build();
+
+            HttpTracer tracer = new HttpTracer().maybeLogRequest(request, null);
+            assertNotNull(tracer);
+
+            tracer.logResponse(
+                new RestResponse(RestStatus.ACCEPTED, ""),
+                new FakeRestRequest.FakeHttpChannel(InetSocketAddress.createUnresolved("127.0.0.1", 9200)),
+                "length",
+                "idHeader",
+                1L,
+                true
+            );
+
+            appender.assertAllExpectationsMatched();
+        } finally {
+            Loggers.removeAppender(LogManager.getLogger(httpTracerLog), appender);
+            appender.stop();
+        }
+    }
+}