Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[POC] Fleet agent concurrency #70495

Closed
wants to merge 3 commits into from

Conversation

kobelb
Copy link
Contributor

@kobelb kobelb commented Jul 1, 2020

This is a proof-of-concept for implementing concurrency controls for a maximum number of agents being connected to a single instance of Kibana. There are some deficiencies and open questions inline using PR comments.

Proof-of-concept for #67987

@@ -282,7 +282,7 @@ export class HttpServer {
this.log.warn(`registerOnPreAuth called after stop`);
}

this.server.ext('onRequest', adoptToHapiOnPreAuthFormat(fn, this.log));
this.server.ext('onPreAuth', adoptToHapiOnPreAuthFormat(fn, this.log));
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The onRequest lifecycle event occurs prior to "route lookup", which prevented the use of request.route.options.tags within the pre-auth handler to determine whether or not the route is a fleet-agent specific. Changing this from onRequest to onPreAuth fixes this specific issue, but potentially introduces others.

@restrry this was originally using onRequest as part of #36690, are you aware of any reason why this can't be changed to onPreAuth instead?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

onRequest was required to support Spaces rewriting url.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Gotcha, thanks! Could we theoretically change http.registerOnPreAuth to use onPreAuth, and introduce a http.registerOnPreRouting which uses onRequest?

Copy link
Contributor

@mshustov mshustov Jul 3, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Gotcha, thanks! Could we theoretically change http.registerOnPreAuth to use onPreAuth, and introduce a http.registerOnPreRouting which uses onRequest?

