search

elastic / kibana

Your window into the Elastic Stack
https://www.elastic.co/products/kibana
Other
19.65k stars 8.22k forks source link

[Unit Testing][Flaky] Jest suite and react-testing-library registration race condition #59469

Closed Dosant closed 4 years ago

Dosant commented 4 years ago

While working on https://github.com/elastic/kibana/pull/59445 I discovered a race condition related to when react-testing-library (@testing-library/react) is first used in tests. Test suite could basically fail if a test which imports @testing-library/react runs before problematic tests.

This race condition is easy to proof if to properly import @testing-library/react into setupAfterEnv hook. Test suite (both OSS and x-pack) start to fail. Failure reasons are not completely deterministic.

By default when @testing-library/react is imported it registers it's afterEach clean up hook and if it registers too early - some occasional tests start to fail with different reasons (see below). The hook: https://github.com/testing-library/react-testing-library/blob/master/src/index.js#L11

Right now this is causing following problems:

  1. If there is a race condition, then this might be a reason for occasional CI failures?
  2. New tests with @testing-library/react will increase chance of race conditions. Adopting in more places will start causing unrelated tests failures on ci

Possible solutions:

  1. Disabled react testing libraries auto clean up. Some tests in x-pack start to fail it do to this. But it is easy to fix by doing local clean up
  2. Enable react testing libraries auto clean up and setup in the very beginning of test suite. Problematic tests have to be fixed. List of problematic tests I encountered is below, but it could be more, as it is not deterministic:

OSS:

Summary of all failing tests
 FAIL  src/legacy/core_plugins/kibana/public/management/sections/index_patterns/create_index_pattern_wizard/components/step_index_pattern/step_index_pattern.test.tsx
  ● StepIndexPattern › renders matching indices when input is valid

    TypeError: target.setSelectionRange is not a function

      159 |       query += '*';
      160 |       this.setState({ appendedWildcard: true });
    > 161 |       setTimeout(() => target.setSelectionRange(1, 1));
          |                               ^
      162 |     } else {
      163 |       if (query === '*' && appendedWildcard) {
      164 |         query = '';

      at setTimeout (src/legacy/core_plugins/kibana/public/management/sections/index_patterns/create_index_pattern_wizard/components/step_index_pattern/step_index_pattern.tsx:161:31)

  ● StepIndexPattern › appends a wildcard automatically to queries

    TypeError: target.setSelectionRange is not a function

      159 |       query += '*';
      160 |       this.setState({ appendedWildcard: true });
    > 161 |       setTimeout(() => target.setSelectionRange(1, 1));
          |                               ^
      162 |     } else {
      163 |       if (query === '*' && appendedWildcard) {
      164 |         query = '';

      at setTimeout (src/legacy/core_plugins/kibana/public/management/sections/index_patterns/create_index_pattern_wizard/components/step_index_pattern/step_index_pattern.tsx:161:31)

  ● StepIndexPattern › ensures the response of the latest request is persisted

    TypeError: target.setSelectionRange is not a function

      159 |       query += '*';
      160 |       this.setState({ appendedWildcard: true });
    > 161 |       setTimeout(() => target.setSelectionRange(1, 1));
          |                               ^
      162 |     } else {
      163 |       if (query === '*' && appendedWildcard) {
      164 |         query = '';

      at setTimeout (src/legacy/core_plugins/kibana/public/management/sections/index_patterns/create_index_pattern_wizard/components/step_index_pattern/step_index_pattern.tsx:161:31)

 FAIL  src/plugins/data/server/search/routes.test.ts
  ● Search service › handler calls context.search.search with the given request and strategy

    TypeError: Invalid event target

      29 | export function getRequestAbortedSignal(aborted$: Observable<void>): AbortSignal {
      30 |   const controller = new AbortController();
    > 31 |   aborted$.subscribe(() => controller.abort());
         |            ^
      32 |   return controller.signal;
      33 | }
      34 | 

      at setupSubscription (node_modules/rxjs/src/internal/observable/fromEvent.ts:229:11)
      at Observable._subscribe (node_modules/rxjs/src/internal/observable/fromEvent.ts:204:5)
      at Observable.Object.<anonymous>.Observable._trySubscribe (node_modules/rxjs/src/internal/Observable.ts:238:19)
      at Observable.Object.<anonymous>.Observable.subscribe (node_modules/rxjs/src/internal/Observable.ts:219:14)
      at Object.subscribeToResult (node_modules/rxjs/src/internal/util/subscribeToResult.ts:26:19)
      at MergeMapSubscriber.Object.<anonymous>.MergeMapSubscriber._innerSub (node_modules/rxjs/src/internal/operators/mergeMap.ts:148:5)
      at MergeMapSubscriber.Object.<anonymous>.MergeMapSubscriber._tryNext (node_modules/rxjs/src/internal/operators/mergeMap.ts:141:10)
      at MergeMapSubscriber.Object.<anonymous>.MergeMapSubscriber._next (node_modules/rxjs/src/internal/operators/mergeMap.ts:125:12)
      at MergeMapSubscriber.Object.<anonymous>.Subscriber.next (node_modules/rxjs/src/internal/Subscriber.ts:99:12)
      at Observable._subscribe (node_modules/rxjs/src/internal/util/subscribeToArray.ts:9:16)
      at Observable.Object.<anonymous>.Observable._trySubscribe (node_modules/rxjs/src/internal/Observable.ts:238:19)
      at Observable.Object.<anonymous>.Observable.subscribe (node_modules/rxjs/src/internal/Observable.ts:219:14)
      at MergeMapOperator.Object.<anonymous>.MergeMapOperator.call (node_modules/rxjs/src/internal/operators/mergeMap.ts:100:19)
      at Observable.Object.<anonymous>.Observable.subscribe (node_modules/rxjs/src/internal/Observable.ts:214:25)
      at TakeSubscriber.shareReplayOperation (node_modules/rxjs/src/internal/operators/shareReplay.ts:97:29)
      at Observable.Object.<anonymous>.Observable.subscribe (node_modules/rxjs/src/internal/Observable.ts:214:25)
      at TakeOperator.Object.<anonymous>.TakeOperator.call (node_modules/rxjs/src/internal/operators/take.ts:72:19)
      at Observable.Object.<anonymous>.Observable.subscribe (node_modules/rxjs/src/internal/Observable.ts:214:25)
      at ThrowIfEmptyOperator.Object.<anonymous>.ThrowIfEmptyOperator.call (node_modules/rxjs/src/internal/operators/throwIfEmpty.ts:48:19)
      at Observable.Object.<anonymous>.Observable.subscribe (node_modules/rxjs/src/internal/Observable.ts:214:25)
      at Object.subscribeToResult (node_modules/rxjs/src/internal/util/subscribeToResult.ts:26:19)
      at TakeUntilOperator.Object.<anonymous>.TakeUntilOperator.call (node_modules/rxjs/src/internal/operators/takeUntil.ts:61:34)
      at Observable.subscribe (node_modules/rxjs/src/internal/Observable.ts:214:25)
      at getRequestAbortedSignal (src/plugins/data/server/lib/get_request_aborted_signal.ts:31:12)
      at handler (src/plugins/data/server/search/routes.ts:39:22)
      at Object.it (src/plugins/data/server/search/routes.test.ts:59:11)

  ● Search service › handler throws an error if the search throws an error

    TypeError: Invalid event target

      29 | export function getRequestAbortedSignal(aborted$: Observable<void>): AbortSignal {
      30 |   const controller = new AbortController();
    > 31 |   aborted$.subscribe(() => controller.abort());
         |            ^
      32 |   return controller.signal;
      33 | }
      34 | 

      at setupSubscription (node_modules/rxjs/src/internal/observable/fromEvent.ts:229:11)
      at Observable._subscribe (node_modules/rxjs/src/internal/observable/fromEvent.ts:204:5)
      at Observable.Object.<anonymous>.Observable._trySubscribe (node_modules/rxjs/src/internal/Observable.ts:238:19)
      at Observable.Object.<anonymous>.Observable.subscribe (node_modules/rxjs/src/internal/Observable.ts:219:14)
      at Object.subscribeToResult (node_modules/rxjs/src/internal/util/subscribeToResult.ts:26:19)
      at MergeMapSubscriber.Object.<anonymous>.MergeMapSubscriber._innerSub (node_modules/rxjs/src/internal/operators/mergeMap.ts:148:5)
      at MergeMapSubscriber.Object.<anonymous>.MergeMapSubscriber._tryNext (node_modules/rxjs/src/internal/operators/mergeMap.ts:141:10)
      at MergeMapSubscriber.Object.<anonymous>.MergeMapSubscriber._next (node_modules/rxjs/src/internal/operators/mergeMap.ts:125:12)
      at MergeMapSubscriber.Object.<anonymous>.Subscriber.next (node_modules/rxjs/src/internal/Subscriber.ts:99:12)
      at Observable._subscribe (node_modules/rxjs/src/internal/util/subscribeToArray.ts:9:16)
      at Observable.Object.<anonymous>.Observable._trySubscribe (node_modules/rxjs/src/internal/Observable.ts:238:19)
      at Observable.Object.<anonymous>.Observable.subscribe (node_modules/rxjs/src/internal/Observable.ts:219:14)
      at MergeMapOperator.Object.<anonymous>.MergeMapOperator.call (node_modules/rxjs/src/internal/operators/mergeMap.ts:100:19)
      at Observable.Object.<anonymous>.Observable.subscribe (node_modules/rxjs/src/internal/Observable.ts:214:25)
      at TakeSubscriber.shareReplayOperation (node_modules/rxjs/src/internal/operators/shareReplay.ts:97:29)
      at Observable.Object.<anonymous>.Observable.subscribe (node_modules/rxjs/src/internal/Observable.ts:214:25)
      at TakeOperator.Object.<anonymous>.TakeOperator.call (node_modules/rxjs/src/internal/operators/take.ts:72:19)
      at Observable.Object.<anonymous>.Observable.subscribe (node_modules/rxjs/src/internal/Observable.ts:214:25)
      at ThrowIfEmptyOperator.Object.<anonymous>.ThrowIfEmptyOperator.call (node_modules/rxjs/src/internal/operators/throwIfEmpty.ts:48:19)
      at Observable.Object.<anonymous>.Observable.subscribe (node_modules/rxjs/src/internal/Observable.ts:214:25)
      at Object.subscribeToResult (node_modules/rxjs/src/internal/util/subscribeToResult.ts:26:19)
      at TakeUntilOperator.Object.<anonymous>.TakeUntilOperator.call (node_modules/rxjs/src/internal/operators/takeUntil.ts:61:34)
      at Observable.subscribe (node_modules/rxjs/src/internal/Observable.ts:214:25)
      at getRequestAbortedSignal (src/plugins/data/server/lib/get_request_aborted_signal.ts:31:12)
      at handler (src/plugins/data/server/search/routes.ts:39:22)
      at Object.it (src/plugins/data/server/search/routes.test.ts:96:11)

 FAIL  src/plugins/kibana_utils/common/of.test.ts
  ● of() › when promise resolves › first member of 3-tuple is the promise value

    thrown: 123

      24 |     const promise = new Promise(resolve => resolve()).then(() => 123);
      25 | 
    > 26 |     test('first member of 3-tuple is the promise value', async () => {
         |     ^
      27 |       const [result] = await of(promise);
      28 |       expect(result).toBe(123);
      29 |     });

      at new Spec (node_modules/jest-jasmine2/build/jasmine/Spec.js:116:22)
      at Suite.describe (src/plugins/kibana_utils/common/of.test.ts:26:5)
      at Suite.Object.<anonymous>.describe (src/plugins/kibana_utils/common/of.test.ts:23:3)
      at Object.<anonymous> (src/plugins/kibana_utils/common/of.test.ts:22:1)

x-pack: https://kibana-ci.elastic.co/job/elastic+kibana+pipeline-pull-request/31344/consoleText

[2020-03-06T08:39:02.073Z]      │ proc [kibana]   log   [08:39:01.972] [warning][plugins][taskManager][taskManager] The task vis_telemetry "oss_telemetry-vis_telemetry" is not cancellable.
[2020-03-06T08:39:02.073Z]      │ proc [kibana]   log   [08:39:01.973] [warning][plugins][taskManager][taskManager] The task lens_telemetry "Lens-lens_telemetry" is not cancellable.
[2020-03-06T08:39:02.073Z]      │ info [kibana] exited with null after a minute
[2020-03-06T08:39:02.158Z]                └- ✓ pass  (357ms) "machine learning anomaly detection categorization job creation displays the summary step"
[2020-03-06T08:39:02.158Z]              └-> job creation creates the job and finishes processing
[2020-03-06T08:39:02.158Z]                └-> "before each" hook: global before each
[2020-03-06T08:39:02.302Z]     Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.Error: Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.
[2020-03-06T08:39:02.302Z] 
[2020-03-06T08:39:02.302Z]       at mapper (../node_modules/jest-jasmine2/build/queueRunner.js:25:45)
[2020-03-06T08:39:02.302Z] 
[2020-03-06T08:39:02.302Z]  FAIL  legacy/plugins/cross_cluster_replication/__jest__/client_integration/auto_follow_pattern_list.test.js (123.324s)
[2020-03-06T08:39:02.307Z]                │ proc [kibana]   log   [08:39:02.017] [info][savedobjects-service] Creating index .kibana_2.
[2020-03-06T08:39:02.307Z]                │ proc [kibana]   log   [08:39:02.084] [info][savedobjects-service] Reindexing .kibana to .kibana_1
[2020-03-06T08:39:02.329Z]      │ info [o.e.x.m.p.NativeController] [kibana-ci-immutable-oraclelinux-tests-xl-1583479512898115244] Native controller process has stopped - no new native processes can be started
[2020-03-06T08:39:02.329Z]      │ info [o.e.n.Node] [kibana-ci-immutable-oraclelinux-tests-xl-1583479512898115244] stopping ...
[2020-03-06T08:39:02.329Z]      │ info [o.e.x.w.WatcherService] [kibana-ci-immutable-oraclelinux-tests-xl-1583479512898115244] stopping watch service, reason [shutdown initiated]
[2020-03-06T08:39:02.329Z]      │ info [o.e.x.w.WatcherLifeCycleService] [kibana-ci-immutable-oraclelinux-tests-xl-1583479512898115244] watcher has stopped and shutdown
[2020-03-06T08:39:02.559Z]   ● <AutoFollowPatternList /> › when there are auto-follow patterns › detail panel › should have a default value when there are no prefix or no suffix
[2020-03-06T08:39:02.559Z] 
[2020-03-06T08:39:02.559Z]     Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.Error: Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.
[2020-03-06T08:39:02.559Z] 
[2020-03-06T08:39:02.559Z]       at mapper (../node_modules/jest-jasmine2/build/queueRunner.js:25:45)
[2020-03-06T08:39:02.559Z] 
[2020-03-06T08:39:02.559Z]   ● <AutoFollowPatternList /> › when there are auto-follow patterns › detail panel › should display the recent errors
[2020-03-06T08:39:02.559Z] 
[2020-03-06T08:39:02.563Z]                │ proc [kibana]   log   [08:39:02.444] [info][savedobjects-service] Migrating .kibana_1 saved objects to .kibana_2
[2020-03-06T08:39:02.585Z]      │ info [o.e.n.Node] [kibana-ci-immutable-oraclelinux-tests-xl-1583479512898115244] stopped
[2020-03-06T08:39:02.585Z]      │ info [o.e.n.Node] [kibana-ci-immutable-oraclelinux-tests-xl-1583479512898115244] closing ...
[2020-03-06T08:39:02.586Z]      │ info [o.e.n.Node] [kibana-ci-immutable-oraclelinux-tests-xl-1583479512898115244] closed
[2020-03-06T08:39:02.586Z]      │ info [es] stopped
[2020-03-06T08:39:02.586Z]      │ info [es] cleanup complete
[2020-03-06T08:39:02.586Z]  info Running /dev/shm/workspace/kibana/x-pack/test/token_api_integration/config.js
[2020-03-06T08:39:02.586Z]  │ debg Loading config file from "/dev/shm/workspace/kibana/x-pack/test/token_api_integration/config.js"
[2020-03-06T08:39:02.817Z]     Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.Error: Timeout - Async callback was not invoked within the 5000ms timeout specified by jest.setTimeout.
[2020-03-06T08:39:02.817Z] 
[2020-03-06T08:39:02.817Z]       at mapper (../node_modules/jest-jasmine2/build/queueRunner.js:25:45)
[2020-03-06T08:39:02.817Z] 
[2020-03-06T08:39:02.817Z]  FAIL  legacy/plugins/index_lifecycle_management/__jest__/extend_index_management.test.js
[2020-03-06T08:39:02.817Z]   ● extend index management › ilm banner extension › should return null no index has lifecycle error
[2020-03-06T08:39:02.817Z] 
[2020-03-06T08:39:02.819Z]                │ proc [kibana]   log   [08:39:02.636] [info][savedobjects-service] Pointing alias .kibana to .kibana_2.
[2020-03-06T08:39:02.820Z]                │ proc [kibana]   log   [08:39:02.672] [info][savedobjects-service] Finished in 657ms.
[2020-03-06T08:39:02.820Z]              └-> should return 200
[2020-03-06T08:39:02.820Z]                └-> "before each" hook: global before each
[2020-03-06T08:39:02.841Z]  │ info Config loaded
[2020-03-06T08:39:02.841Z]  │ info Only running suites (and their sub-suites) if they include the tag(s): [ 'ciGroup6' ]
[2020-03-06T08:39:02.841Z]  │ info Installing from snapshot
[2020-03-06T08:39:02.841Z]      │ info version: 8.0.0
[2020-03-06T08:39:02.841Z]      │ info install path: /dev/shm/workspace/kibana/.es/job-xpack-kibana-ciGroup6-worker-6-es-test-cluster
[2020-03-06T08:39:02.841Z]      │ info license: trial
[2020-03-06T08:39:02.841Z]      │ info Downloading snapshot manifest from https://storage.googleapis.com/kibana-ci-es-snapshots-daily/8.0.0/manifest-latest-verified.json
[2020-03-06T08:39:02.841Z]      │ info verifying cache of https://storage.googleapis.com/kibana-ci-es-snapshots-daily/8.0.0/archives/20200226-193908_cfecb541aa1/elasticsearch-8.0.0-SNAPSHOT-linux-x86_64.tar.gz
[2020-03-06T08:39:02.841Z]      │ info etags match, reusing cache from 2020-03-06T07:33:25.503Z
[2020-03-06T08:39:02.841Z]      │ info extracting /dev/shm/workspace/kibana/.es/cache/elasticsearch-8.0.0-SNAPSHOT-linux-x86_64.tar.gz
[2020-03-06T08:39:03.074Z]     TypeError: Cannot read property 'add' of undefined
[2020-03-06T08:39:03.074Z] 
[2020-03-06T08:39:03.074Z]       39 |   // This error isn't an HTTP error, so let the fatal error screen tell the user something
[2020-03-06T08:39:03.074Z]       40 |   // unexpected happened.
[2020-03-06T08:39:03.074Z]     > 41 |   fatalErrors.add(error, errorTitle);
[2020-03-06T08:39:03.074Z]          |               ^
[2020-03-06T08:39:03.074Z]       42 | }
[2020-03-06T08:39:03.330Z]       43 | 
[2020-03-06T08:39:03.330Z] 
[2020-03-06T08:39:03.330Z]       at showApiError (legacy/plugins/index_lifecycle_management/public/np_ready/application/services/api_errors.js:41:15)
[2020-03-06T08:39:03.331Z]       at AddLifecyclePolicyConfirmModal.componentDidMount (legacy/plugins/index_lifecycle_management/public/np_ready/extend_index_management/components/add_lifecycle_confirm_modal.js:205:7)
elasticmachine commented 4 years ago

Pinging @elastic/kibana-app-arch (Team:AppArch)

elasticmachine commented 4 years ago

Pinging @elastic/kibana-operations (Team:Operations)