HttpTracer does not log trace.id in all cases

[zamazan4ik]

Elasticsearch Version

7.17.4

Installed Plugins

No response

Java Version

bundled

OS Version

Docker

Problem Description

After enabling HttpTracer (https://www.elastic.co/guide/en/elasticsearch/reference/7.7/modules-http.html#_rest_request_tracer) I make calls with HTTP interface with traceparent header. And I see that only responses have trace id entry on logs.

Actual behaviour:
Trace Id from traceparent header appears only in logs for responses to request, but does not appear in logs for requests.

Expected behaviour:
Trace id appears for both request and responses logs.

Why do we need it
We are trying to introduce transparent distributed tracing to our ElasticSearch installation. And for this we need to have a trace id in each log entry for all HTTP requests.

Considered alternatives:
I have checked a way with X-Opaque-Id - it works fine (this header is logged for requests and responses) but according to the documentation (https://www.elastic.co/guide/en/elasticsearch/reference/7.17/api-conventions.html#x-opaque-id) it is not recommended to make it unique for each request. So in our case we cannot use this header as a storage for our own request_id (or at least it violates somehow ElasticSearch recommendations)

Steps to Reproduce

1. Install ElasticSearch 7.17.4
2. Enable HttpTracer for an index
3. Make sample request
4. Check logs

Logs (if relevant)

{"type": "server", "timestamp": "2022-06-29T11:24:33,133Z", "level": "TRACE", "component": "o.e.h.HttpTracer", "cluster.name": "es-docker-cluster", "node.name": "es01", "message": "[24][SomeUniqueValue][GET][/test-index/_search] received request from [Netty4HttpChannel{localAddress=/172.18.0.2:9200, remoteAddress=/172.18.0.1:62278}]", "cluster.uuid": "8BovEnDySNSD13p3Ih2QXw", "node.id": "hqru84auT8KvjTYdMdv9cg" }

{"type": "server", "timestamp": "2022-06-29T11:24:33,167Z", "level": "TRACE", "component": "o.e.h.HttpTracer", "cluster.name": "es-docker-cluster", "node.name": "es01", "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]", "cluster.uuid": "8BovEnDySNSD13p3Ih2QXw", "node.id": "hqru84auT8KvjTYdMdv9cg" , "trace.id": "4bf92f3577b34da6a3ce929d0e0e4736" }

[elasticmachine]

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

[zamazan4ik]

Ping. Do you have any updates? Do you need additional information from my side?

[zamazan4ik]

Any updates?

[thecoop]

The issue here is that HttpTracer logs the request as part of initial request processing, before it gets handed over to the controller, but the thread context that provides trace id is not set until later in processing.

I think our options here are:

• Add another thread context set, just for the initial request log
• Refactor the trace logger, rest transport, controller, and response, to move the request log into the RestController (complicated...).

@original-brownbear @pugnascotia you've previously worked on this, any preference/other suggestions?

[pgomulka]

I personally would prefer some refactoring instead of setting the header thread context in a separate place. It would be harder to track what headers are copied.
This would require I think the logging call after the chanel is created https://github.com/elastic/elasticsearch/blob/main/server/src/main/java/org/elasticsearch/http/AbstractHttpServerTransport.java#L459
and configure AbstractHttpServerTransport with headers to copy.

Otherwise we could make the HttpTracer to directly fetch the headers from the request. It does this for x-opaque-id now.

[thecoop]

The issue with moving it is that the request can fail due to parameters etc, and it's useful to have something logged beforehand that can be used to debug such errors. If it was moved to after the channel creation you wouldn't get any trace logging, just the REST error.

[thecoop]

Fixed by #91772 (although it's not pretty)