search

eclipse-che / che

Kubernetes based Cloud Development Environments for Enterprise Teams
http://eclipse.org/che
Eclipse Public License 2.0
6.99k stars 1.19k forks source link

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

Closed dmytro-ndp closed 3 years ago

dmytro-ndp commented 3 years ago

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

https://github.com/eclipse/che/commit/7cf011ba3875ce4a012c6b46b0ed92d2d8c201a6#diff-b96b2d264d519e3f7e46f5b4efcfd0ad8705484447198b5db1b054974ada813a

rhopp commented 3 years ago

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 https://github.com/eclipse/che/issues/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.