Skip to content

Commit

Permalink
[ftr] Improve FTR error handling for NoSuchSessionError (elastic#161025)
Browse files Browse the repository at this point in the history 
## Summary

Sometimes browser/driver process dies during test run on CI and FTR
fails with errors cascade, good example is
[here](https://buildkite.com/elastic/kibana-pull-request/builds/138535#0188fd74-9adf-4011-8168-1bdc6e3d0f17)

Current behaviour on `main`: FTR lifecycle hooks, defined in
[remote](https://github.com/elastic/kibana/blob/57aea91fae4f2d0a047ff9e2339eb61352f1d73d/test/functional/services/remote/remote.ts)
service, has no access to the information about test suite run and
particular test failure. These hooks are related to WebDriver (browser)
state management and suppose to reset it to default state.
Currently we silently fail screenshot taking which means tests execution
is continued even if `--bail` flag is passed. It ends with cascade of
failures with the same error `NoSuchSessionError: invalid session id`

<details>

<summary>FTR output on failure</summary>

```
         └- ✖ fail: discover/group1 discover test query should show correct time range string by timepicker
         │      Error: expected 'Sep 19, 2015 @ 06:31:44.000' to equal 'Sep 23, 2015 @ 18:31:44.000'
         │       at Assertion.assert (expect.js:100:11)
         │       at Assertion.apply (expect.js:227:8)
         │       at Assertion.be (expect.js:69:22)
         │       at Context.<anonymous> (_discover.ts:53:31)
         │       at processTicksAndRejections (node:internal/process/task_queues:96:5)
         │       at Object.apply (wrap_function.js:73:16)
         │
         │
       └-> "after all" hook: afterTestSuite.trigger for "should reload the saved search with persisted query to show the initial hit count"
         └- ✖ fail: discover/group1 discover test query "after all" hook: afterTestSuite.trigger for "should reload the saved search with persisted query to show the initial hit count"
         │      NoSuchSessionError: invalid session id
         │       at Object.throwDecodedError (node_modules/selenium-webdriver/lib/error.js:524:15)
         │       at parseHttpResponse (node_modules/selenium-webdriver/lib/http.js:601:13)
         │       at Executor.execute (node_modules/selenium-webdriver/lib/http.js:529:28)
         │       at processTicksAndRejections (node:internal/process/task_queues:96:5)
         │       at Task.exec (prevent_parallel_calls.ts:28:20)
         │
         │
       └-> "after all" hook in "discover test"
         │ debg Cleaning all saved objects { space: undefined }
         │ succ deleted 2 objects
       └-> "after all" hook: afterTestSuite.trigger in "discover test"
         └- ✖ fail: discover/group1 discover test "after all" hook: afterTestSuite.trigger in "discover test"
         │      NoSuchSessionError: invalid session id
         │       at Object.throwDecodedError (node_modules/selenium-webdriver/lib/error.js:524:15)
         │       at parseHttpResponse (node_modules/selenium-webdriver/lib/http.js:601:13)
         │       at Executor.execute (node_modules/selenium-webdriver/lib/http.js:529:28)
         │       at processTicksAndRejections (node:internal/process/task_queues:96:5)
         │       at Task.exec (prevent_parallel_calls.ts:28:20)
         │
         │
       └-> "after all" hook: unloadMakelogs in "discover/group1"
         │ info [test/functional/fixtures/es_archiver/logstash_functional] Unloading indices from "mappings.json"
         │ info [test/functional/fixtures/es_archiver/logstash_functional] Deleted existing index "logstash-2015.09.22"
         │ info [test/functional/fixtures/es_archiver/logstash_functional] Deleted existing index "logstash-2015.09.20"
         │ info [test/functional/fixtures/es_archiver/logstash_functional] Deleted existing index "logstash-2015.09.21"
         │ info [test/functional/fixtures/es_archiver/logstash_functional] Unloading indices from "data.json.gz"
       └-> "after all" hook: afterTestSuite.trigger in "discover/group1"
         └- ✖ fail: discover/group1 "after all" hook: afterTestSuite.trigger in "discover/group1"
         │      NoSuchSessionError: invalid session id
         │       at Object.throwDecodedError (node_modules/selenium-webdriver/lib/error.js:524:15)
         │       at parseHttpResponse (node_modules/selenium-webdriver/lib/http.js:601:13)
         │       at Executor.execute (node_modules/selenium-webdriver/lib/http.js:529:28)
         │       at runMicrotasks (<anonymous>)
         │       at processTicksAndRejections (node:internal/process/task_queues:96:5)
         │       at Task.exec (prevent_parallel_calls.ts:28:20)
         │
         │
     │
     │0 passing (15.7s)
     │4 failing
     │
     │1)    discover/group1
     │       discover test
     │         query
     │           should show correct time range string by timepicker:
     │
     │      Error: expected 'Sep 19, 2015 @ 06:31:44.000' to equal 'Sep 23, 2015 @ 18:31:44.000'
     │       at Assertion.assert (expect.js:100:11)
     │       at Assertion.apply (expect.js:227:8)
     │       at Assertion.be (expect.js:69:22)
     │       at Context.<anonymous> (_discover.ts:53:31)
     │       at processTicksAndRejections (node:internal/process/task_queues:96:5)
     │       at Object.apply (wrap_function.js:73:16)
     │
     │
     │2)    discover/group1
     │       discover test
     │         query
     │           "after all" hook: afterTestSuite.trigger for "should reload the saved search with persisted query to show the initial hit count":
     │
     │      NoSuchSessionError: invalid session id
     │       at Object.throwDecodedError (node_modules/selenium-webdriver/lib/error.js:524:15)
     │       at parseHttpResponse (node_modules/selenium-webdriver/lib/http.js:601:13)
     │       at Executor.execute (node_modules/selenium-webdriver/lib/http.js:529:28)
     │       at processTicksAndRejections (node:internal/process/task_queues:96:5)
     │       at Task.exec (prevent_parallel_calls.ts:28:20)
     │
     │
     │3)    discover/group1
     │       discover test
     │         "after all" hook: afterTestSuite.trigger in "discover test":
     │
     │      NoSuchSessionError: invalid session id
     │       at Object.throwDecodedError (node_modules/selenium-webdriver/lib/error.js:524:15)
     │       at parseHttpResponse (node_modules/selenium-webdriver/lib/http.js:601:13)
     │       at Executor.execute (node_modules/selenium-webdriver/lib/http.js:529:28)
     │       at processTicksAndRejections (node:internal/process/task_queues:96:5)
     │       at Task.exec (prevent_parallel_calls.ts:28:20)
     │
     │
     │4)    discover/group1
     │       "after all" hook: afterTestSuite.trigger in "discover/group1":
     │
     │      NoSuchSessionError: invalid session id
     │       at Object.throwDecodedError (node_modules/selenium-webdriver/lib/error.js:524:15)
     │       at parseHttpResponse (node_modules/selenium-webdriver/lib/http.js:601:13)
     │       at Executor.execute (node_modules/selenium-webdriver/lib/http.js:529:28)
     │       at runMicrotasks (<anonymous>)
     │       at processTicksAndRejections (node:internal/process/task_queues:96:5)
     │       at Task.exec (prevent_parallel_calls.ts:28:20)
```

</details>

This PR change: I didn't find a good reason why we need to fail silently
on screenshot taking. I added a check WebDriver session status with
`hasOpenWindow` and take failure artefacts only if is still valid.
Next change is to fail FTR after hooks related to WebDriver silently:
there is no help having cascade of the repeated stacktrace so I wrap
WebDriver call in hooks with `tryWebDriverCall` that catches the error
and only prints it for visibility.

<details>

<summary>FTR new output on failure</summary>

```
 │ERROR WebDriver session is no longer valid.
         │      Probably Chrome process crashed when it tried to use more memory than what was available.
         │ERROR Browser is closed, no artifacts were captured for the failure
         └- ✖ fail: discover/group1 discover test query should show correct time range string by timepicker
         │      Error: expected 'Sep 19, 2015 @ 06:31:44.000' to equal 'Sep 23, 2015 @ 18:31:44.000'
         │       at Assertion.assert (expect.js:100:11)
         │       at Assertion.apply (expect.js:227:8)
         │       at Assertion.be (expect.js:69:22)
         │       at Context.<anonymous> (_discover.ts:53:31)
         │       at processTicksAndRejections (node:internal/process/task_queues:96:5)
         │       at Object.apply (wrap_function.js:73:16)
         │
         │
       └-> "after all" hook: afterTestSuite.trigger for "should reload the saved search with persisted query to show the initial hit count"
         │ERROR WebDriver session is no longer valid
     └-> "after all" hook in "discover test"
       │ debg Cleaning all saved objects { space: undefined }
       │ warn browser[SEVERE] ERROR FETCHING BROWSR LOGS: This driver instance does not have a valid session ID (did you call WebDriver.quit()?) and may no longer be used.
       │ succ deleted 2 objects
     └-> "after all" hook: afterTestSuite.trigger in "discover test"
       │ERROR WebDriver session is no longer valid
   └-> "after all" hook: unloadMakelogs in "discover/group1"
     │ info [test/functional/fixtures/es_archiver/logstash_functional] Unloading indices from "mappings.json"
     │ info [test/functional/fixtures/es_archiver/logstash_functional] Deleted existing index "logstash-2015.09.22"
     │ info [test/functional/fixtures/es_archiver/logstash_functional] Deleted existing index "logstash-2015.09.20"
     │ info [test/functional/fixtures/es_archiver/logstash_functional] Deleted existing index "logstash-2015.09.21"
     │ info [test/functional/fixtures/es_archiver/logstash_functional] Unloading indices from "data.json.gz"
   └-> "after all" hook: afterTestSuite.trigger in "discover/group1"
     │ERROR WebDriver session is no longer valid

0 passing (16.2s)
1 failing

1)    discover/group1
       discover test
         query
           should show correct time range string by timepicker:

      Error: expected 'Sep 19, 2015 @ 06:31:44.000' to equal 'Sep 23, 2015 @ 18:31:44.000'
       at Assertion.assert (expect.js:100:11)
       at Assertion.apply (expect.js:227:8)
       at Assertion.be (expect.js:69:22)
       at Context.<anonymous> (_discover.ts:53:31)
       at processTicksAndRejections (node:internal/process/task_queues:96:5)
       at Object.apply (wrap_function.js:73:16)
```

</details>

Flaky-test-runner verification: started 100x to hopefully catch invalid
session on CI
https://buildkite.com/elastic/kibana-flaky-test-suite-runner/builds/2539
Note: locally I was simulating it by calling `this.driver.close()` to
close browser before screenshot taking

(cherry picked from commit 8a95bf7)
  • Loading branch information
@dmlemeshko
dmlemeshko committed Jul 4, 2023
1 parent c1f10d8 commit 62b4106
Show file tree
Hide file tree
Showing 4 changed files with 63 additions and 24 deletions.
30 changes: 28 additions & 2 deletions test/functional/services/common/browser.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@ import { Key, Origin, WebDriver } from 'selenium-webdriver';
import { modifyUrl } from '@kbn/std';

import sharp from 'sharp';
import { NoSuchSessionError } from 'selenium-webdriver/lib/error';
import { WebElementWrapper } from '../lib/web_element_wrapper';
import { FtrProviderContext, FtrService } from '../../ftr_provider_context';
import { Browsers } from '../remote/browsers';
Expand Down Expand Up @@ -632,8 +633,33 @@ class BrowserService extends FtrService {
return Boolean(result?.state === 'granted');
}

public getClipboardValue(): Promise<string> {
return this.driver.executeAsyncScript('navigator.clipboard.readText().then(arguments[0])');
public async getClipboardValue(): Promise<string> {
return await this.driver.executeAsyncScript(
'navigator.clipboard.readText().then(arguments[0])'
);
}

/**
* Checks if browser session is active and any browser window exists
* @returns {Promise<boolean>}
*/
public async hasOpenWindow(): Promise<boolean> {
if (this.driver == null) {
return false;
} else {
try {
const windowHandles = await this.driver.getAllWindowHandles();
return windowHandles.length > 0;
} catch (err) {
if (err instanceof NoSuchSessionError) {
// https://developer.mozilla.org/en-US/docs/Web/WebDriver/Errors/InvalidSessionID
this.log.error(
`WebDriver session is no longer valid.\nProbably Chrome process crashed when it tried to use more memory than what was available.`
);
}
return false;
}
}
}
}

Expand Down
7 changes: 6 additions & 1 deletion test/functional/services/common/failure_debugging.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -50,7 +50,12 @@ export async function FailureDebuggingProvider({ getService }: FtrProviderContex

async function onFailure(_: any, test: Test) {
const name = FtrScreenshotFilename.create(test.fullTitle(), { ext: false });
await Promise.all([screenshots.takeForFailure(name), logCurrentUrl(), savePageHtml(name)]);
const hasOpenWindow = await browser.hasOpenWindow();
if (hasOpenWindow) {
await Promise.all([screenshots.takeForFailure(name), logCurrentUrl(), savePageHtml(name)]);
} else {
log.error('Browser is closed, no artifacts were captured for the failure');
}
}

lifecycle.testFailure.add(onFailure);
Expand Down
20 changes: 4 additions & 16 deletions test/functional/services/common/screenshots.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,6 @@
import { resolve, dirname } from 'path';
import { writeFile, readFileSync, mkdir } from 'fs';
import { promisify } from 'util';
import { NoSuchSessionError } from 'selenium-webdriver/lib/error';

import del from 'del';

Expand Down Expand Up @@ -85,20 +84,9 @@ export class ScreenshotsService extends FtrService {
}

private async capture(path: string, el?: WebElementWrapper) {
try {
this.log.info(`Taking screenshot "${path}"`);
const screenshot = await (el ? el.takeScreenshot() : this.browser.takeScreenshot());
await mkdirAsync(dirname(path), { recursive: true });
await writeFileAsync(path, screenshot, 'base64');
} catch (err) {
this.log.error('SCREENSHOT FAILED');
this.log.error(err);
if (err instanceof NoSuchSessionError) {
// https://developer.mozilla.org/en-US/docs/Web/WebDriver/Errors/InvalidSessionID
this.log.error(
`WebDriver session is no longer valid.\nProbably Chrome process crashed when it tried to use more memory than what was available.`
);
}
}
this.log.info(`Taking ${el ? 'element' : 'window'} screenshot "${path}"`);
const screenshot = await (el ? el.takeScreenshot() : this.browser.takeScreenshot());
await mkdirAsync(dirname(path), { recursive: true });
await writeFileAsync(path, screenshot, 'base64');
}
}
30 changes: 25 additions & 5 deletions test/functional/services/remote/remote.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@
* Side Public License, v 1.
*/

import { NoSuchSessionError } from 'selenium-webdriver/lib/error';
import { FtrProviderContext } from '../../ftr_provider_context';
import { initWebDriver, BrowserConfig } from './webdriver';
import { Browsers } from './browsers';
Expand All @@ -27,6 +28,21 @@ export async function RemoteProvider({ getService }: FtrProviderContext) {
}
};

const tryWebDriverCall = async (command: () => Promise<void>) => {
// Since WebDriver session may be deleted, we fail silently. Use only in after hooks.
try {
await command();
} catch (error) {
if (error instanceof NoSuchSessionError) {
// Avoid duplicating NoSuchSessionError error output on each hook
// https://developer.mozilla.org/en-US/docs/Web/WebDriver/Errors/InvalidSessionID
log.error('WebDriver session is no longer valid');
} else {
throw error;
}
}
};

const browserConfig: BrowserConfig = {
logPollingMs: config.get('browser.logPollingMs'),
acceptInsecureCerts: config.get('browser.acceptInsecureCerts'),
Expand Down Expand Up @@ -72,14 +88,18 @@ export async function RemoteProvider({ getService }: FtrProviderContext) {
});

lifecycle.afterTestSuite.add(async () => {
const { width, height } = windowSizeStack.shift()!;
await driver.manage().window().setRect({ width, height });
await clearBrowserStorage('sessionStorage');
await clearBrowserStorage('localStorage');
await tryWebDriverCall(async () => {
const { width, height } = windowSizeStack.shift()!;
await driver.manage().window().setRect({ width, height });
await clearBrowserStorage('sessionStorage');
await clearBrowserStorage('localStorage');
});
});

lifecycle.cleanup.add(async () => {
await driver.quit();
await tryWebDriverCall(async () => {
await driver.quit();
});
});

return { driver, browserType, consoleLog$ };
Expand Down

0 comments on commit 62b4106

Please sign in to comment.