Yeah, it shouldn't be that hard. I want to make sure it's necessary to extend API for the current implementation. Let me know and the platform team can provide an interceptor implementation

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@kobelb I put up PR #70775

);
core.http.registerOnPreResponse(
(request: KibanaRequest, preResponse: OnPreResponseInfo, toolkit: OnPreResponseToolkit) => {
if (isAgentRequest(request) && preResponse.statusCode !== 429) {
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This assumes that only the pre-auth handler could cause a response with status code 429, which isn't absolutely certain. It's possible that one of the HTTP route handlers is replying with a 429 itself, or propagating a 429 from Elasticsearch, which would mess up the counter.

The request object is different from the pre-auth to the pre-response, so I wasn't able to use a Set or WeakSet to track whether or not this was a 429 that we returned from within the pre-auth handler... Any other ideas?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can the preAuth handler make a value accessible to the preResponse handler?

We're moving towards using errors like FleetTooManyAgentsError so if there's any way to make new FleetTooManyAgentsError('Too Many Agents') available in the response handler it could do typeof FleetTooManyAgentsError

Copy link
Contributor

@mshustov mshustov Jul 2, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we wrap Ingest manager specific route handlers in a function instead of adding global interceptors? https://github.com/elastic/kibana/pull/70495/files#diff-280f58825bd033ffbe7792f8423f6122R88
I'm also not sure that we want to provide access to response data in interceptors.

Copy link
Contributor

@mshustov mshustov Jul 2, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

something along lines (not tested):

import { RequestHandlerWrapper } from 'src/core/server';
class Lock {
  constructor(private readonly maxConnections: number = 1) {}
  private counter = 0;
  increase() {
    this.counter += 1;
  }
  decrease() {
    this.counter += 1;
  }
  canHandle() {
    return this.counter < this.maxConnections;
  }
}
const lock = new Lock();
export const concurrencyLimit: RequestHandlerWrapper = (handler) => {
  return async (context, request, response) => {
    if (!lock.canHandle()) {
      return response.customError({ body: 'Too Many Agents', statusCode: 429 });
    }
    try {
      lock.increase();
      return handler(context, request, response);
    } finally {
      lock.decrease();
    }
  };
};

concurrencyLimit(postAgentEnrollHandler);
concurrencyLimit(postAgentCheckinHandler);

Copy link
Contributor

@roncohen roncohen Jul 2, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this doesn't let us reject traffic without validating API Keys as described here, right?

Copy link
Contributor

@mshustov mshustov Jul 2, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah... I haven't seen the comment. Now I'm surprised that the auth has such a huge penalty.

As @kobelb mentioned, it's critical that we can reject incoming traffic as cheaply as possible. It translates to saved $$ for our customers, making us able to offer a more competitive solution.

@kobelb for what use-cases we should consider this as a critical option? Auth & spaces do a huge number of requests to ES on every page load.
Would server session help to reduce the number of requests? Does this problem exist for API keys only?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fleet's usage of Kibana APIs is different than our traditional usage. The Elastic Agent will be using Kibana APIs to enroll themselves and retrieve their configuration. As such, we're potentially dealing with thousands of Elastic Agents hitting these APIs... Whether or not this is "critical" is debatable and largely dependent on what the ingest-management team is seeing during their load-testing, but skipping auth reduces the load on Kibana when this circuit breaker is hit.

@roncohen despite the current implementation being imperfect and potentially misinterpreting the 429, can we perform load-testing with the circuit breaking being done before authentication and after authentication to determine what type of impact this has on Fleet's scalability?

Would server session help to reduce the number of requests?

I don't think it will, Kibana will still have to make a query to Elasticsearch to return the server-side session document to authenticate the user.

Does this problem exist for API keys only?

Any call to an Elasticsearch API will incur some performance penalty. However, there are differences in the caching strategy for API Keys vs username/password. Regardless of the type of credentials, performing any unnecessary work before their circuit breaker has a chance to short-circuit the operation is inefficient.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@roncohen despite the current implementation being imperfect and potentially misinterpreting the 429, can we perform load-testing with the circuit breaking being done before authentication and after authentication to determine what type of impact this has on Fleet's scalability?

+1 I'd love to adjust the concurrency value (what should the value be) and merge this into master ASAP so we can test in cloud as we did with long polling

@@ -152,6 +157,35 @@ export class IngestManagerPlugin
}

public async setup(core: CoreSetup, deps: IngestManagerSetupDeps) {
const maxConcurrentRequests = 1;
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

All this logic was put here out of laziness, it should really be placed in another file...

@kobelb
Copy link
Contributor Author

kobelb commented Jul 1, 2020

@joshdover any input on the general approach and/or the limitations which I've explicitly noted?

@joshdover
Copy link
Contributor

@joshdover any input on the general approach and/or the limitations which I've explicitly noted?

What's the primary reason for executing this logic in the pre auth stage rather than in the regular request handler? Are we trying to avoid executing some expensive logic or are we just trying to register some behavior in single place?

If it's the latter, I would recommend implementing this as a wrapper or even a Proxy object around the IRouter interface that executes some logic on each request before invoking the actual route handler.

@kobelb
Copy link
Contributor Author

kobelb commented Jul 1, 2020

What's the primary reason for executing this logic in the pre auth stage rather than in the regular request handler? Are we trying to avoid executing some expensive logic or are we just trying to register some behavior in single place?

If it's the latter, I would recommend implementing this as a wrapper or even a Proxy object around the IRouter interface that executes some logic on each request before invoking the actual route handler.

It was intending to address #67987 (comment). Authenticating incurs some overhead, so if we can short-circuit before performing the authentication we minimize the load on Elasticsearch even more.

@roncohen
Copy link
Contributor

roncohen commented Jul 2, 2020

thanks so much for taking stab at this! I really appreciate the effort here. As @kobelb mentioned, it's critical that we can reject incoming traffic as cheaply as possible. It translates to saved $$ for our customers, making us able to offer a more competitive solution.

@kobelb
Copy link
Contributor Author

kobelb commented Jul 6, 2020

Thanks for getting #70775 together so quickly @restrry!

@roncohen, is my understanding correct that Fleet's performance tests can't be done against feature-branches? While I'd prefer to hold off on adding disparate onPreAuth and onPreRouting lifecycles until we know it's absolutely necessary, if the performance tests don't work against feature-branches, I'm not sure what other option we have...

@roncohen
Copy link
Contributor

roncohen commented Jul 7, 2020

@roncohen, is my understanding correct that Fleet's performance tests can't be done against feature-branches? While I'd prefer to hold off on adding disparate onPreAuth and onPreRouting lifecycles until we know it's absolutely necessary, if the performance tests don't work against feature-branches, I'm not sure what other option we have...

ccing @jfsiii and @scunningham: what do you think about testing this feature branch locally/self-hosted GCP instance just to compare the difference this makes? e.g. try to enroll 7k-10k agents over a very short period and see how Kibana/Elasticsearch does in the branch vs. master? A simple "autocannon" test would also be sufficient. It's probably worth trying out a few different maxConnections values, maybe 10, 100 and 1000.

@kobelb should we do a version/branch that doesn't add the OnPreAuth (meaning it'll do the API Key authentication against Elasticsearch on each request), but still limits calls to the actual route so we can compare if the preAuth hook is worth it?

@kobelb
Copy link
Contributor Author

kobelb commented Jul 7, 2020

@kobelb should we do a version/branch that doesn't add the OnPreAuth (meaning it'll do the API Key authentication against Elasticsearch on each request), but still limits calls to the actual route so we can compare if the preAuth hook is worth it?

As long as it's feasible, that'd be great.

@elastic elastic deleted a comment from elasticmachine Jul 7, 2020
@jfsiii
Copy link
Contributor

jfsiii commented Jul 8, 2020

@elasticmachine merge upstream

@kibanamachine
Copy link
Contributor

💔 Build Failed

Failed CI Steps


Test Failures

Chrome X-Pack UI Functional Tests.x-pack/test/functional/apps/discover/feature_controls/discover_spaces·ts.discover feature controls spaces space with no features disabled shows discover navlink

Link to Jenkins

Standard Out

[00:00:00]       │
[00:00:00]         └-: discover
[00:00:00]           └-> "before all" hook
[00:00:00]           └-: feature controls
[00:00:00]             └-> "before all" hook
[00:04:53]             └-: spaces
[00:04:53]               └-> "before all" hook
[00:04:53]               └-> "before all" hook
[00:04:53]                 │ info [logstash_functional] Loading "mappings.json"
[00:04:53]                 │ info [logstash_functional] Loading "data.json.gz"
[00:04:53]                 │ info [logstash_functional] Skipped restore for existing index "logstash-2015.09.22"
[00:04:53]                 │ info [logstash_functional] Skipped restore for existing index "logstash-2015.09.20"
[00:04:53]                 │ info [logstash_functional] Skipped restore for existing index "logstash-2015.09.21"
[00:04:54]               └-: space with no features disabled
[00:04:54]                 └-> "before all" hook
[00:04:54]                 └-> "before all" hook
[00:04:54]                   │ info [discover/feature_controls/spaces] Loading "mappings.json"
[00:04:54]                   │ info [discover/feature_controls/spaces] Loading "data.json"
[00:04:54]                   │ info [o.e.c.m.MetadataDeleteIndexService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_2/8i-XYmKAR52MWKwGsxxESA] deleting index
[00:04:54]                   │ info [o.e.c.m.MetadataDeleteIndexService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_1/POMVjRVsSSOH57A-4_3C1w] deleting index
[00:04:54]                   │ info [discover/feature_controls/spaces] Deleted existing index [".kibana_2",".kibana_1"]
[00:04:54]                   │ info [o.e.c.m.MetadataCreateIndexService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana] creating index, cause [api], templates [], shards [1]/[0]
[00:04:54]                   │ info [o.e.c.r.a.AllocationService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] current.health="GREEN" message="Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[.kibana][0]]])." previous.health="YELLOW" reason="shards started [[.kibana][0]]"
[00:04:54]                   │ info [discover/feature_controls/spaces] Created index ".kibana"
[00:04:54]                   │ debg [discover/feature_controls/spaces] ".kibana" settings {"index":{"number_of_shards":"1","auto_expand_replicas":"0-1","number_of_replicas":"0"}}
[00:04:54]                   │ info [discover/feature_controls/spaces] Indexed 4 docs into ".kibana"
[00:04:54]                   │ info [o.e.c.m.MetadataMappingService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana/eNqAPs84SJikmAUeHZ-lEQ] update_mapping [_doc]
[00:04:54]                   │ debg Migrating saved objects
[00:04:54]                   │ proc [kibana]   log   [11:00:00.611] [info][savedobjects-service] Creating index .kibana_2.
[00:04:54]                   │ info [o.e.c.m.MetadataCreateIndexService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_2] creating index, cause [api], templates [], shards [1]/[1]
[00:04:54]                   │ info [o.e.c.r.a.AllocationService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] updating number_of_replicas to [0] for indices [.kibana_2]
[00:04:54]                   │ info [o.e.c.r.a.AllocationService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] current.health="GREEN" message="Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[.kibana_2][0]]])." previous.health="YELLOW" reason="shards started [[.kibana_2][0]]"
[00:04:54]                   │ proc [kibana]   log   [11:00:00.681] [info][savedobjects-service] Reindexing .kibana to .kibana_1
[00:04:54]                   │ info [o.e.c.m.MetadataCreateIndexService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_1] creating index, cause [api], templates [], shards [1]/[1]
[00:04:54]                   │ info [o.e.c.r.a.AllocationService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] updating number_of_replicas to [0] for indices [.kibana_1]
[00:04:54]                   │ info [o.e.c.r.a.AllocationService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] current.health="GREEN" message="Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[.kibana_1][0]]])." previous.health="YELLOW" reason="shards started [[.kibana_1][0]]"
[00:04:54]                   │ info [o.e.t.LoggingTaskListener] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] 5738 finished with response BulkByScrollResponse[took=21.9ms,timed_out=false,sliceId=null,updated=0,created=4,deleted=0,batches=1,versionConflicts=0,noops=0,retries=0,throttledUntil=0s,bulk_failures=[],search_failures=[]]
[00:04:55]                   │ info [o.e.c.m.MetadataDeleteIndexService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana/eNqAPs84SJikmAUeHZ-lEQ] deleting index
[00:04:55]                   │ proc [kibana]   log   [11:00:01.043] [info][savedobjects-service] Migrating .kibana_1 saved objects to .kibana_2
[00:04:55]                   │ info [o.e.c.m.MetadataMappingService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_2/J0vRIsFAQxqUeDlrVFIDhA] update_mapping [_doc]
[00:04:55]                   │ info [o.e.c.m.MetadataMappingService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_2/J0vRIsFAQxqUeDlrVFIDhA] update_mapping [_doc]
[00:04:55]                   │ proc [kibana]   log   [11:00:01.146] [info][savedobjects-service] Pointing alias .kibana to .kibana_2.
[00:04:55]                   │ proc [kibana]   log   [11:00:01.189] [info][savedobjects-service] Finished in 579ms.
[00:04:55]                   │ debg applying update to kibana config: {"accessibility:disableAnimations":true,"dateFormat:tz":"UTC"}
[00:04:55]                   │ info [o.e.c.m.MetadataMappingService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_2/J0vRIsFAQxqUeDlrVFIDhA] update_mapping [_doc]
[00:04:56]                   │ debg creating space
[00:04:57]                   │ debg created space
[00:04:57]                 └-> shows discover navlink
[00:04:57]                   └-> "before each" hook: global before each
[00:04:57]                   │ debg navigating to home url: http://localhost:61111/s/custom_space/app/home#/
[00:04:57]                   │ debg navigate to: http://localhost:61111/s/custom_space/app/home#/
[00:04:57]                   │ proc [kibana]   log   [11:00:03.696] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:04:57]                   │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:04:57]                   │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:04:57]                   │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:04:57]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:04:57]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:04:57]                   │ proc [kibana]   generatedMessage: false,
[00:04:57]                   │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:04:57]                   │ proc [kibana]   code: 'ERR_ASSERTION',
[00:04:57]                   │ proc [kibana]   actual: false,
[00:04:57]                   │ proc [kibana]   expected: true,
[00:04:57]                   │ proc [kibana]   operator: '==' }
[00:04:57]                   │ proc [kibana]  error  [11:00:03.694]  Error: Internal Server Error
[00:04:57]                   │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:04:57]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:04:57]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:04:57]                   │ERROR browser[SEVERE] http://localhost:61111/s/custom_space/app/home?_t=1594206003691#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:04:57]                   │ debg ... sleep(700) start
[00:04:58]                   │ debg ... sleep(700) end
[00:04:58]                   │ debg returned from get, calling refresh
[00:04:58]                   │ proc [kibana]   log   [11:00:04.459] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:04:58]                   │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:04:58]                   │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:04:58]                   │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:04:58]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:04:58]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:04:58]                   │ proc [kibana]   generatedMessage: false,
[00:04:58]                   │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:04:58]                   │ proc [kibana]   code: 'ERR_ASSERTION',
[00:04:58]                   │ proc [kibana]   actual: false,
[00:04:58]                   │ proc [kibana]   expected: true,
[00:04:58]                   │ proc [kibana]   operator: '==' }
[00:04:58]                   │ proc [kibana]  error  [11:00:04.458]  Error: Internal Server Error
[00:04:58]                   │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:04:58]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:04:58]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:04:58]                   │ERROR browser[SEVERE] http://localhost:61111/s/custom_space/app/home?_t=1594206003691#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:04:58]                   │ debg currentUrl = http://localhost:61111/s/custom_space/app/home#/
[00:04:58]                   │          appUrl = http://localhost:61111/s/custom_space/app/home#/
[00:04:58]                   │ debg TestSubjects.find(kibanaChrome)
[00:04:58]                   │ debg Find.findByCssSelector('[data-test-subj="kibanaChrome"]') with timeout=60000
[00:05:59]                   │ debg --- retry.try error: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:05:59]                   │      Wait timed out after 61213ms
[00:06:00]                   │ debg navigate to: http://localhost:61111/s/custom_space/app/home#/
[00:06:00]                   │ proc [kibana]   log   [11:01:06.240] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:06:00]                   │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:06:00]                   │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:06:00]                   │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:06:00]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:06:00]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:06:00]                   │ proc [kibana]   generatedMessage: false,
[00:06:00]                   │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:06:00]                   │ proc [kibana]   code: 'ERR_ASSERTION',
[00:06:00]                   │ proc [kibana]   actual: false,
[00:06:00]                   │ proc [kibana]   expected: true,
[00:06:00]                   │ proc [kibana]   operator: '==' }
[00:06:00]                   │ proc [kibana]  error  [11:01:06.240]  Error: Internal Server Error
[00:06:00]                   │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:06:00]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:06:00]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:06:00]                   │ERROR browser[SEVERE] http://localhost:61111/s/custom_space/app/home?_t=1594206066236#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:06:00]                   │ debg ... sleep(700) start
[00:06:01]                   │ debg ... sleep(700) end
[00:06:01]                   │ debg returned from get, calling refresh
[00:06:01]                   │ proc [kibana]   log   [11:01:06.999] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:06:01]                   │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:06:01]                   │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:06:01]                   │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:06:01]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:06:01]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:06:01]                   │ proc [kibana]   generatedMessage: false,
[00:06:01]                   │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:06:01]                   │ proc [kibana]   code: 'ERR_ASSERTION',
[00:06:01]                   │ proc [kibana]   actual: false,
[00:06:01]                   │ proc [kibana]   expected: true,
[00:06:01]                   │ proc [kibana]   operator: '==' }
[00:06:01]                   │ proc [kibana]  error  [11:01:06.998]  Error: Internal Server Error
[00:06:01]                   │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:06:01]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:06:01]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:06:01]                   │ERROR browser[SEVERE] http://localhost:61111/s/custom_space/app/home?_t=1594206066236#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:06:01]                   │ debg currentUrl = http://localhost:61111/s/custom_space/app/home#/
[00:06:01]                   │          appUrl = http://localhost:61111/s/custom_space/app/home#/
[00:06:01]                   │ debg TestSubjects.find(kibanaChrome)
[00:06:01]                   │ debg Find.findByCssSelector('[data-test-subj="kibanaChrome"]') with timeout=60000
[00:07:02]                   │ debg --- retry.try error: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:07:02]                   │      Wait timed out after 61197ms
[00:07:02]                   │ debg --- retry.tryForTime error: retry.try timeout: TimeoutError: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:07:02]                   │      Wait timed out after 61197ms
[00:07:02]                   │          at /dev/shm/workspace/kibana/node_modules/selenium-webdriver/lib/webdriver.js:842:17
[00:07:02]                   │          at process._tickCallback (internal/process/next_tick.js:68:7)
[00:07:03]                   │ debg navigate to: http://localhost:61111/s/custom_space/app/home#/
[00:07:03]                   │ proc [kibana]   log   [11:02:09.267] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:07:03]                   │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:07:03]                   │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:07:03]                   │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:07:03]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:07:03]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:07:03]                   │ proc [kibana]   generatedMessage: false,
[00:07:03]                   │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:07:03]                   │ proc [kibana]   code: 'ERR_ASSERTION',
[00:07:03]                   │ proc [kibana]   actual: false,
[00:07:03]                   │ proc [kibana]   expected: true,
[00:07:03]                   │ proc [kibana]   operator: '==' }
[00:07:03]                   │ proc [kibana]  error  [11:02:09.266]  Error: Internal Server Error
[00:07:03]                   │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:07:03]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:07:03]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:07:03]                   │ERROR browser[SEVERE] http://localhost:61111/s/custom_space/app/home?_t=1594206129262#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:07:03]                   │ debg ... sleep(700) start
[00:07:04]                   │ debg ... sleep(700) end
[00:07:04]                   │ debg returned from get, calling refresh
[00:07:04]                   │ proc [kibana]   log   [11:02:10.022] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:07:04]                   │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:07:04]                   │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:07:04]                   │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:07:04]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:07:04]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:07:04]                   │ proc [kibana]   generatedMessage: false,
[00:07:04]                   │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:07:04]                   │ proc [kibana]   code: 'ERR_ASSERTION',
[00:07:04]                   │ proc [kibana]   actual: false,
[00:07:04]                   │ proc [kibana]   expected: true,
[00:07:04]                   │ proc [kibana]   operator: '==' }
[00:07:04]                   │ proc [kibana]  error  [11:02:10.022]  Error: Internal Server Error
[00:07:04]                   │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:07:04]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:07:04]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:07:04]                   │ERROR browser[SEVERE] http://localhost:61111/s/custom_space/app/home?_t=1594206129262#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:07:04]                   │ debg currentUrl = http://localhost:61111/s/custom_space/app/home#/
[00:07:04]                   │          appUrl = http://localhost:61111/s/custom_space/app/home#/
[00:07:04]                   │ debg TestSubjects.find(kibanaChrome)
[00:07:04]                   │ debg Find.findByCssSelector('[data-test-subj="kibanaChrome"]') with timeout=60000
[00:08:05]                   │ debg --- retry.try error: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:08:05]                   │      Wait timed out after 61151ms
[00:08:05]                   │ debg navigate to: http://localhost:61111/s/custom_space/app/home#/
[00:08:05]                   │ proc [kibana]   log   [11:03:11.740] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:08:05]                   │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:08:05]                   │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:08:05]                   │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:08:05]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:08:05]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:08:05]                   │ proc [kibana]   generatedMessage: false,
[00:08:05]                   │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:08:05]                   │ proc [kibana]   code: 'ERR_ASSERTION',
[00:08:05]                   │ proc [kibana]   actual: false,
[00:08:05]                   │ proc [kibana]   expected: true,
[00:08:05]                   │ proc [kibana]   operator: '==' }
[00:08:05]                   │ proc [kibana]  error  [11:03:11.739]  Error: Internal Server Error
[00:08:05]                   │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:08:05]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:08:05]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:08:06]                   │ERROR browser[SEVERE] http://localhost:61111/s/custom_space/app/home?_t=1594206191733#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:08:06]                   │ debg ... sleep(700) start
[00:08:06]                   │ debg ... sleep(700) end
[00:08:06]                   │ debg returned from get, calling refresh
[00:08:06]                   │ proc [kibana]   log   [11:03:12.499] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:08:06]                   │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:08:06]                   │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:08:06]                   │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:08:06]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:08:06]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:08:06]                   │ proc [kibana]   generatedMessage: false,
[00:08:06]                   │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:08:06]                   │ proc [kibana]   code: 'ERR_ASSERTION',
[00:08:06]                   │ proc [kibana]   actual: false,
[00:08:06]                   │ proc [kibana]   expected: true,
[00:08:06]                   │ proc [kibana]   operator: '==' }
[00:08:06]                   │ proc [kibana]  error  [11:03:12.498]  Error: Internal Server Error
[00:08:06]                   │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:08:06]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/11/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:08:06]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:08:06]                   │ERROR browser[SEVERE] http://localhost:61111/s/custom_space/app/home?_t=1594206191733#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:08:06]                   │ debg currentUrl = http://localhost:61111/s/custom_space/app/home#/
[00:08:06]                   │          appUrl = http://localhost:61111/s/custom_space/app/home#/
[00:08:06]                   │ debg TestSubjects.find(kibanaChrome)
[00:08:06]                   │ debg Find.findByCssSelector('[data-test-subj="kibanaChrome"]') with timeout=60000
[00:09:02]                   │ info [o.e.x.i.IndexLifecycleTransition] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] moving index [.kibana-event-log-8.0.0-000001] from [{"phase":"hot","action":"unfollow","name":"wait-for-follow-shard-tasks"}] to [{"phase":"hot","action":"unfollow","name":"pause-follower-index"}] in policy [kibana-event-log-policy]
[00:09:02]                   │ info [o.e.x.i.IndexLifecycleTransition] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] moving index [ilm-history-2-000001] from [{"phase":"hot","action":"unfollow","name":"wait-for-follow-shard-tasks"}] to [{"phase":"hot","action":"unfollow","name":"pause-follower-index"}] in policy [ilm-history-ilm-policy]
[00:09:02]                   │ info [o.e.x.i.IndexLifecycleTransition] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] moving index [.kibana-event-log-8.0.0-000001] from [{"phase":"hot","action":"unfollow","name":"pause-follower-index"}] to [{"phase":"hot","action":"unfollow","name":"close-follower-index"}] in policy [kibana-event-log-policy]
[00:09:02]                   │ info [o.e.x.i.IndexLifecycleTransition] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] moving index [ilm-history-2-000001] from [{"phase":"hot","action":"unfollow","name":"pause-follower-index"}] to [{"phase":"hot","action":"unfollow","name":"close-follower-index"}] in policy [ilm-history-ilm-policy]
[00:09:02]                   │ info [o.e.x.i.IndexLifecycleTransition] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] moving index [.kibana-event-log-8.0.0-000001] from [{"phase":"hot","action":"unfollow","name":"close-follower-index"}] to [{"phase":"hot","action":"unfollow","name":"unfollow-follower-index"}] in policy [kibana-event-log-policy]
[00:09:02]                   │ info [o.e.x.i.IndexLifecycleTransition] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] moving index [ilm-history-2-000001] from [{"phase":"hot","action":"unfollow","name":"close-follower-index"}] to [{"phase":"hot","action":"unfollow","name":"unfollow-follower-index"}] in policy [ilm-history-ilm-policy]
[00:09:02]                   │ info [o.e.x.i.IndexLifecycleTransition] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] moving index [.kibana-event-log-8.0.0-000001] from [{"phase":"hot","action":"unfollow","name":"unfollow-follower-index"}] to [{"phase":"hot","action":"unfollow","name":"open-follower-index"}] in policy [kibana-event-log-policy]
[00:09:02]                   │ info [o.e.x.i.IndexLifecycleTransition] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] moving index [ilm-history-2-000001] from [{"phase":"hot","action":"unfollow","name":"unfollow-follower-index"}] to [{"phase":"hot","action":"unfollow","name":"open-follower-index"}] in policy [ilm-history-ilm-policy]
[00:09:02]                   │ info [o.e.x.i.IndexLifecycleTransition] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] moving index [.kibana-event-log-8.0.0-000001] from [{"phase":"hot","action":"unfollow","name":"open-follower-index"}] to [{"phase":"hot","action":"unfollow","name":"wait-for-yellow-step"}] in policy [kibana-event-log-policy]
[00:09:02]                   │ info [o.e.x.i.IndexLifecycleTransition] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] moving index [ilm-history-2-000001] from [{"phase":"hot","action":"unfollow","name":"open-follower-index"}] to [{"phase":"hot","action":"unfollow","name":"wait-for-yellow-step"}] in policy [ilm-history-ilm-policy]
[00:09:02]                   │ info [o.e.x.i.IndexLifecycleTransition] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] moving index [.kibana-event-log-8.0.0-000001] from [{"phase":"hot","action":"unfollow","name":"wait-for-yellow-step"}] to [{"phase":"hot","action":"rollover","name":"check-rollover-ready"}] in policy [kibana-event-log-policy]
[00:09:02]                   │ info [o.e.x.i.IndexLifecycleTransition] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] moving index [ilm-history-2-000001] from [{"phase":"hot","action":"unfollow","name":"wait-for-yellow-step"}] to [{"phase":"hot","action":"rollover","name":"check-rollover-ready"}] in policy [ilm-history-ilm-policy]
[00:09:07]                   │ debg --- retry.try error: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:09:07]                   │      Wait timed out after 61189ms
[00:09:08]                   │ debg --- retry.tryForTime error: retry.try timeout: TimeoutError: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:09:08]                   │      Wait timed out after 61189ms
[00:09:08]                   │          at /dev/shm/workspace/kibana/node_modules/selenium-webdriver/lib/webdriver.js:842:17
[00:09:08]                   │          at process._tickCallback (internal/process/next_tick.js:68:7)
[00:09:08]                   │ info Taking screenshot "/dev/shm/workspace/parallel/11/kibana/x-pack/test/functional/screenshots/failure/discover feature controls spaces space with no features disabled shows discover navlink.png"
[00:09:09]                   │ info Current URL is: http://localhost:61111/s/custom_space/app/home#/
[00:09:09]                   │ info Saving page source to: /dev/shm/workspace/parallel/11/kibana/x-pack/test/functional/failure_debug/html/discover feature controls spaces space with no features disabled shows discover navlink.html
[00:09:09]                   └- ✖ fail: "discover feature controls spaces space with no features disabled shows discover navlink"
[00:09:09]                   │

