Add request duration to the Elasticsearch response logs

[mshustov]

You can find the motivation description and proposed format in the parent issue #119062.
This issue is created to track implementation progress.

[elasticmachine]

Pinging @elastic/kibana-core (Team:Core)

[pgayvallet]

In #119062, you said

Unforatuntely, elasticsearch-js client doesn't seem to measure how long the response took. I'm erring on the side of adding this logic to the elasticsearch-js client since it manages the underlying connections. If @delvedor agrees, I will open an issue.

Is the implementation going to be performed in the client itself, or is this issue about a custom implementation in Kibana?

[mshustov]

@delvedor would evaluate the possibility of implementing this logic on the transport level. elastic/elastic-transport-js#35 Depending on his decision, we either rely on the transport implementation or implement it in Kibana.

[mshustov]

@delvedor doesn't think it's worth adding this feature on the transport level due to performance overhead. See elastic/elastic-transport-js#40
@mikecote told me the Response Ops team needs this functionality, and they are ready to implement it on the plugin level. We need to sync with @mikecote to align on the implementation. Ideally, Core will enhance the ES client with this functionality, and other plugins can access duration via observability events. In this way, the Core can leverage request duration for logging purposes, the Response Ops team can use request duration for their internal logic (stop executing a slow query. for example).
It doesn't seem that we can mutate observability event content, but we can store requestStartTimestamp time on the transport level:

class KibanaTransport extends Transport {
  async request (params, options = {}) {
    options.context = { requestStartTimestamp: Date.now() }
    return super.request(params, options)
  }
}
// in obs events:
const took = Date.now()- event.meta.context.startTime;

Although, it would be awesome if we find a way to calculate the duration only once in the Core.

[mikecote]

@mshustov, keep us posted, we will go with our custom wrapper method at this time, but as soon as you have something to use, we can look into refactoring.

the Response Ops team can use request duration for their internal logic (stop executing a slow query. for example).

Our intent for stopping slow queries is to stop them when task manager determines the task ran for too long (abort existing searches when task manager sends a cancel execution signal). So I believe an event approach may not suit this use case but not sure.

cc @elastic/response-ops-execution

[pgayvallet]

Although, it would be awesome if we find a way to calculate the duration only once in the Core.

elastic/elastic-transport-js#40 is imho the exact implementation we'd like to have.

If we want to implement the same feature from within core, to have something like

const { body, meta } = await client.ping({}, { meta: true });
const { duration } = meta;

We can for sure implement the logic in our custom Transport, but we will also need a way to extend the TransportResult and/or DiagnosticResult type to add this new meta.duration field. I don't see any easy way to do what without an ugly declare module statement to overload the client's types, which I don't like one bit.

Also, if this field is added from within our transport, I wonder if it would also be added to the events which are, from my understanding, emitted from lower (but need to confirm that, cc @delvedor)

client.diagnostic.on('response', (error, event) => {
  // will event.meta.duration be populated here?
});

[pgayvallet]

Parent was closed, closing this one too