From f62db9f8bb1e7ae832bc6e025b19d5f3ed58e1df Mon Sep 17 00:00:00 2001 From: Simon Cooper Date: Wed, 23 Nov 2022 15:41:11 +0000 Subject: [PATCH] Add trace.id to request trace logs (#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 | 5 ++ .../org/elasticsearch/http/HttpTracer.java | 14 ++- .../elasticsearch/rest/RestController.java | 6 +- .../org/elasticsearch/rest/RestUtils.java | 15 +++- .../elasticsearch/http/HttpTracerTests.java | 86 +++++++++++++++++++ 5 files changed, 121 insertions(+), 5 deletions(-) create mode 100644 docs/changelog/91772.yaml create mode 100644 server/src/test/java/org/elasticsearch/http/HttpTracerTests.java diff --git a/docs/changelog/91772.yaml b/docs/changelog/91772.yaml new file mode 100644 index 0000000000000..0fbe8e9dc32f4 --- /dev/null +++ b/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] diff --git a/server/src/main/java/org/elasticsearch/http/HttpTracer.java b/server/src/main/java/org/elasticsearch/http/HttpTracer.java index 2978f00d7a160..9e879c44aea6a 100644 --- a/server/src/main/java/org/elasticsearch/http/HttpTracer.java +++ b/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]", diff --git a/server/src/main/java/org/elasticsearch/rest/RestController.java b/server/src/main/java/org/elasticsearch/rest/RestController.java index 81825c790cc19..c314c4dbc82de 100644 --- a/server/src/main/java/org/elasticsearch/rest/RestController.java +++ b/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 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)) { diff --git a/server/src/main/java/org/elasticsearch/rest/RestUtils.java b/server/src/main/java/org/elasticsearch/rest/RestUtils.java index 80d68161243da..39ef8200424b3 100644 --- a/server/src/main/java/org/elasticsearch/rest/RestUtils.java +++ b/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 W3 traceparent spec + * + * @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 extractTraceId(String traceparent) { + return traceparent != null && traceparent.length() >= 55 ? Optional.of(traceparent.substring(3, 35)) : Optional.empty(); + } + } diff --git a/server/src/test/java/org/elasticsearch/http/HttpTracerTests.java b/server/src/test/java/org/elasticsearch/http/HttpTracerTests.java new file mode 100644 index 0000000000000..aac41e8349f2d --- /dev/null +++ b/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(); + } + } +}