[APM] Wrap Elasticsearch client errors #91125

dgieselaar · 2021-02-11T13:02:32Z

The stack trace from the ES client is not useful, as it loses the context of where the client was called. To get a useful stack trace, we create a new error. Additionally, we override message.toString() to see full ES error when logging to console, instead of only request metadata.

@elastic/kibana-operations I am wondering if there's a better way for the console output. Maybe the console output can be fixed for all errors? From what I can tell there's already a specific function to output errors - we can perhaps use util.inspect(error, { depth: null }) there?

Before:

server    log   [10:34:45.814] [error][http] ResponseError: search_phase_execution_exception
    at onBody (/Users/dariogieselaar/dev/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:333:23)
    at IncomingMessage.onEnd (/Users/dariogieselaar/dev/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:260:11)
    at IncomingMessage.elasticAPMCallbackWrapper (/Users/dariogieselaar/dev/kibana/node_modules/elastic-apm-node/lib/instrumentation/index.js:310:27)
    at IncomingMessage.emit (events.js:327:22)
    at endReadableNT (internal/streams/readable.js:1327:12)
    at processTicksAndRejections (internal/process/task_queues.js:80:21) {
  meta: {
    body: { error: [Object], status: 400 },
    statusCode: 400,
    headers: {
      'content-length': '1591',
      'content-type': 'application/json; charset=UTF-8',
      date: 'Sat, 13 Feb 2021 09:34:45 GMT'
    },
    meta: {
      context: null,
      request: [Object],
      name: 'elasticsearch-js',
      connection: [Object],
      attempts: 0,
      aborted: false
    }
  }
}
Sending error to Elastic APM { id: 'f8af19a4fe7bf42bb847b4a98f7b7e4c' }
server   error  [10:34:44.381]  Error: Internal Server Error
    at HapiResponseAdapter.toInternalError (/Users/dariogieselaar/dev/kibana/src/core/server/http/router/response_adapter.ts:49:19)
    at Router.handle (/Users/dariogieselaar/dev/kibana/src/core/server/http/router/router.ts:286:34)
    at runMicrotasks (<anonymous>)
    at processTicksAndRejections (internal/process/task_queues.js:93:5)
    at handler (/Users/dariogieselaar/dev/kibana/src/core/server/http/router/router.ts:227:11)
    at exports.Manager.execute (/Users/dariogieselaar/dev/kibana/node_modules/@hapi/hapi/lib/toolkit.js:60:28)
    at Object.internals.handler (/Users/dariogieselaar/dev/kibana/node_modules/@hapi/hapi/lib/handler.js:46:20)
    at exports.execute (/Users/dariogieselaar/dev/kibana/node_modules/@hapi/hapi/lib/handler.js:31:20)
    at Request._lifecycle (/Users/dariogieselaar/dev/kibana/node_modules/@hapi/hapi/lib/request.js:370:32)
    at Request._execute (/Users/dariogieselaar/dev/kibana/node_modules/@hapi/hapi/lib/request.js:279:9)
Sending error to Elastic APM { id: '1ee3026db1e021e7596628701dfd408a' }

After:

server    log   [10:39:05.621] [error][http] WrappedElasticsearchClientError: search_phase_execution_exception
    at /Users/dariogieselaar/dev/kibana/x-pack/plugins/observability/server/utils/unwrap_es_response.ts:46:13
    at processTicksAndRejections (internal/process/task_queues.js:93:5)
    at /Users/dariogieselaar/dev/kibana/x-pack/plugins/apm/server/lib/services/get_service_transaction_group_comparison_statistics.ts:70:24
    at /Users/dariogieselaar/dev/kibana/x-pack/plugins/apm/server/routes/create_api/index.ts:123:28
    at Router.handle (/Users/dariogieselaar/dev/kibana/src/core/server/http/router/router.ts:272:30)
    at handler (/Users/dariogieselaar/dev/kibana/src/core/server/http/router/router.ts:227:11)
    at exports.Manager.execute (/Users/dariogieselaar/dev/kibana/node_modules/@hapi/hapi/lib/toolkit.js:60:28)
    at Object.internals.handler (/Users/dariogieselaar/dev/kibana/node_modules/@hapi/hapi/lib/handler.js:46:20)
    at exports.execute (/Users/dariogieselaar/dev/kibana/node_modules/@hapi/hapi/lib/handler.js:31:20)
    at Request._lifecycle (/Users/dariogieselaar/dev/kibana/node_modules/@hapi/hapi/lib/request.js:370:32)
    at Request._execute (/Users/dariogieselaar/dev/kibana/node_modules/@hapi/hapi/lib/request.js:279:9)
