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

Enormousness "INFO" messages in E2E typescript selenium tests output regardless TS_SELENIUM_LOG_LEVEL=ERROR #18602

Closed
dmytro-ndp opened this issue Dec 11, 2020 · 1 comment · Fixed by #18646
Assignees
Labels
area/qe kind/bug Outline of a bug - must adhere to the bug report template. severity/P1 Has a major impact to usage or development of the system.
Milestone

Comments

@dmytro-ndp
Copy link
Contributor

Describe the bug

There were enormose INFO messages in E2E typescript selenium tests output regardless - e TS_SELENIUM_LOG_LEVEL=ERROR.

Command to run the tests

 docker run --shm-size=1g --net=host --ipc=host \
  -p 5920:5920 \
  -e TS_SELENIUM_HEADLESS='false' \
  -e TS_SELENIUM_DEFAULT_TIMEOUT=300000 \
  -e TS_SELENIUM_LOAD_PAGE_TIMEOUT=240000 \
  -e TS_SELENIUM_WORKSPACE_STATUS_POLLING=20000 \
  -e TS_SELENIUM_BASE_URL=${CHE_URL} \
  -e TS_SELENIUM_LOG_LEVEL='ERROR' \
  -e TS_SELENIUM_MULTIUSER="true" \
  -e TS_SELENIUM_USERNAME="admin" \
  -e TS_SELENIUM_PASSWORD="admin" \
  -v ${WORKSPACE}/che/tests/e2e:/tmp/e2e:Z \
  -e NODE_TLS_REJECT_UNAUTHORIZED=0 \
  quay.io/eclipse/che-e2e:nightly

Test log fragment https://codeready-workspaces-jenkins.rhev-ci-vms.eng.rdu2.redhat.com/view/che-pr-tests/view/K8S/job/Che-Theia-PR-check-E2E-Happy-path-tests-against-K8S__reserved/2111/:

15:48:14   Validation of workspace start
15:48:14 Can not get bearer token. URL used: https:keycloak-eclipse-che.10.0.102.108.nip.io/auth/realms/che/protocol/openid-connect/token
15:48:14   [ERROR] PreferencesHandler.setPreferences failed to get user preferences
15:48:14 (node:228) UnhandledPromiseRejectionWarning: Error: Request failed with status code 400
15:48:14     at createError (/tmp/e2e/node_modules/axios/lib/core/createError.js:16:15)
15:48:14     at settle (/tmp/e2e/node_modules/axios/lib/core/settle.js:18:12)
15:48:14     at IncomingMessage.handleStreamEnd (/tmp/e2e/node_modules/axios/lib/adapters/http.js:202:11)
15:48:14     at emitNone (events.js:111:20)
15:48:14     at IncomingMessage.emit (events.js:208:7)
15:48:14     at endReadableNT (_stream_readable.js:1064:12)
15:48:14     at _combinedTickCallback (internal/process/next_tick.js:138:11)
15:48:14     at process._tickCallback (internal/process/next_tick.js:180:9)
15:48:14 (node:228) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 2)
15:48:14 (node:228) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
15:48:15 Starting ChromeDriver 86.0.4240.22 (398b0743353ff36fb1b82468f63a3a93b4e2e89e-refs/branch-heads/4240@{#378}) on port 19585
15:48:15 Only local connections are allowed.
15:48:15 Please see https://chromedriver.chromium.org/security-considerations for suggestions on keeping ChromeDriver safe.
15:48:15 ChromeDriver was started successfully.
15:48:15 13:48:15.745 INFO [LoggingOptions$1.lambda$export$1] - {"traceId": "347f406d5987fa79fcc41f728638a1bb","spanId": "9974c1e7c73085a4","spanKind": "INTERNAL","eventTime": 1607694495744677226,"eventName": "HTTP request received response","attributes": {"http.status_code": 200,"http.client_class": "org.openqa.selenium.remote.http.netty.NettyClient","http.url": "\u002fsession","http.method": "POST"}}
15:48:15 
15:48:15 13:48:15.752 INFO [ProtocolHandshake.createSession] - Detected dialect: W3C
15:48:15 13:48:15.775 INFO [LoggingOptions$1.lambda$export$1] - {"traceId": "347f406d5987fa79fcc41f728638a1bb","spanId": "b4cf74d4bde7b78d","spanKind": "INTERNAL","eventTime": 1607694495754147335,"eventName": "Driver service created session","attributes": {"upstream.dialect": "W3C","driver.url": "http:\u002f\u002flocalhost:19585","logger": "org.openqa.selenium.grid.node.config.DriverServiceSessionFactory","downstream.dialect": "OSS","session.capabilities": "Capabilities {browserName: chrome, chromeOptions: {args: [--no-sandbox, --disable-web-security, --allow-running-insecure-co..., --ignore-certificate-errors]}}","driver.response": "(Response: SessionID: 3a0c379339e2a87c93ac405ffa96637f, Status: 0, Value: {acceptInsecureCerts=false, browserName=chrome, browserVersion=86.0.4240.75, chrome={chromedriverVersion=86.0.4240.22 (398b0743353ff36fb1b82468f63a3a93b4e2e89e-refs\u002fbranch-heads\u002f4240@{#378}), userDataDir=\u002ftmp\u002f.com.google.Chrome.hnxYvJ}, goog:chromeOptions={debuggerAddress=localhost:40470}, networkConnectionEnabled=false, pageLoadStrategy=normal, platformName=linux, proxy=Proxy(), setWindowRect=true, strictFileInteractability=false, timeouts={implicit=0, pageLoad=300000, script=30000}, unhandledPromptBehavior=dismiss and notify, webauthn:virtualAuthenticators=true})"}}
15:48:15 
15:48:15 13:48:15.782 INFO [LoggingOptions$1.lambda$export$1] - {"traceId": "347f406d5987fa79fcc41f728638a1bb","spanId": "14247df40bdc02f8","spanKind": "INTERNAL","eventTime": 1607694495777524312,"eventName": "Session created by node","attributes": {"session.request.downstreamdialect": "[OSS]","upstream.dialect": "W3C","current.session.count": 0,"session.uri": "http:\u002f\u002flocalhost:19585","logger": "org.openqa.selenium.grid.node.local.LocalNode","session.request.capabilities": "Capabilities {browserName: chrome, chromeOptions: {args: [--no-sandbox, --disable-web-security, --allow-running-insecure-co..., --ignore-certificate-errors]}}","downstream.dialect": "OSS","session.capabilities": "Capabilities {acceptInsecureCerts: false, browserName: chrome, browserVersion: 86.0.4240.75, chrome: {chromedriverVersion: 86.0.4240.22 (398b0743353ff..., userDataDir: \u002ftmp\u002f.com.google.Chrome.hnxYvJ}, goog:chromeOptions: {debuggerAddress: localhost:40470}, networkConnectionEnabled: false, pageLoadStrategy: normal, platformName: linux, proxy: Proxy(), se:options: {cdp: http:\u002f\u002flocalhost:40470}, setWindowRect: true, strictFileInteractability: false, timeouts: {implicit: 0, pageLoad: 300000, script: 30000}, unhandledPromptBehavior: dismiss and notify, webauthn:virtualAuthenticators: true}","session.id": "3a0c379339e2a87c93ac405ffa96637f"}}
...

Recent changes

7cf011b#diff-b96b2d264d519e3f7e46f5b4efcfd0ad8705484447198b5db1b054974ada813a

@dmytro-ndp dmytro-ndp added kind/bug Outline of a bug - must adhere to the bug report template. severity/P1 Has a major impact to usage or development of the system. area/qe labels Dec 11, 2020
@dmytro-ndp dmytro-ndp changed the title TS_SELENIUM_LOG_LEVEL variable doesn't affect on log messages in E2E typescript selenium tests output TS_SELENIUM_LOG_LEVEL variable doesn't affect log level in E2E typescript selenium tests output Dec 11, 2020
@dmytro-ndp dmytro-ndp changed the title TS_SELENIUM_LOG_LEVEL variable doesn't affect log level in E2E typescript selenium tests output Enormousness "INFO" messages in E2E typescript selenium tests output regardless TS_SELENIUM_LOG_LEVEL=ERROR Dec 11, 2020
@rhopp rhopp added this to the Backlog - QE milestone Dec 16, 2020
@rhopp
Copy link
Contributor

rhopp commented Dec 17, 2020

Seems like selenium dockerimages are transitioning to selenium 4.x, which implements OpenTelemetry (this is where these logs are coming from).
I didn't spend much time with this, so I don't know how to disable these outputs right now.
Trivial workaround would be to fall back to selenium grid 3 images, which are still getting published.
Preferably to this tag in particular: https://github.com/SeleniumHQ/docker-selenium/releases/tag/3.141.59-20201119 which contains Chrome 87 - we would need to check, whether #18433 is reproducible there. If yes, we can fall back to https://github.com/SeleniumHQ/docker-selenium/releases/tag/3.141.59-20201117 which contains Chrom 86.

@rhopp rhopp modified the milestones: Backlog - QE, 7.24 Dec 17, 2020
@rhopp rhopp self-assigned this Dec 17, 2020
rhopp added a commit to rhopp/che that referenced this issue Dec 17, 2020
dmytro-ndp pushed a commit that referenced this issue Dec 17, 2020
* 🔨 Fix e2e docker image (log output & crooked screencast)

Fixes #18602 and #18433

Signed-off-by: Radim Hopp <rhopp@redhat.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/qe kind/bug Outline of a bug - must adhere to the bug report template. severity/P1 Has a major impact to usage or development of the system.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants