Add trace.id to request trace logs #91772

thecoop · 2022-11-21T16:00:27Z

Very dirty solution to #88174 - just add the trace id to the log message, rather than using thread context

elasticsearchmachine · 2022-11-21T16:01:28Z

Pinging @elastic/es-core-infra (Team:Core/Infra)

elasticsearchmachine · 2022-11-21T16:05:28Z

Hi @thecoop, I've created a changelog YAML for you.

server/src/main/java/org/elasticsearch/tasks/Task.java

grcevski · 2022-11-22T00:06:16Z

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

                    restRequest.getRequestId(),
                    restRequest.header(Task.X_OPAQUE_ID_HTTP_HEADER),
                    restRequest.method(),
                    restRequest.uri(),
-                    restRequest.getHttpChannel()
+                    restRequest.getHttpChannel(),
+                    Task.extractTraceId(restRequest.header(Task.TRACE_PARENT_HTTP_HEADER)).map(t -> " trace.id: " + t).orElse("")


Can we add a test ensuring the new code produces the expected result? I know logger is hard to test, so perhaps we can extract the code into a method? I also recall we had a way to ensure logs had a certain message in some tests, but I can't seem to find it now.

some of those tests are in JsonLoggerTests

Unfortunately that's in a different package, and HttpTracer is package private. I'll see what I can do

I've added a separate test

pgomulka

I think the workaround is ok.
bear in mind that this still will produce a different result in request than in response (the trace.id will be inside a message field". Therefore it will be harder to automatically parse.
I suspect that HttpTracer class was meant to be used for human debugging - hence the trace level which will be unfeasible for investigating problems happening in real clusters.
request after changes:
{ ... "message": "[24][SomeUniqueValue][GET][/test-index/_search] received request from [Netty4HttpChannel{localAddress=/172.18.0.2:9200, remoteAddress=/172.18.0.1:62278}] trace.id: 4bf92f3577b34da6a3ce929d0e0e4736",
response
"message": "[24][SomeUniqueValue][OK][application/json; charset=UTF-8][1005] sent response to [Netty4HttpChannel{localAddress=/172.18.0.2:9200, remoteAddress=/172.18.0.1:62278}] success [true]",..., "trace.id": "4bf92f3577b34da6a3ce929d0e0e4736"

pgomulka · 2022-11-22T08:35:19Z

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

                    restRequest.getRequestId(),
                    restRequest.header(Task.X_OPAQUE_ID_HTTP_HEADER),
                    restRequest.method(),
                    restRequest.uri(),
-                    restRequest.getHttpChannel()
+                    restRequest.getHttpChannel(),
+                    Task.extractTraceId(restRequest.header(Task.TRACE_PARENT_HTTP_HEADER)).map(t -> " trace.id: " + t).orElse("")


some of those tests are in JsonLoggerTests

pgomulka · 2022-11-22T08:36:37Z

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

@@ -57,12 +57,13 @@ HttpTracer maybeLogRequest(RestRequest restRequest, @Nullable Exception e) {
        if (logger.isTraceEnabled() && TransportService.shouldTraceAction(restRequest.uri(), tracerLogInclude, tracerLogExclude)) {
            logger.trace(
                () -> format(
-                    "[%s][%s][%s][%s] received request from [%s]",
+                    "[%s][%s][%s][%s] received request from [%s]%s",


should the new %s be also in square brackets?

I was aiming to get it looking as similar as possible to the response log format

I wonder if we actually don't want to keep this the same in both request and response. so that it would be easier to parse. the same as it is done for x-opaque-id. That means that trace.id or x-opaque-id are duplicated in a response. Present in both message and its own field.
I leave that up to you, or feel free to bring it up with the team

Getting the trace id in there is not completely simple, so I would prefer to leave this hack as small a footprint as possible - if people do complain about the difference, we can then spend more time on this looking at it properly

thecoop · 2022-11-22T11:32:18Z

This was originally reported on 7.17, should this fix be backported at all?

pgomulka

LGTM, I left one comment. Feel free to apply this or merge as it is.

pgomulka · 2022-11-23T14:16:26Z

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

@@ -57,12 +57,13 @@ HttpTracer maybeLogRequest(RestRequest restRequest, @Nullable Exception e) {
        if (logger.isTraceEnabled() && TransportService.shouldTraceAction(restRequest.uri(), tracerLogInclude, tracerLogExclude)) {
            logger.trace(
                () -> format(
-                    "[%s][%s][%s][%s] received request from [%s]",
+                    "[%s][%s][%s][%s] received request from [%s]%s",


I wonder if we actually don't want to keep this the same in both request and response. so that it would be easier to parse. the same as it is done for x-opaque-id. That means that trace.id or x-opaque-id are duplicated in a response. Present in both message and its own field.
I leave that up to you, or feel free to bring it up with the team

grcevski

LGTM! Great test!

elasticsearchmachine · 2022-11-23T15:27:23Z

Hi @thecoop, I've updated the changelog YAML for you.

This reverts commit 302842e.

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.

elasticsearchmachine · 2022-11-23T15:42:49Z

💔 Backport failed

Status	Branch	Result
❌	7.17	Commit could not be cherrypicked due to conflicts
✅	8.6
✅	8.5

You can use sqren/backport to manually backport by running backport --upstream elastic/elasticsearch --pr 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.

* 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.

thecoop · 2022-11-24T08:35:04Z

All backports applied

Add trace.id to request trace logs

0a198e4

thecoop requested review from original-brownbear and pgomulka November 21, 2022 16:00

elasticsearchmachine added needs:triage Requires assignment of a team area label v8.7.0 labels Nov 21, 2022

thecoop added :Core/Infra/Core Core issues without another label and removed needs:triage Requires assignment of a team area label labels Nov 21, 2022

elasticsearchmachine added the Team:Core/Infra Meta label for core/infra team label Nov 21, 2022

thecoop added >bug Team:Core/Infra Meta label for core/infra team and removed Team:Core/Infra Meta label for core/infra team labels Nov 21, 2022

Update docs/changelog/91772.yaml

446d688

splotless

b53db66

thecoop added :Core/Infra/REST API REST infrastructure and utilities and removed :Core/Infra/Core Core issues without another label labels Nov 21, 2022

Update changelog

fb4994e

grcevski reviewed Nov 22, 2022

View reviewed changes

pgomulka reviewed Nov 22, 2022

View reviewed changes

thecoop added 5 commits November 23, 2022 10:54

Merge remote-tracking branch 'upstream/main' into http-trace-id

7803a62

Move extractTraceId to RestUtils

942a768

splotless

4288ce5

Add test for HttpTracer logging

8f63ae0

spotless again

417dcf6

thecoop requested review from grcevski and pgomulka November 23, 2022 13:22

thecoop added 2 commits November 23, 2022 13:23

Fix test logger name

a5d205c

Rename test class

541305e

pgomulka approved these changes Nov 23, 2022

View reviewed changes

grcevski approved these changes Nov 23, 2022

View reviewed changes

thecoop added v7.17.8 auto-backport-and-merge Automatically create backport pull requests and merge when ready labels Nov 23, 2022

thecoop added 2 commits November 23, 2022 15:27

Update docs/changelog/91772.yaml

302842e

Revert "Update docs/changelog/91772.yaml"

d724129

This reverts commit 302842e.

thecoop added v8.6.0 v8.6.1 v8.5.3 and removed v8.6.0 labels Nov 23, 2022

Add comment to explain trace.id log

a759ec4

thecoop merged commit f62db9f into elastic:main Nov 23, 2022

thecoop deleted the http-trace-id branch November 23, 2022 15:41

This was referenced Nov 23, 2022

HttpTracer does not log trace.id in all cases #88174

Closed

[8.6] Add trace.id to request trace logs (#91772) #91858

Merged

thecoop mentioned this pull request Nov 23, 2022

[8.5] Add trace.id to request trace logs (#91772) #91859

Merged

elasticsearchmachine added the backport pending label Nov 23, 2022

thecoop mentioned this pull request Nov 23, 2022

[7.17] Add trace.id to request trace logs (#91772) #91860

Merged

thecoop removed the backport pending label Nov 24, 2022

n1v0lg mentioned this pull request Nov 24, 2022

[CI] HttpTracerTests testLogging failing #91877

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add trace.id to request trace logs #91772

Add trace.id to request trace logs #91772

thecoop commented Nov 21, 2022

elasticsearchmachine commented Nov 21, 2022

elasticsearchmachine commented Nov 21, 2022

grcevski Nov 22, 2022

pgomulka Nov 22, 2022

thecoop Nov 23, 2022

thecoop Nov 23, 2022

pgomulka left a comment

pgomulka Nov 22, 2022

pgomulka Nov 22, 2022

thecoop Nov 22, 2022

pgomulka Nov 23, 2022

thecoop Nov 23, 2022

thecoop commented Nov 22, 2022

pgomulka left a comment

pgomulka Nov 23, 2022

grcevski left a comment

elasticsearchmachine commented Nov 23, 2022

elasticsearchmachine commented Nov 23, 2022

thecoop commented Nov 24, 2022

Add trace.id to request trace logs #91772

Add trace.id to request trace logs #91772

Conversation

thecoop commented Nov 21, 2022

elasticsearchmachine commented Nov 21, 2022

elasticsearchmachine commented Nov 21, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

pgomulka left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

thecoop commented Nov 22, 2022

pgomulka left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

grcevski left a comment

Choose a reason for hiding this comment

elasticsearchmachine commented Nov 23, 2022

elasticsearchmachine commented Nov 23, 2022

💔 Backport failed

thecoop commented Nov 24, 2022