Kibana crashes with ECONNRESET when connection to remote cluster is lost due to unhandled promises

[sorenlouv]

The problem
Kibana crashes with ECONNRESET error when connection to Elasticsearch cluster is lost (I assume this is the problem)

Expectation
Kibana should not crash when connection to Elasticsearch cluster is lost

Reproduction

This happens on my local developer machine when running yarn start and connecting to an external (cloud based) elasticsearch cluster. If I close the laptop lid and thus disable network, Kibana crashes after about 1 hour.

First I see the following lines:

[warning][kibanaUsageCollection][plugins] Average event loop delay threshold exceeded 350ms. Received 2654.3637022916055ms. See https://ela.st/kibana-scaling-considerations for more information about scaling Kibana.
[error][plugins][taskManager] [Task Poller Monitor]: Observable Monitor: Hung Observable restarted after 33000ms of inactivity
[warning][plugins][taskManager] Detected potential performance issue with Task Manager. Set 'xpack.task_manager.monitored_stats_health_verbose_log.enabled: true' in your Kibana.yml to enable debug logging
[info][status] Kibana is now unavailable (was available)
[info][status] Kibana is now available (was unavailable)

Then after a few more minutes I see:

[warning][kibanaUsageCollection][plugins] Average event loop delay threshold exceeded 350ms. Received 577.03415997404ms. See https://ela.st/kibana-scaling-considerations for more information about scaling Kibana.
[error][plugins][taskManager] [Task Poller Monitor]: Observable Monitor: Hung Observable restarted after 33000ms of inactivity
[warning][plugins][taskManager] Detected potential performance issue with Task Manager. Set 'xpack.task_manager.monitored_stats_health_verbose_log.enabled: true' in your Kibana.yml to enable debug logging

And then it crashes with:

Unhandled Promise rejection detected:

ConnectionError: read ECONNRESET
    at ClientRequest.onError (/Users/sqren/elastic/kibana/node_modules/@elastic/elasticsearch/lib/Connection.js:116:16)
    at ClientRequest.emit (events.js:400:28)
    at TLSSocket.socketErrorListener (_http_client.js:475:9)
    at TLSSocket.emit (events.js:400:28)
    at emitErrorNT (internal/streams/destroy.js:106:8)
    at emitErrorCloseNT (internal/streams/destroy.js:74:3)
    at processTicksAndRejections (internal/process/task_queues.js:82:21) {
  meta: {
    body: null,
    statusCode: null,
    headers: null,
    meta: {
      context: null,
      request: [Object],
      name: 'elasticsearch-js',
      connection: [Object],
      attempts: 0,
      aborted: false
    }
  },
  isBoom: true,
  isServer: true,
  data: null,
  output: {
    statusCode: 503,
    payload: {
      statusCode: 503,
      error: 'Service Unavailable',
      message: 'read ECONNRESET'
    },
    headers: {}
  },
  [Symbol(SavedObjectsClientErrorCode)]: 'SavedObjectsClient/esUnavailable'
}

Terminating process...
 server crashed  with status code 1

[elasticmachine]

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

[sorenlouv]

Somewhat related to #101277 (fyi @mshustov)

[mshustov]

It looks like a plugin performing a request to the Elasticsearch server doesn't handle an exception.
It's hard to debug the problem without an error reproduction scenario or error stack. I'm not even sure we will get the error stack once the ES client drops callback-style API. (see elastic/elasticsearch-js#1542)
Have you seen any other log records with read ECONNRESET before the exception crashes the server?

[afharo]

It looks like a plugin performing a request to the Elasticsearch server doesn't handle an exception.

I tried to hunt it and, unfortunately, I found too many places:

• Timelion's start method calls a promise that is not handled: https://github.com/elastic/kibana/blob/master/src/plugins/timelion/server/plugin.ts#L71
• APM uses async/await in the .then after core.getStartServices(): https://github.com/elastic/kibana/blob/master/x-pack/plugins/apm/server/plugin.ts#L215-L244
• Same type of usage on another place in APM: https://github.com/elastic/kibana/blob/master/x-pack/plugins/apm/server/lib/apm_telemetry/index.ts#L132-L167 (mind that taskManagerStart.ensureScheduled also returns a promise.

I found a useful way to identify the calls making it fail: I created an ES mock that will always return 505 - and the received body to POST and PUT requests (for now). I can continue the investigation to find them all if we want to, although I'd suggest sending an email to Kibana Contributors, asking to each plugin owner to review their implementations to ensure that this is not happening.

However, we may need to document a common way to proceed when plugins need to create something: i.e.: what's the best retrying logic (maybe a core API to do so?).

[mshustov]

although I'd suggest sending an email to Kibana Contributors, asking to each plugin owner to review their implementations to ensure that this is not happening.

Yeah, I'm not sure we are able to find all such cases.
An email is a good start to draw attention to the problem. In the long run, we should provide recommendations on error handling #99568 IIRC @kobelb said he could do it later when he had some free time.

[mshustov]

@spalger found the same problem and fixed a few places in #111637
we discussed the problem on the last DX call, @spalger is going to give it a try https://github.com/typescript-eslint/typescript-eslint/blob/master/packages/eslint-plugin/docs/rules/no-floating-promises.md for the Core code. The main concern is it needs type information that might affect Eslint performance (see https://github.com/typescript-eslint/typescript-eslint/blob/master/docs/getting-started/linting/TYPED_LINTING.md#performance).
If the trial is successful, we could start rolling it to the other plugins.

[elasticmachine]

Pinging @elastic/kibana-alerting-services (Team:Alerting Services)

[rudolf]

@elastic/kibana-alerting-services Based on other's observations, this seems to happen after:

Observable Monitor: Hung Observable restarted after 33000ms of inactivity

It might just be coincidence though in that when ES is unavailable, task manager is the first to start failing.

[mikecote]

@elastic/kibana-alerting-services Based on other's observations, this seems to happen after:

Observable Monitor: Hung Observable restarted after 33000ms of inactivity

It might just be coincidence though in that when ES is unavailable, task manager is the first to start failing.

I think it's a coincidence because the task manager message happens whenever it detects that it didn't poll for a certain amount of time (33000ms in this case). Under the hood, I'm guessing the event loop resumes the function in task manager on wake, sees it's been some time since it polled and logs the message. I believe I've also seen this before when putting my laptop on sleep for a while.

@gmmorris can you confirm the above statement?

[gmmorris]

Indeed.
We have an observable that emit an event every time it's supposed to query ES.
We have another observable that emit an event after 30s and if the above mentioned observable has hung for whatever reason (and has failed to emit an event in the past 30s), then it restarts the observable.

It sounds like a symptom rather than the cause.

[afharo]

#181456 might finally address this