Improve deprecation log traceability

[cjcenizal]

Problem

Upgrade Assistant surfaces ES deprecation logs, but it's a guessing game to figure out which requests are triggering them, and which part of a codebase is sending those requests.

Solution

If I could wave a magic wand, I'd like to see the API request which triggered the deprecation warning. If we could also show the headers that were sent with the request we could specify custom headers to be precisely pinpoint where the request originates in the application code.

[elasticmachine]

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

[elasticmachine]

Pinging @elastic/es-data-management (Team:Data Management)

[elasticmachine]

Pinging @elastic/kibana-stack-management (Team:Stack Management)

[sebelga]

From my testing of the Upgrade assistant UI this looks like a bug. The Upgrade assistant UI job is to help our users upgrade to 8.0 and we are failing to do so as we don't provide enough information to the user to fix a deprecation.

In my current testing I am receiving the following critical warning:

[deprecation.elasticsearch][CRITICAL] this request accesses system indices: [.tasks], but in a future major version, direct access to system indices will be prevented by default

This is the detailed deprecation in the UI

Unfortunately our user don't have enough information to fix that problem and trace back to their application code that needs to be updated in order to fix the problem and upgrade to 8.0.

[williamrandolph]

I took a quick look at the code around the deprecation warning in the example here. It would take some work to add the request itself to the log message, but the deprecation code already supports the X-Opaque-Id header. We have some public documentation around that header. For example: https://www.elastic.co/guide/en/elasticsearch/reference/7.15/tasks.html#_identifying_running_tasks

$ curl -ski --user elastic:password -H 'X-Opaque-Id: 123' 'localhost:9200/.security-7'
[...]

$ cat logs/elasticsearch_deprecation.json
{
  "@timestamp": "2021-11-04T18:02:28.330Z",
  "log.level": "CRITICAL",
  "data_stream.dataset": "deprecation.elasticsearch",
  "data_stream.namespace": "default",
  "data_stream.type": "logs",
  "ecs.version": "1.7",
  "elasticsearch.event.category": "api",
  "elasticsearch.http.request.x_opaque_id": "123",    <---- OPAQUE ID in deprecation log
  "event.code": "open_system_index_access",
  "message": "this request accesses system indices: [.security-7], but in a future major version, direct access to system indices will be prevented by default",
  "service.name": "ES_ECS",
  "process.thread.name": "elasticsearch[Williams-MacBook-Pro.local][system_critical_read][T#1]",
  "log.logger": "org.elasticsearch.deprecation.cluster.metadata.IndexNameExpressionResolver",
  "event.dataset": "deprecation.elasticsearch",
  "elasticsearch.cluster.uuid": "sSqwo5FTSXmASQ88wxGIHQ",
  "elasticsearch.node.id": "gyCLSR7PT_mNzkIpwo1Ocw",
  "elasticsearch.node.name": "Williams-MacBook-Pro.local",
  "elasticsearch.cluster.name": "elasticsearch"
}

[pgomulka]

Just to be clear. The issue is about finding out which part of the "User app" called a deprecated api?

I think traceparent/trace.id in addition to x-opaque-id could help to achieve that.
X-opaque-id - being used as a "call site" in the user app, or just an app Id
trace.id being a uuid which will can be used to correlated requests.

https://www.elastic.co/guide/en/elasticsearch/reference/7.17/api-conventions.html

[cjcenizal]

@pgayvallet Could you please provide input here, particularly regarding the feasibility of @pgomulka's suggestion, above? I see from elastic/kibana#123737 that Core team has been thinking through how to use x-opace-id and trace.id, and this seems related.

[pgayvallet]

@cjcenizal

We're already sending a traceparent header to ES (via the APM agent instrumentation) which trace.id matches the value in kibana logs. This is used for log correlation.

Now, about using that header for traceability, I'll set @mshustov answer, as I don't think that's the direction we're taking (from my understanding, the end goal for traceability was the usage of the baggage header)

[mshustov]

I think traceparent/trace.id in addition to x-opaque-id could help to achieve that.

right, traceparent/trace.id would help to trace a call to an origin in the Kibana server. If a request is triggered from the Kibana application, the only way to trace it is to an origin is to rely on x-opaque-id value.
The problem is that we have execution_context set for a few most popular apps elastic/kibana#102629 Thus, it can't be used as a reliable value for deduplication.

[cjcenizal]

Thank you @mshustov. So, to conclude, is Kibana planning to change its usage of execution_context so that we can use x-opaque-id for tracing, or do we need more help on the ES side to enable tracing?

[mshustov]

So, to conclude, is Kibana planning to change its usage of execution_context so that we can use x-opaque-id for tracing,

Do you mean whether Kibana will get rid of the dynamic part of x-opaque-id as Pierre did in elastic/kibana#123197?
I guess so. We just need to iron out some implementation details.

[cjcenizal]

@mshustov Sorry I'm just trying to figure out on a high-level whether this issue is worth keeping open. Do we need more features from ES to improve tracing in Kibana, or are the existing features sufficient? If they're sufficient I'll close this. Thanks. :)

[mshustov]

@cjcenizal I don't think there is anything else for the ES team to improve right now. All the remaining work (elastic/kibana#123197) seems to be on the Kibana side.

[cjcenizal]

Thanks @mshustov!