Stack Trace

Error: retry.tryForTime timeout: Error: retry.try timeout: TimeoutError: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
Wait timed out after 61189ms
    at /dev/shm/workspace/kibana/node_modules/selenium-webdriver/lib/webdriver.js:842:17
    at process._tickCallback (internal/process/next_tick.js:68:7)
    at onFailure (/dev/shm/workspace/parallel/11/kibana/test/common/services/retry/retry_for_success.ts:28:9)
    at retryForSuccess (/dev/shm/workspace/parallel/11/kibana/test/common/services/retry/retry_for_success.ts:68:13)
    at onFailure (/dev/shm/workspace/parallel/11/kibana/test/common/services/retry/retry_for_success.ts:28:9)
    at retryForSuccess (/dev/shm/workspace/parallel/11/kibana/test/common/services/retry/retry_for_success.ts:68:13)

Chrome X-Pack UI Functional Tests.x-pack/test/functional/apps/dev_tools/feature_controls/dev_tools_spaces·ts.console feature controls spaces space with no features disabled shows 'Dev Tools' navlink

Link to Jenkins

Standard Out

[00:00:00]       │
[00:23:12]         └-: console
[00:23:12]           └-> "before all" hook
[00:23:12]           └-: feature controls
[00:23:12]             └-> "before all" hook
[00:25:27]             └-: spaces
[00:25:27]               └-> "before all" hook
[00:25:27]               └-> "before all" hook
[00:25:27]                 │ info [empty_kibana] Loading "mappings.json"
[00:25:27]                 │ info [o.e.c.m.MetadataDeleteIndexService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_2/kYAWoeC6Toy3wkxEWnZsoA] deleting index
[00:25:27]                 │ info [o.e.c.m.MetadataDeleteIndexService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_1/miWmElEnQv2mmLiY3nM8LA] deleting index
[00:25:27]                 │ info [empty_kibana] Deleted existing index [".kibana_2",".kibana_1"]
[00:25:27]                 │ info [o.e.c.m.MetadataCreateIndexService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana] creating index, cause [api], templates [], shards [1]/[1]
[00:25:27]                 │ info [empty_kibana] Created index ".kibana"
[00:25:27]                 │ debg [empty_kibana] ".kibana" settings {"index":{"number_of_replicas":"1","number_of_shards":"1"}}
[00:25:27]                 │ info [o.e.c.m.MetadataMappingService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana/OljImNyBT02-FZEQ2InrVA] update_mapping [_doc]
[00:25:27]                 │ debg Migrating saved objects
[00:25:27]                 │ proc [kibana]   log   [11:20:39.914] [info][savedobjects-service] Creating index .kibana_2.
[00:25:27]                 │ info [o.e.c.m.MetadataCreateIndexService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_2] creating index, cause [api], templates [], shards [1]/[1]
[00:25:27]                 │ info [o.e.c.r.a.AllocationService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] updating number_of_replicas to [0] for indices [.kibana_2]
[00:25:27]                 │ proc [kibana]   log   [11:20:40.020] [info][savedobjects-service] Reindexing .kibana to .kibana_1
[00:25:27]                 │ info [o.e.c.m.MetadataCreateIndexService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_1] creating index, cause [api], templates [], shards [1]/[1]
[00:25:27]                 │ info [o.e.c.r.a.AllocationService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] updating number_of_replicas to [0] for indices [.kibana_1]
[00:25:27]                 │ info [o.e.t.LoggingTaskListener] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] 15717 finished with response BulkByScrollResponse[took=1.6ms,timed_out=false,sliceId=null,updated=0,created=0,deleted=0,batches=0,versionConflicts=0,noops=0,retries=0,throttledUntil=0s,bulk_failures=[],search_failures=[]]
[00:25:27]                 │ info [o.e.c.m.MetadataDeleteIndexService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana/OljImNyBT02-FZEQ2InrVA] deleting index
[00:25:27]                 │ proc [kibana]   log   [11:20:40.419] [info][savedobjects-service] Migrating .kibana_1 saved objects to .kibana_2
[00:25:27]                 │ proc [kibana]   log   [11:20:40.423] [info][savedobjects-service] Pointing alias .kibana to .kibana_2.
[00:25:27]                 │ proc [kibana]   log   [11:20:40.459] [info][savedobjects-service] Finished in 547ms.
[00:25:28]                 │ debg applying update to kibana config: {"accessibility:disableAnimations":true,"dateFormat:tz":"UTC"}
[00:25:28]                 │ info [o.e.c.m.MetadataMappingService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_2/3KmdvR38SX6yFCEeocP1Cw] update_mapping [_doc]
[00:25:28]                 │ info [o.e.c.m.MetadataMappingService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_2/3KmdvR38SX6yFCEeocP1Cw] update_mapping [_doc]
[00:25:29]               └-: space with no features disabled
[00:25:29]                 └-> "before all" hook
[00:25:29]                 └-> "before all" hook
[00:25:29]                   │ debg creating space
[00:25:30]                   │ debg created space
[00:25:30]                 └-> shows 'Dev Tools' navlink
[00:25:30]                   └-> "before each" hook: global before each
[00:25:30]                   │ debg navigating to home url: http://localhost:61141/s/custom_space/app/home#/
[00:25:30]                   │ debg navigate to: http://localhost:61141/s/custom_space/app/home#/
[00:25:30]                   │ proc [kibana]   log   [11:20:43.103] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:25:30]                   │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:25:30]                   │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:25:30]                   │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:25:30]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:25:30]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:25:30]                   │ proc [kibana]   generatedMessage: false,
[00:25:30]                   │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:25:30]                   │ proc [kibana]   code: 'ERR_ASSERTION',
[00:25:30]                   │ proc [kibana]   actual: false,
[00:25:30]                   │ proc [kibana]   expected: true,
[00:25:30]                   │ proc [kibana]   operator: '==' }
[00:25:30]                   │ proc [kibana]  error  [11:20:43.101]  Error: Internal Server Error
[00:25:30]                   │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:25:30]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:25:30]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:25:30]                   │ debg ... sleep(700) start
[00:25:30]                   │ERROR browser[SEVERE] http://localhost:61141/s/custom_space/app/home?_t=1594207243097#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:25:31]                   │ debg ... sleep(700) end
[00:25:31]                   │ debg returned from get, calling refresh
[00:25:31]                   │ proc [kibana]   log   [11:20:43.862] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:25:31]                   │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:25:31]                   │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:25:31]                   │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:25:31]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:25:31]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:25:31]                   │ proc [kibana]   generatedMessage: false,
[00:25:31]                   │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:25:31]                   │ proc [kibana]   code: 'ERR_ASSERTION',
[00:25:31]                   │ proc [kibana]   actual: false,
[00:25:31]                   │ proc [kibana]   expected: true,
[00:25:31]                   │ proc [kibana]   operator: '==' }
[00:25:31]                   │ proc [kibana]  error  [11:20:43.861]  Error: Internal Server Error
[00:25:31]                   │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:25:31]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:25:31]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:25:31]                   │ERROR browser[SEVERE] http://localhost:61141/s/custom_space/app/home?_t=1594207243097#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:25:31]                   │ debg currentUrl = http://localhost:61141/s/custom_space/app/home#/
[00:25:31]                   │          appUrl = http://localhost:61141/s/custom_space/app/home#/
[00:25:31]                   │ debg TestSubjects.find(kibanaChrome)
[00:25:31]                   │ debg Find.findByCssSelector('[data-test-subj="kibanaChrome"]') with timeout=60000
[00:26:32]                   │ debg --- retry.try error: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:26:32]                   │      Wait timed out after 61075ms
[00:26:33]                   │ debg navigate to: http://localhost:61141/s/custom_space/app/home#/
[00:26:33]                   │ proc [kibana]   log   [11:21:45.500] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:26:33]                   │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:26:33]                   │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:26:33]                   │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:26:33]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:26:33]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:26:33]                   │ proc [kibana]   generatedMessage: false,
[00:26:33]                   │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:26:33]                   │ proc [kibana]   code: 'ERR_ASSERTION',
[00:26:33]                   │ proc [kibana]   actual: false,
[00:26:33]                   │ proc [kibana]   expected: true,
[00:26:33]                   │ proc [kibana]   operator: '==' }
[00:26:33]                   │ proc [kibana]  error  [11:21:45.499]  Error: Internal Server Error
[00:26:33]                   │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:26:33]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:26:33]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:26:33]                   │ERROR browser[SEVERE] http://localhost:61141/s/custom_space/app/home?_t=1594207305494#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:26:33]                   │ debg ... sleep(700) start
[00:26:33]                   │ debg ... sleep(700) end
[00:26:33]                   │ debg returned from get, calling refresh
[00:26:33]                   │ proc [kibana]   log   [11:21:46.254] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:26:33]                   │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:26:33]                   │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:26:33]                   │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:26:33]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:26:33]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:26:33]                   │ proc [kibana]   generatedMessage: false,
[00:26:33]                   │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:26:33]                   │ proc [kibana]   code: 'ERR_ASSERTION',
[00:26:33]                   │ proc [kibana]   actual: false,
[00:26:33]                   │ proc [kibana]   expected: true,
[00:26:33]                   │ proc [kibana]   operator: '==' }
[00:26:33]                   │ proc [kibana]  error  [11:21:46.253]  Error: Internal Server Error
[00:26:33]                   │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:26:33]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:26:33]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:26:33]                   │ERROR browser[SEVERE] http://localhost:61141/s/custom_space/app/home?_t=1594207305494#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:26:33]                   │ debg currentUrl = http://localhost:61141/s/custom_space/app/home#/
[00:26:33]                   │          appUrl = http://localhost:61141/s/custom_space/app/home#/
[00:26:33]                   │ debg TestSubjects.find(kibanaChrome)
[00:26:33]                   │ debg Find.findByCssSelector('[data-test-subj="kibanaChrome"]') with timeout=60000
[00:27:35]                   │ debg --- retry.try error: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:27:35]                   │      Wait timed out after 61191ms
[00:27:35]                   │ debg --- retry.tryForTime error: retry.try timeout: TimeoutError: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:27:35]                   │      Wait timed out after 61191ms
[00:27:35]                   │          at /dev/shm/workspace/kibana/node_modules/selenium-webdriver/lib/webdriver.js:842:17
[00:27:35]                   │          at process._tickCallback (internal/process/next_tick.js:68:7)
[00:27:36]                   │ debg navigate to: http://localhost:61141/s/custom_space/app/home#/
[00:27:36]                   │ proc [kibana]   log   [11:22:48.517] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:27:36]                   │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:27:36]                   │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:27:36]                   │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:27:36]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:27:36]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:27:36]                   │ proc [kibana]   generatedMessage: false,
[00:27:36]                   │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:27:36]                   │ proc [kibana]   code: 'ERR_ASSERTION',
[00:27:36]                   │ proc [kibana]   actual: false,
[00:27:36]                   │ proc [kibana]   expected: true,
[00:27:36]                   │ proc [kibana]   operator: '==' }
[00:27:36]                   │ proc [kibana]  error  [11:22:48.516]  Error: Internal Server Error
[00:27:36]                   │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:27:36]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:27:36]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:27:36]                   │ERROR browser[SEVERE] http://localhost:61141/s/custom_space/app/home?_t=1594207368512#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:27:36]                   │ debg ... sleep(700) start
[00:27:36]                   │ debg ... sleep(700) end
[00:27:36]                   │ debg returned from get, calling refresh
[00:27:36]                   │ proc [kibana]   log   [11:22:49.275] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:27:36]                   │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:27:36]                   │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:27:36]                   │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:27:36]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:27:36]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:27:36]                   │ proc [kibana]   generatedMessage: false,
[00:27:36]                   │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:27:36]                   │ proc [kibana]   code: 'ERR_ASSERTION',
[00:27:36]                   │ proc [kibana]   actual: false,
[00:27:36]                   │ proc [kibana]   expected: true,
[00:27:36]                   │ proc [kibana]   operator: '==' }
[00:27:36]                   │ proc [kibana]  error  [11:22:49.274]  Error: Internal Server Error
[00:27:36]                   │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:27:36]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:27:36]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:27:36]                   │ERROR browser[SEVERE] http://localhost:61141/s/custom_space/app/home?_t=1594207368512#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:27:36]                   │ debg currentUrl = http://localhost:61141/s/custom_space/app/home#/
[00:27:36]                   │          appUrl = http://localhost:61141/s/custom_space/app/home#/
[00:27:36]                   │ debg TestSubjects.find(kibanaChrome)
[00:27:36]                   │ debg Find.findByCssSelector('[data-test-subj="kibanaChrome"]') with timeout=60000
[00:28:38]                   │ debg --- retry.try error: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:28:38]                   │      Wait timed out after 61228ms
[00:28:38]                   │ debg navigate to: http://localhost:61141/s/custom_space/app/home#/
[00:28:38]                   │ proc [kibana]   log   [11:23:51.072] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:28:38]                   │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:28:38]                   │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:28:38]                   │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:28:38]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:28:38]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:28:38]                   │ proc [kibana]   generatedMessage: false,
[00:28:38]                   │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:28:38]                   │ proc [kibana]   code: 'ERR_ASSERTION',
[00:28:38]                   │ proc [kibana]   actual: false,
[00:28:38]                   │ proc [kibana]   expected: true,
[00:28:38]                   │ proc [kibana]   operator: '==' }
[00:28:38]                   │ proc [kibana]  error  [11:23:51.071]  Error: Internal Server Error
[00:28:38]                   │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:28:38]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:28:38]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:28:38]                   │ERROR browser[SEVERE] http://localhost:61141/s/custom_space/app/home?_t=1594207431067#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:28:38]                   │ debg ... sleep(700) start
[00:28:39]                   │ debg ... sleep(700) end
[00:28:39]                   │ debg returned from get, calling refresh
[00:28:39]                   │ proc [kibana]   log   [11:23:51.828] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:28:39]                   │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:28:39]                   │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:28:39]                   │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:28:39]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:28:39]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:28:39]                   │ proc [kibana]   generatedMessage: false,
[00:28:39]                   │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:28:39]                   │ proc [kibana]   code: 'ERR_ASSERTION',
[00:28:39]                   │ proc [kibana]   actual: false,
[00:28:39]                   │ proc [kibana]   expected: true,
[00:28:39]                   │ proc [kibana]   operator: '==' }
[00:28:39]                   │ proc [kibana]  error  [11:23:51.828]  Error: Internal Server Error
[00:28:39]                   │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:28:39]                   │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/14/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:28:39]                   │ proc [kibana]     at process._tickCallback (internal/process/next_tick.js:68:7)
[00:28:39]                   │ERROR browser[SEVERE] http://localhost:61141/s/custom_space/app/home?_t=1594207431067#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:28:39]                   │ debg currentUrl = http://localhost:61141/s/custom_space/app/home#/
[00:28:39]                   │          appUrl = http://localhost:61141/s/custom_space/app/home#/
[00:28:39]                   │ debg TestSubjects.find(kibanaChrome)
[00:28:39]                   │ debg Find.findByCssSelector('[data-test-subj="kibanaChrome"]') with timeout=60000
[00:29:40]                   │ debg --- retry.try error: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:29:40]                   │      Wait timed out after 61194ms
[00:29:41]                   │ debg --- retry.tryForTime error: retry.try timeout: TimeoutError: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:29:41]                   │      Wait timed out after 61194ms
[00:29:41]                   │          at /dev/shm/workspace/kibana/node_modules/selenium-webdriver/lib/webdriver.js:842:17
[00:29:41]                   │          at process._tickCallback (internal/process/next_tick.js:68:7)
[00:29:41]                   │ info Taking screenshot "/dev/shm/workspace/parallel/14/kibana/x-pack/test/functional/screenshots/failure/console feature controls spaces space with no features disabled shows _Dev Tools_ navlink.png"
[00:29:41]                   │ info Current URL is: http://localhost:61141/s/custom_space/app/home#/
[00:29:41]                   │ info Saving page source to: /dev/shm/workspace/parallel/14/kibana/x-pack/test/functional/failure_debug/html/console feature controls spaces space with no features disabled shows _Dev Tools_ navlink.html
[00:29:41]                   └- ✖ fail: "console feature controls spaces space with no features disabled shows 'Dev Tools' navlink"
[00:29:41]                   │

Stack Trace

Error: retry.tryForTime timeout: Error: retry.try timeout: TimeoutError: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
Wait timed out after 61194ms
    at /dev/shm/workspace/kibana/node_modules/selenium-webdriver/lib/webdriver.js:842:17
    at process._tickCallback (internal/process/next_tick.js:68:7)
    at onFailure (/dev/shm/workspace/parallel/14/kibana/test/common/services/retry/retry_for_success.ts:28:9)
    at retryForSuccess (/dev/shm/workspace/parallel/14/kibana/test/common/services/retry/retry_for_success.ts:68:13)
    at onFailure (/dev/shm/workspace/parallel/14/kibana/test/common/services/retry/retry_for_success.ts:28:9)
    at retryForSuccess (/dev/shm/workspace/parallel/14/kibana/test/common/services/retry/retry_for_success.ts:68:13)

Chrome X-Pack UI Functional Tests.x-pack/test/functional/apps/canvas/feature_controls/canvas_spaces·ts.Canvas app spaces feature controls space with no features disabled shows canvas navlink

Link to Jenkins

Standard Out

[00:00:00]       │
[00:01:39]         └-: Canvas app
[00:01:39]           └-> "before all" hook
[00:03:50]           └-: spaces feature controls
[00:03:50]             └-> "before all" hook
[00:03:50]             └-> "before all" hook
[00:03:50]               │ info [logstash_functional] Loading "mappings.json"
[00:03:50]               │ info [logstash_functional] Loading "data.json.gz"
[00:03:50]               │ info [logstash_functional] Skipped restore for existing index "logstash-2015.09.22"
[00:03:50]               │ info [logstash_functional] Skipped restore for existing index "logstash-2015.09.20"
[00:03:50]               │ info [logstash_functional] Skipped restore for existing index "logstash-2015.09.21"
[00:03:51]             └-: space with no features disabled
[00:03:51]               └-> "before all" hook
[00:03:51]               └-> "before all" hook
[00:03:51]                 │ info [canvas/default] Loading "mappings.json"
[00:03:51]                 │ info [canvas/default] Loading "data.json.gz"
[00:03:51]                 │ info [o.e.c.m.MetadataDeleteIndexService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_2/q7zMvkOMQVyYqfyLm_T_BQ] deleting index
[00:03:51]                 │ info [o.e.c.m.MetadataDeleteIndexService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_1/jOhOjw_aR3amt8GjEN-m7A] deleting index
[00:03:51]                 │ info [canvas/default] Deleted existing index [".kibana_2",".kibana_1"]
[00:03:51]                 │ info [o.e.c.m.MetadataCreateIndexService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_1] creating index, cause [api], templates [], shards [1]/[1]
[00:03:51]                 │ info [canvas/default] Created index ".kibana_1"
[00:03:51]                 │ debg [canvas/default] ".kibana_1" settings {"index":{"number_of_replicas":"1","number_of_shards":"1"}}
[00:03:51]                 │ info [canvas/default] Indexed 3 docs into ".kibana_1"
[00:03:51]                 │ info [o.e.c.m.MetadataMappingService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_1/XbFLRJ0fTJ6cywrOFeErAg] update_mapping [_doc]
[00:03:51]                 │ debg Migrating saved objects
[00:03:51]                 │ proc [kibana]   log   [10:58:46.912] [info][savedobjects-service] Creating index .kibana_2.
[00:03:51]                 │ info [o.e.c.m.MetadataCreateIndexService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_2] creating index, cause [api], templates [], shards [1]/[1]
[00:03:51]                 │ info [o.e.c.r.a.AllocationService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] updating number_of_replicas to [0] for indices [.kibana_2]
[00:03:51]                 │ proc [kibana]   log   [10:58:47.000] [info][savedobjects-service] Migrating .kibana_1 saved objects to .kibana_2
[00:03:51]                 │ info [o.e.c.m.MetadataMappingService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_2/Vs1yZ8j3TcutuLkWQ-KVQA] update_mapping [_doc]
[00:03:51]                 │ info [o.e.c.m.MetadataMappingService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_2/Vs1yZ8j3TcutuLkWQ-KVQA] update_mapping [_doc]
[00:03:51]                 │ info [o.e.c.m.MetadataMappingService] [kibana-ci-immutable-centos-tests-xxl-1594203525224058384] [.kibana_2/Vs1yZ8j3TcutuLkWQ-KVQA] update_mapping [_doc]
[00:03:51]                 │ proc [kibana]   log   [10:58:47.147] [info][savedobjects-service] Pointing alias .kibana to .kibana_2.
[00:03:51]                 │ proc [kibana]   log   [10:58:47.216] [info][savedobjects-service] Finished in 305ms.
[00:03:51]                 │ debg creating space
[00:03:52]                 │ debg created space
[00:03:52]               └-> shows canvas navlink
[00:03:52]                 └-> "before each" hook: global before each
[00:03:52]                 │ debg navigating to home url: http://localhost:61161/s/custom_space/app/home#/
[00:03:52]                 │ debg navigate to: http://localhost:61161/s/custom_space/app/home#/
[00:03:52]                 │ proc [kibana]   log   [10:58:47.987] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:03:52]                 │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:03:52]                 │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:03:52]                 │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:03:52]                 │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:03:52]                 │ proc [kibana]   generatedMessage: false,
[00:03:52]                 │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:03:52]                 │ proc [kibana]   code: 'ERR_ASSERTION',
[00:03:52]                 │ proc [kibana]   actual: false,
[00:03:52]                 │ proc [kibana]   expected: true,
[00:03:52]                 │ proc [kibana]   operator: '==' }
[00:03:52]                 │ proc [kibana]  error  [10:58:47.984]  Error: Internal Server Error
[00:03:52]                 │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:03:52]                 │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:03:52]                 │ERROR browser[SEVERE] http://localhost:61161/s/custom_space/app/home?_t=1594205927980#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:03:52]                 │ debg ... sleep(700) start
[00:03:53]                 │ debg ... sleep(700) end
[00:03:53]                 │ debg returned from get, calling refresh
[00:03:53]                 │ proc [kibana]   log   [10:58:48.754] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:03:53]                 │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:03:53]                 │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:03:53]                 │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:03:53]                 │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:03:53]                 │ proc [kibana]   generatedMessage: false,
[00:03:53]                 │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:03:53]                 │ proc [kibana]   code: 'ERR_ASSERTION',
[00:03:53]                 │ proc [kibana]   actual: false,
[00:03:53]                 │ proc [kibana]   expected: true,
[00:03:53]                 │ proc [kibana]   operator: '==' }
[00:03:53]                 │ proc [kibana]  error  [10:58:48.753]  Error: Internal Server Error
[00:03:53]                 │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:03:53]                 │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:03:53]                 │ERROR browser[SEVERE] http://localhost:61161/s/custom_space/app/home?_t=1594205927980#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:03:53]                 │ debg currentUrl = http://localhost:61161/s/custom_space/app/home#/
[00:03:53]                 │          appUrl = http://localhost:61161/s/custom_space/app/home#/
[00:03:53]                 │ debg TestSubjects.find(kibanaChrome)
[00:03:53]                 │ debg Find.findByCssSelector('[data-test-subj="kibanaChrome"]') with timeout=60000
[00:04:54]                 │ debg --- retry.try error: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:04:54]                 │      Wait timed out after 61195ms
[00:04:55]                 │ debg navigate to: http://localhost:61161/s/custom_space/app/home#/
[00:04:55]                 │ proc [kibana]   log   [10:59:50.522] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:04:55]                 │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:04:55]                 │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:04:55]                 │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:04:55]                 │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:04:55]                 │ proc [kibana]   generatedMessage: false,
[00:04:55]                 │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:04:55]                 │ proc [kibana]   code: 'ERR_ASSERTION',
[00:04:55]                 │ proc [kibana]   actual: false,
[00:04:55]                 │ proc [kibana]   expected: true,
[00:04:55]                 │ proc [kibana]   operator: '==' }
[00:04:55]                 │ proc [kibana]  error  [10:59:50.521]  Error: Internal Server Error
[00:04:55]                 │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:04:55]                 │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:04:55]                 │ERROR browser[SEVERE] http://localhost:61161/s/custom_space/app/home?_t=1594205990517#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:04:55]                 │ debg ... sleep(700) start
[00:04:56]                 │ debg ... sleep(700) end
[00:04:56]                 │ debg returned from get, calling refresh
[00:04:56]                 │ proc [kibana]   log   [10:59:51.283] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:04:56]                 │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:04:56]                 │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:04:56]                 │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:04:56]                 │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:04:56]                 │ proc [kibana]   generatedMessage: false,
[00:04:56]                 │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:04:56]                 │ proc [kibana]   code: 'ERR_ASSERTION',
[00:04:56]                 │ proc [kibana]   actual: false,
[00:04:56]                 │ proc [kibana]   expected: true,
[00:04:56]                 │ proc [kibana]   operator: '==' }
[00:04:56]                 │ proc [kibana]  error  [10:59:51.282]  Error: Internal Server Error
[00:04:56]                 │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:04:56]                 │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:04:56]                 │ERROR browser[SEVERE] http://localhost:61161/s/custom_space/app/home?_t=1594205990517#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:04:56]                 │ debg currentUrl = http://localhost:61161/s/custom_space/app/home#/
[00:04:56]                 │          appUrl = http://localhost:61161/s/custom_space/app/home#/
[00:04:56]                 │ debg TestSubjects.find(kibanaChrome)
[00:04:56]                 │ debg Find.findByCssSelector('[data-test-subj="kibanaChrome"]') with timeout=60000
[00:05:57]                 │ debg --- retry.try error: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:05:57]                 │      Wait timed out after 61220ms
[00:05:57]                 │ debg --- retry.tryForTime error: retry.try timeout: TimeoutError: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:05:57]                 │      Wait timed out after 61220ms
[00:05:57]                 │          at /dev/shm/workspace/kibana/node_modules/selenium-webdriver/lib/webdriver.js:842:17
[00:05:57]                 │          at process._tickCallback (internal/process/next_tick.js:68:7)
[00:05:58]                 │ debg navigate to: http://localhost:61161/s/custom_space/app/home#/
[00:05:58]                 │ proc [kibana]   log   [11:00:53.576] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:05:58]                 │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:05:58]                 │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:05:58]                 │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:05:58]                 │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:05:58]                 │ proc [kibana]   generatedMessage: false,
[00:05:58]                 │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:05:58]                 │ proc [kibana]   code: 'ERR_ASSERTION',
[00:05:58]                 │ proc [kibana]   actual: false,
[00:05:58]                 │ proc [kibana]   expected: true,
[00:05:58]                 │ proc [kibana]   operator: '==' }
[00:05:58]                 │ proc [kibana]  error  [11:00:53.575]  Error: Internal Server Error
[00:05:58]                 │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:05:58]                 │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:05:58]                 │ERROR browser[SEVERE] http://localhost:61161/s/custom_space/app/home?_t=1594206053570#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:05:58]                 │ debg ... sleep(700) start
[00:05:59]                 │ debg ... sleep(700) end
[00:05:59]                 │ debg returned from get, calling refresh
[00:05:59]                 │ proc [kibana]   log   [11:00:54.335] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:05:59]                 │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:05:59]                 │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:05:59]                 │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:05:59]                 │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:05:59]                 │ proc [kibana]   generatedMessage: false,
[00:05:59]                 │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:05:59]                 │ proc [kibana]   code: 'ERR_ASSERTION',
[00:05:59]                 │ proc [kibana]   actual: false,
[00:05:59]                 │ proc [kibana]   expected: true,
[00:05:59]                 │ proc [kibana]   operator: '==' }
[00:05:59]                 │ proc [kibana]  error  [11:00:54.334]  Error: Internal Server Error
[00:05:59]                 │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:05:59]                 │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:05:59]                 │ERROR browser[SEVERE] http://localhost:61161/s/custom_space/app/home?_t=1594206053570#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:05:59]                 │ debg currentUrl = http://localhost:61161/s/custom_space/app/home#/
[00:05:59]                 │          appUrl = http://localhost:61161/s/custom_space/app/home#/
[00:05:59]                 │ debg TestSubjects.find(kibanaChrome)
[00:05:59]                 │ debg Find.findByCssSelector('[data-test-subj="kibanaChrome"]') with timeout=60000
[00:07:00]                 │ debg --- retry.try error: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:07:00]                 │      Wait timed out after 61201ms
[00:07:00]                 │ debg navigate to: http://localhost:61161/s/custom_space/app/home#/
[00:07:00]                 │ proc [kibana]   log   [11:01:56.105] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:07:00]                 │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:07:00]                 │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:07:00]                 │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:07:00]                 │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:07:00]                 │ proc [kibana]   generatedMessage: false,
[00:07:00]                 │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:07:00]                 │ proc [kibana]   code: 'ERR_ASSERTION',
[00:07:00]                 │ proc [kibana]   actual: false,
[00:07:00]                 │ proc [kibana]   expected: true,
[00:07:00]                 │ proc [kibana]   operator: '==' }
[00:07:00]                 │ proc [kibana]  error  [11:01:56.103]  Error: Internal Server Error
[00:07:00]                 │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:07:00]                 │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:07:00]                 │ERROR browser[SEVERE] http://localhost:61161/s/custom_space/app/home?_t=1594206116099#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:07:00]                 │ debg ... sleep(700) start
[00:07:01]                 │ debg ... sleep(700) end
[00:07:01]                 │ debg returned from get, calling refresh
[00:07:01]                 │ proc [kibana]   log   [11:01:56.864] [error][server][Kibana][http] { AssertionError [ERR_ASSERTION]: Cannot change request URL after routing
[00:07:01]                 │ proc [kibana]     at new AssertionError (internal/assert.js:269:11)
[00:07:01]                 │ proc [kibana]     at Object.exports.assert (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/node_modules/hoek/lib/index.js:736:11)
[00:07:01]                 │ proc [kibana]     at Request.setUrl (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/node_modules/hapi/lib/request.js:108:14)
[00:07:01]                 │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:97:17)
[00:07:01]                 │ proc [kibana]   generatedMessage: false,
[00:07:01]                 │ proc [kibana]   name: 'AssertionError [ERR_ASSERTION]',
[00:07:01]                 │ proc [kibana]   code: 'ERR_ASSERTION',
[00:07:01]                 │ proc [kibana]   actual: false,
[00:07:01]                 │ proc [kibana]   expected: true,
[00:07:01]                 │ proc [kibana]   operator: '==' }
[00:07:01]                 │ proc [kibana]  error  [11:01:56.859]  Error: Internal Server Error
[00:07:01]                 │ proc [kibana]     at HapiResponseAdapter.toInternalError (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/router/response_adapter.js:69:19)
[00:07:01]                 │ proc [kibana]     at interceptPreAuthRequest (/dev/shm/workspace/parallel/16/kibana/build/kibana-build-xpack/src/core/server/http/lifecycle/on_pre_auth.js:106:34)
[00:07:01]                 │ERROR browser[SEVERE] http://localhost:61161/s/custom_space/app/home?_t=1594206116099#/ - Failed to load resource: the server responded with a status of 500 (Internal Server Error)
[00:07:01]                 │ debg currentUrl = http://localhost:61161/s/custom_space/app/home#/
[00:07:01]                 │          appUrl = http://localhost:61161/s/custom_space/app/home#/
[00:07:01]                 │ debg TestSubjects.find(kibanaChrome)
[00:07:01]                 │ debg Find.findByCssSelector('[data-test-subj="kibanaChrome"]') with timeout=60000
[00:08:02]                 │ debg --- retry.try error: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:08:02]                 │      Wait timed out after 61160ms
[00:08:03]                 │ debg --- retry.tryForTime error: retry.try timeout: TimeoutError: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
[00:08:03]                 │      Wait timed out after 61160ms
[00:08:03]                 │          at /dev/shm/workspace/kibana/node_modules/selenium-webdriver/lib/webdriver.js:842:17
[00:08:03]                 │          at process._tickCallback (internal/process/next_tick.js:68:7)
[00:08:03]                 │ info Taking screenshot "/dev/shm/workspace/parallel/16/kibana/x-pack/test/functional/screenshots/failure/Canvas app spaces feature controls space with no features disabled shows canvas navlink.png"
[00:08:04]                 │ info Current URL is: http://localhost:61161/s/custom_space/app/home#/
[00:08:04]                 │ info Saving page source to: /dev/shm/workspace/parallel/16/kibana/x-pack/test/functional/failure_debug/html/Canvas app spaces feature controls space with no features disabled shows canvas navlink.html
[00:08:04]                 └- ✖ fail: "Canvas app spaces feature controls space with no features disabled shows canvas navlink"
[00:08:04]                 │

Stack Trace

Error: retry.tryForTime timeout: Error: retry.try timeout: TimeoutError: Waiting for element to be located By(css selector, [data-test-subj="kibanaChrome"])
Wait timed out after 61160ms
    at /dev/shm/workspace/kibana/node_modules/selenium-webdriver/lib/webdriver.js:842:17
    at process._tickCallback (internal/process/next_tick.js:68:7)
    at onFailure (/dev/shm/workspace/parallel/16/kibana/test/common/services/retry/retry_for_success.ts:28:9)
    at retryForSuccess (/dev/shm/workspace/parallel/16/kibana/test/common/services/retry/retry_for_success.ts:68:13)
    at onFailure (/dev/shm/workspace/parallel/16/kibana/test/common/services/retry/retry_for_success.ts:28:9)
    at retryForSuccess (/dev/shm/workspace/parallel/16/kibana/test/common/services/retry/retry_for_success.ts:68:13)

and 13 more failures, only showing the first 3.

Build metrics

‼️ unable to find a baseline build for [master@9499417]. Try merging the upstream branch and trying again.

History

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

@jfsiii
Copy link
Contributor

jfsiii commented Jul 8, 2020

@kobelb @roncohen just wanted to mention that I am working on this locally #67987 (comment)

I'll push any changes/numbers to my fork and we can decide what to do from there

@jfsiii
Copy link
Contributor

jfsiii commented Jul 9, 2020

I put a draft PR up at #71221 but it's having some issues. I'd love some additional 👀

@kobelb
Copy link
Contributor Author

kobelb commented Jul 9, 2020

@jfsiii I overlooked the fact that onPreResponse doesn't fire when a request is aborted. There's a request.events.aborted$ we should be using to catch this, but there's a bug with request.events.aborted$ where this is being fired even when requests complete successfully. I threw up a PR which takes advantage of the request.events.aborted$ bug, which should let us do load-testing to see if this approach is required before figuring out the final solution.

@kobelb
Copy link
Contributor Author

kobelb commented Jul 9, 2020

but there's a bug with request.events.aborted$ where this is being fired even when requests complete successfully

I was wrong about this... request.events.aborted$ is an Observable, and I was using .toPromise with it instead of subscribing to figure out when it was truly aborted...

// determine if request completed for any reason
request.events.aborted$.toPromise().then(() => console.log('completed'));

// determine if request was truly aborted
request.events.aborted$.subscribe(() => {
  console.log('aborted');
});

Whether or not we should be using the completion of the request.events.aborted$ Observable to determine when the request is complete, regardless of it being aborted or not, is I question I defer to @joshdover 😄

@joshdover
Copy link
Contributor

Whether or not we should be using the completion of the request.events.aborted$ Observable to determine when the request is complete, regardless of it being aborted or not, is I question I defer to @joshdover 😄

So we do have test coverage that explicitly verifies that the request.events.aborted$ Observable is completed whenever a response is sent, regardless of whether or not the request was aborted. But this does feel like a 'works by coincidence' scenario rather than a 'works by design' one. Adding a request.events.completed$ event would be fairly trivial. @restrry do you see any reason not to do it? I'm happy to throw up a quick PR.

@mshustov
Copy link
Contributor

Observable is completed whenever a response is sent, regardless of whether or not the request was aborted.

Works by the design of the Observables. @joshdover yes, you can add completed$/finished$ events easily, we already have this code in place

const finish$ = merge(
fromEvent(request.raw.req, 'end'), // all data consumed
fromEvent(request.raw.req, 'close') // connection was closed
).pipe(shareReplay(1), first());

@joshdover
Copy link
Contributor

Works by the design of the Observables.

I should have clarified. The aborted API is working by design, but using the completion as a signal that the request completed would be abusing the API. I agree we should add the completed event if it is necessary. @kobelb LMK if you would like a PR for that

@jfsiii jfsiii mentioned this pull request Jul 13, 2020
2 tasks
@roncohen
Copy link
Contributor

It looks like request.events.aborted$ no longer works (maybe it never did?) as we expected (#70495 (comment))

In my testing, it seem like maxCounter.decrease(); gets called before the handler is even called here:
https://github.com/elastic/kibana/blob/master/x-pack/plugins/ingest_manager/server/routes/limited_concurrency.ts#L71

Could you help me verify if this is true, and whether it has recently changed or was always the case?

@roncohen
Copy link
Contributor

i reread the discussion. Looks like it's wrong to use toPromise here. Sorry for the noise

@kobelb kobelb closed this Sep 22, 2020
@kobelb kobelb deleted the poc/fleet-concurrency branch September 22, 2020 13:42
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

7 participants