Response: {
  error: {
    root_cause: [
      {
        type: 'illegal_argument_exception',
        reason: 'The mode parameter is only supported with field or script'
      },
      {
        type: 'illegal_argument_exception',
        reason: 'The mode parameter is only supported with field or script'
      },
      {
        type: 'illegal_argument_exception',
        reason: 'The mode parameter is only supported with field or script'
      },
      {
        type: 'illegal_argument_exception',
        reason: 'The mode parameter is only supported with field or script'
      }
    ],
    type: 'search_phase_execution_exception',
    reason: '',
    phase: 'fetch',
    grouped: true,
    failed_shards: [
      {
        shard: 0,
        index: 'apm-8.0.0-error-2020.12.03-000009',
        node: 'XMRop47YSAOtd9hRXn_i4w',
        reason: {
          type: 'illegal_argument_exception',
          reason: 'The mode parameter is only supported with field or script'
        }
      },
      {
        shard: 0,
        index: 'apm-8.0.0-metric-2020.12.03-000009',
        node: 'w7JFZCU5TEOUnO2A8rH-wA',
        reason: {
          type: 'illegal_argument_exception',
          reason: 'The mode parameter is only supported with field or script'
        }
      },
      {
        shard: 0,
        index: 'apm-8.0.0-span-2020.12.03-000011',
        node: 'tHLgfNYATY2J5g9THCXOLg',
        reason: {
          type: 'illegal_argument_exception',
          reason: 'The mode parameter is only supported with field or script'
        }
      },
      {
        shard: 0,
        index: 'apm-8.0.0-transaction-2020.12.03-000009',
        node: 'XMRop47YSAOtd9hRXn_i4w',
        reason: {
          type: 'illegal_argument_exception',
          reason: 'The mode parameter is only supported with field or script'
        }
      }
    ],
    caused_by: {
      type: 'null_pointer_exception',
      reason: 'Cannot invoke "org.elasticsearch.search.aggregations.InternalAggregations.getSerializedSize()" because "reducePhase.aggregations" is null'
    }
  },
  status: 400
}
 {
  originalError: ResponseError: search_phase_execution_exception
      at onBody (/Users/dariogieselaar/dev/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:333:23)
      at IncomingMessage.onEnd (/Users/dariogieselaar/dev/kibana/node_modules/@elastic/elasticsearch/lib/Transport.js:260:11)
      at IncomingMessage.elasticAPMCallbackWrapper (/Users/dariogieselaar/dev/kibana/node_modules/elastic-apm-node/lib/instrumentation/index.js:310:27)
      at IncomingMessage.emit (events.js:327:22)
      at endReadableNT (internal/streams/readable.js:1327:12)
      at processTicksAndRejections (internal/process/task_queues.js:80:21) {
    meta: {
      body: [Object],
      statusCode: 400,
      headers: [Object],
      meta: [Object]
    }
  }
}
Sending error to Elastic APM { id: 'f753eeb0f853ce13490ddef7485a3ec7' }
server   error  [10:39:03.657]  Error: Internal Server Error
    at HapiResponseAdapter.toInternalError (/Users/dariogieselaar/dev/kibana/src/core/server/http/router/response_adapter.ts:49:19)
    at Router.handle (/Users/dariogieselaar/dev/kibana/src/core/server/http/router/router.ts:286:34)
    at processTicksAndRejections (internal/process/task_queues.js:93:5)
    at handler (/Users/dariogieselaar/dev/kibana/src/core/server/http/router/router.ts:227:11)
    at exports.Manager.execute (/Users/dariogieselaar/dev/kibana/node_modules/@hapi/hapi/lib/toolkit.js:60:28)
    at Object.internals.handler (/Users/dariogieselaar/dev/kibana/node_modules/@hapi/hapi/lib/handler.js:46:20)
    at exports.execute (/Users/dariogieselaar/dev/kibana/node_modules/@hapi/hapi/lib/handler.js:31:20)
    at Request._lifecycle (/Users/dariogieselaar/dev/kibana/node_modules/@hapi/hapi/lib/request.js:370:32)
    at Request._execute (/Users/dariogieselaar/dev/kibana/node_modules/@hapi/hapi/lib/request.js:279:9)
Sending error to Elastic APM { id: '0a6054554cd0b303dbc2bd7a180b42ce' }

The stack trace from the ES client is not useful, as it loses the context of where the client was called. To get a useful stack trace, we create a new error. Additionally, we override message.toString() to see full ES error when logging to console.

elasticmachine · 2021-02-11T20:34:28Z

Pinging @elastic/apm-ui (Team:apm)

dgieselaar · 2021-02-12T13:54:34Z

@elasticmachine merge upstream

…p-es-error

sorenlouv

Nice improvement!

sorenlouv · 2021-02-13T00:19:13Z

x-pack/plugins/observability/server/utils/unwrap_es_response.ts

+    .then((res) => res.body)
+    .catch((err) => {
+      // make sure stacktrace is relative to where client was called
+      throw new WrappedElasticsearchClientError(err);


Not sure you can use it for anything in this context but have you played around with Error.captureStackTrace ?

I did, but that won't allow me to change the output of the error in the console. But I'll talk to some ops folks to see if we can address that issue for all errors rather than this hack.

kibanamachine · 2021-02-16T12:50:14Z

💚 Build Succeeded

continuous-integration/kibana-ci/pull-request
Commit: 8f20267

Metrics [docs]

✅ unchanged

History

💛 Build #106417 was flaky b6f4a1c
💚 Build #106395 succeeded f908f90
💚 Build #106367 succeeded d308fa6
💛 Build #106214 was flaky 2e3362a
💔 Build #106013 failed e9fd2b2

To update your PR or re-run it, just comment with:
@elasticmachine merge upstream

spalger · 2021-02-16T17:36:21Z

@dgieselaar I think @elastic/kibana-core would be better equipped to help determine if there's a good place to log failures like this, we don't manage the loggers or ES client infrastructure used in the Kibana server.

dgieselaar · 2021-02-17T08:28:40Z

@spalger ah, TIL, thanks - I spoke to @rudolf about it already and I think he will talk to Tomas to figure out something that works for everybody by default. I'll merge this one in for now.

Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com>

kibanamachine · 2021-02-17T08:31:40Z

💚 Backport successful

✅ 7.x / #91608

Successful backport PRs will be merged automatically after passing CI.

Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com> Co-authored-by: Dario Gieselaar <dario.gieselaar@elastic.co>

* master: (157 commits) [DOCS] Adds machine learning to the security section of alerting (elastic#91501) [Uptime] Ping list step screenshot caption formatting (elastic#91403) [Vislib] Use timestamp on brush event instead of iso dates (elastic#91483) [Application Usage] Remove deprecated & unused legacy.appChanged API (elastic#91464) Migrate logstash, monitoring, url_drilldowns, xpack_legacy to ts projects (elastic#91194) [APM] Wrap Elasticsearch client errors (elastic#91125) [APM] Fix optimize-tsconfig script (elastic#91487) [Discover][docs] Add searchFieldsFromSource description (elastic#90980) Adds support for 'ip' data type (elastic#85087) [Detection Rules] Add updates from 7.11.2 rules (elastic#91553) [SECURITY SOLUTION] Eql in timeline (elastic#90816) [APM] Correlations Beta (elastic#86477) (elastic#89952) [Security Solutions][Detection Engine] Adds a warning banner when the alerts data has not been migrated yet. (elastic#90258) [Security Solution] [Timeline] Endpoint row renderers (2nd batch) (elastic#91446) skip flaky suite (elastic#91450) skip flaky suite (elastic#91592) [Security Solution][Endpoint][Admin] Endpoint Details UX Enhancements (elastic#90870) [ML] Add better UI support for runtime fields Transforms (elastic#90363) [Security Solution] [Detections] Replace 'partial failure' with 'warning' for rule statuses (elastic#91167) [Security Solution][Detections] Adds Indicator path config for indicator match rules (elastic#91260) ...

dgieselaar added release_note:skip Skip the PR/issue when compiling release notes v7.12.0 auto-backport Deprecated - use backport:version if exact versions are needed labels Feb 11, 2021

Unwrap error in get_stored_annotations

2e3362a

dgieselaar requested a review from a team as a code owner February 11, 2021 20:34

botelastic bot added the Team:APM All issues that need APM UI Team support label Feb 11, 2021

kibanamachine and others added 3 commits February 12, 2021 08:54

Merge branch 'master' into wrap-es-error

d308fa6

Merge branch 'master' of github.com:elastic/kibana into wrap-es-error

c1fa633

Merge branch 'wrap-es-error' of github.com:dgieselaar/kibana into wra…

f908f90

…p-es-error

sorenlouv approved these changes Feb 13, 2021

View reviewed changes

sorenlouv reviewed Feb 13, 2021

View reviewed changes

dgieselaar requested a review from a team February 13, 2021 09:42

dgieselaar added 2 commits February 13, 2021 10:43

Merge branch 'master' of github.com:elastic/kibana into wrap-es-error

b6f4a1c

Merge branch 'master' of github.com:elastic/kibana into wrap-es-error

8f20267

dgieselaar removed the request for review from a team February 17, 2021 08:27

dgieselaar merged commit b71f49f into elastic:master Feb 17, 2021

dgieselaar deleted the wrap-es-error branch February 17, 2021 08:28

kibanamachine added a commit to kibanamachine/kibana that referenced this pull request Feb 17, 2021

[APM] Wrap Elasticsearch client errors (elastic#91125)

a7320a0

Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com>

kibanamachine mentioned this pull request Feb 17, 2021

[7.x] [APM] Wrap Elasticsearch client errors (#91125) #91608

Merged

kibanamachine added a commit that referenced this pull request Feb 17, 2021

[APM] Wrap Elasticsearch client errors (#91125) (#91608)

46b73b5

Co-authored-by: Kibana Machine <42973632+kibanamachine@users.noreply.github.com> Co-authored-by: Dario Gieselaar <dario.gieselaar@elastic.co>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[APM] Wrap Elasticsearch client errors #91125

[APM] Wrap Elasticsearch client errors #91125

dgieselaar commented Feb 11, 2021 •

edited

Loading

elasticmachine commented Feb 11, 2021

dgieselaar commented Feb 12, 2021

sorenlouv left a comment

sorenlouv Feb 13, 2021

dgieselaar Feb 13, 2021

kibanamachine commented Feb 16, 2021

spalger commented Feb 16, 2021

dgieselaar commented Feb 17, 2021

kibanamachine commented Feb 17, 2021

[APM] Wrap Elasticsearch client errors #91125

[APM] Wrap Elasticsearch client errors #91125

Conversation

dgieselaar commented Feb 11, 2021 • edited Loading

elasticmachine commented Feb 11, 2021

dgieselaar commented Feb 12, 2021

sorenlouv left a comment

Choose a reason for hiding this comment

sorenlouv Feb 13, 2021

Choose a reason for hiding this comment

dgieselaar Feb 13, 2021

Choose a reason for hiding this comment

kibanamachine commented Feb 16, 2021

💚 Build Succeeded

Metrics [docs]

History

spalger commented Feb 16, 2021

dgieselaar commented Feb 17, 2021

kibanamachine commented Feb 17, 2021

💚 Backport successful

dgieselaar commented Feb 11, 2021 •

edited

Loading