Non-deterministic behavior while installing a package

[mtojek]

This PR elastic/package-storage#370 introduces an update AWS package. The update might be faulty, so Kibana rejects it with HTTP 500. Unfortunately it says nothing, but "Bad request" (side issue: error reporting for developer purposes should be improved).

I clicked the Install button second time and it worked without any problems. See screenshots, I'm not sure if it works or not.

/cc @ruflin @kaiyan-sheng

[elasticmachine]

Pinging @elastic/ingest-management (Team:Ingest Management)

[ruflin]

@jfsiii You might know here as you spent some time on improving the error handling / error messaging.

[jfsiii]

We have a ticket to improve error handling #66688

The issue description says a 500 code but I believe 'Bad Request' is a 400.

I thought it might be an outdated package, but I see we are using 400 for unknown errors as well (for now, unknown errors will be 500 again soon)

kibana/x-pack/plugins/ingest_manager/server/errors.ts

Lines 22 to 26 in fec0d51

	if (error instanceof PackageOutdatedError) {
	return 400;
	} else {
	return 400; // Bad Request
	}

I'll look into it, especially regarding the error message, but @neptunian would better know what might be going on with the installation.

[mtojek]

@jfsiii I put more details about the error in this PR: elastic/package-storage#370 (comment) . It looks that it's reported as HTTP 500.

[skh]

I think the relevant parts of the proposal in #66688 for this situation are:

• Create a descriptive error message as close as possible to the place where the error happens
• Log that error message in the route handler
• Return that error message in the HTTP response (because cloud users can't access the Kibana log)
• As the stack trace for all 500 errors will come from within platform code, log the stack trace of the error before passing a 500 error to the platform, e.g. by also logging the stack trace in the route handler.

[neptunian]

@skh @jfsiii Creating a package policy calls ensureInstalledPackage and which calls installLatestPackage which calls installPackage. It doesn't use the api and so it doesn't benefit from the error handling in installPackageHandler. This also occurs in /setup and a few other places. I mentioned this concern to @ruflin yesterday. Any reason why we can't directly call our API instead of installPackage?

[skh]

@neptunian But there must be some route handler handling the request triggering the error, is there a reason why we can't add error handling to that handler?

[neptunian]

@skh Yes, the handler is createPackagePolicyHandler.

We have all this error handling specific to installing a package in the installPackageHandler. Such as removing the package if it failed or reinstalling a previous package if the update failed.

[jfsiii]

@skh agreed, I have a WIP at #74409 which does that

@neptunian indeed, I've been in that code recently with #75372 and #74409.

We don't want to incur the cost of creating/handling those new connections. We also may need to pass requests around to access current user info, etc. It'd be a big change in approach. We can talk about it more anywhere outside this ticket if you want.

@mtojek I ran the mage -debug testIntegration command and got the failing result. Can you post steps here or find me on Slack/Zoom to get it so I can POST to that route and see the failure? Maybe we edit a test file?

[mtojek]

Steps to reproduce it:

1. Git checkout the branch behind the PR: [snapshot] Update "aws" integration to version 0.2.7 package-storage#370 (problem is related to the AWS packages
2. mage build
3. mage -debug testIntegration - this command will spin up stack with Kibana, ES and package-registry.

Actually you don't need to anything special, just try to serve and install the latest aws package even via the Kibana UI.

[jfsiii]

@mtojek thanks, those are the steps I took before posting. I can see the tests failing w/500 vs 200, but I don't know how to stand up the same stack the tests are using and run HTTP / ES requests.

Update: I just found https://github.com/elastic/package-storage/blob/master/testing/environments/README.md

I ran those docker compose commands and now I am executing requests. This will be very helpful!

[jfsiii]

Steps for me or anyone else following along:

1. Git checkout the branch behind the PR: [snapshot] Update "aws" integration to version 0.2.7 package-storage#370 (problem is related to the AWS packages
2. mage build
3. cd testing/environments/
4. docker-compose commands from the README:
   docker-compose -f snapshot.yml pull
docker-compose -f snapshot.yml -f local.yml up --force-recreate
5. in separate window, run HTTP requests (or view Kibana at http://localhost:5601/, etc)

I can now reproduce this error with

$ curl --user elastic:changeme -X POST http://localhost:5601/api/ingest_manager/epm/packages/aws-0.2.7 -H 'kbn-xsrf: xyz'
{"statusCode":500,"error":"Internal Server Error","message":"Bad Request"}

Now I'll try to run a local kibana branch like https://github.com/jfsiii/kibana/tree/ingest-default-error-handler against this local registry and do what I can to improve the error reporting. I'll report back later today (I'm afk for a few more hours)

[jfsiii]

Maybe I'm not afk :)

I ran that registry locally in my https://github.com/jfsiii/kibana/tree/ingest-default-error-handler branch

I ran this in one window

curl --user elastic:changeme -X POST http://localhost:5601/api/ingest_manager/epm/packages/aws-0.2.7 -H 'kbn-xsrf: xyz'
{"statusCode":500,"error":"Internal Server Error","message":"Bad Request"}

and saw this in the logs

server    log   [10:11:36.617] [error][ingestManager][plugins] Error: error deleting pipeline logs-aws.cloudtrail-0.2.7
    at deletePipeline (/Users/jfsiii/work/kibana/x-pack/plugins/ingest_manager/server/services/epm/elasticsearch/ingest_pipeline/remove.ts:63:13)
    at process._tickCallback (internal/process/next_tick.js:68:7)
server    log   [10:11:37.515] [error][ingestManager][plugins] { Error: Bad Request
    at respond (/Users/jfsiii/work/kibana/node_modules/elasticsearch/src/lib/transport.js:349:15)
    at checkRespForFailure (/Users/jfsiii/work/kibana/node_modules/elasticsearch/src/lib/transport.js:306:7)
    at HttpConnector.<anonymous> (/Users/jfsiii/work/kibana/node_modules/elasticsearch/src/lib/connectors/http.js:173:7)
    at IncomingMessage.wrapper (/Users/jfsiii/work/kibana/node_modules/lodash/lodash.js:4949:19)
    at IncomingMessage.emit (events.js:203:15)
    at endReadableNT (_stream_readable.js:1145:12)
    at process._tickCallback (internal/process/next_tick.js:63:19)
  status: 400,
  displayName: 'BadRequest',
  message: 'Bad Request',
  path: '/_ingest/pipeline/logs-aws.cloudtrail-0.2.7',
  query: undefined,
  body:
   '---\nerror:\n  root_cause:\n  - type: "parse_exception"\n    reason: "Failed to parse content to map"\n  type: "parse_exception"\n  reason: "Failed to parse content to map"\n  caused_by:\n    type: "json_parse_exception"\n    reason: "Duplicate field \'ListGroupsForUser\'\\n at [Source: (org.elasticsearch.common.bytes.AbstractBytesReference$MarkSupportingStreamInputWrapper);\\\n      \\ line: 489, column: 26]"\nstatus: 400\n',
  statusCode: 400,
  response:
   '---\nerror:\n  root_cause:\n  - type: "parse_exception"\n    reason: "Failed to parse content to map"\n  type: "parse_exception"\n  reason: "Failed to parse content to map"\n  caused_by:\n    type: "json_parse_exception"\n    reason: "Duplicate field \'ListGroupsForUser\'\\n at [Source: (org.elasticsearch.common.bytes.AbstractBytesReference$MarkSupportingStreamInputWrapper);\\\n      \\ line: 489, column: 26]"\nstatus: 400\n',
  toString: [Function],
  toJSON: [Function] }
server   error  [10:11:31.963]  Error: Internal Server Error
    at HapiResponseAdapter.toError (/Users/jfsiii/work/kibana/src/core/server/http/router/response_adapter.ts:129:19)
    at HapiResponseAdapter.toHapiResponse (/Users/jfsiii/work/kibana/src/core/server/http/router/response_adapter.ts:79:19)
    at HapiResponseAdapter.handle (/Users/jfsiii/work/kibana/src/core/server/http/router/response_adapter.ts:74:17)
    at Router.handle (/Users/jfsiii/work/kibana/src/core/server/http/router/router.ts:273:34)
    at process._tickCallback (internal/process/next_tick.js:68:7)

Root cause aside, what status code and message would most helpful/appropriate for the response to /api/ingest_manager/epm/packages/aws-0.2.7 ?

[kaiyan-sheng]

@leehinman Does this error message look familiar? ^^