Unhandled promise rejection on remote device failure

[Lukas-Kullmann]

Sometimes we get unhandled promise rejection warnings when using the new Chrome 71 beta browser on browserstack. Due to this issue, the build on our Jenkins hangs.

The message is:

(node:1537) UnhandledPromiseRejectionWarning: Unhandled promise rejection (rejection id: 1): StatusCodeError: 500 - {"state":"unknown error","sessionId":"[session-id]","hCode":882635045,"value":{"additionalInformation":"\nDriver info: org.openqa.selenium.chrome.ChromeDriver\nCapabilities [{mobileEmulationEnabled=false, hasTouchScreen=false, platform=MAC, acceptSslCerts=false, goog:chromeOptions={debuggerAddress=localhost:51142}, acceptInsecureCerts=false, webStorageEnabled=true, browserName=chrome, takesScreenshot=true, javascriptEnabled=true, setWindowRect=true, unexpectedAlertBehaviour=, applicationCacheEnabled=false, rotatable=false, networkConnectionEnabled=false, chrome={chromedriverVersion=2.42.591059, userDataDir=/var/folders/[...]/.org.chromium.Chromium.UuLkvy}, takesHeapSnapshot=true, pageLoadStrategy=normal, databaseEnabled=false, handlesAlerts=true, version=71.0.3578.20, browserConnectionEnabled=false, nativeEvents=true, locationContextEnabled=true, cssSelectorsEnabled=true}]\nSession ID: c3f2df94bddd40d33c73727b1010e330","localizedMessage":"unknown error: failed to change window state to maximized, current state is normal\n  (Session info: chrome=71.0.3578.20)\n  (Driver info: chromedriver=2.42.591059,platform=Mac OS X 10.14.0 x86_64) (WARNING: The server did not provide any stacktrace information)\nCommand duration or timeout: 183 milliseconds\nBuild info: version: '3.0.1', revision: '1969d75', time: '2016-10-18 09:48:19 -0700'\nSystem info: host: 'mac-185-44-130-194.browserstack.com', ip: '[ip]', os.name: 'Mac OS X', os.arch: 'x86_64', os.version: '10.14', java.version: '1.8.0_51'\nDriver info: org.openqa.selenium.chrome.ChromeDriver\nCapabilities [{mobileEmulationEnabled=false, hasTouchScreen=false, platform=MAC, acceptSslCerts=false, goog:chromeOptions={debuggerAddress=localhost:51142}, acceptInsecureCerts=false, webStorageEnabled=true, browserName=chrome, takesScreenshot=true, javascriptEnabled=true, setWindowRect=true, unexpectedAlertBehaviour=, applicationCacheEnabled=false, rotatable=false, networkConnectionEnabled=false, chrome={chromedriverVersion=2.42.591059, userDataDir=/var/folders/[...]/.org.chromium.Chromium.UuLkvy}, takesHeapSnapshot=true, pageLoadStrategy=normal, databaseEnabled=false, handlesAlerts=true, version=71.0.3578.20, browserConnectionEnabled=false, nativeEvents=true, locationContextEnabled=true, cssSelectorsEnabled=true}]\nSession ID: [session-id]","systemInformation":"System info: host: 'mac-185-44-130-194.browserstack.com', ip: '[ip]', os.name: 'Mac OS X', os.arch: 'x86_64', os.version: '10.14', java.version: '1.8.0_51'","supportUrl":null,"cause":null,"stackTrace":[{"fileName":"NativeConstructorAccessorImpl.java","nativeMethod":true,"methodName":"newInstance0","className":"sun.reflect.NativeConstructorAccessorImpl","hCode":-917798116,"lineNumber":-2,"class":"java.lang.StackTraceElement"},{"fileName":"NativeConstructorAccessorImpl.java","nativeMethod":false,"methodName":"newInstance","className":"sun.reflect.NativeConstructorAccessorImpl","hCode":-1864225098,"lineNumber":62,"class":"java.lang.StackTraceElement"},{"fileName":"DelegatingConstructorAccessorImpl.java","nativeMethod":false,"methodName":"newInstance","className":"sun.reflect.DelegatingConstructorAccessorImpl","hCode":-2122307259,"lineNumber":45,"class":"java.lang.StackTraceElement"},{"fileName":"Constructor.java","nativeMethod":false,"methodName":"newInstance","className":"java.lang.reflect.Constructor","hCode":-1319859920,"lineNumber":422,"class":"java.lang.StackTraceElement"},{"fileName":"ErrorHandler.java","nativeMethod":false,"methodName":"createThrowable","className":"org.openqa.selenium.remote.ErrorHandler","hCode":514255498,"lineNumber":216,"class":"java.lang.StackTraceElement"},{"fileName":"ErrorHandler.java","nativeMethod":false,"methodName":"throwIfResponseFailed","className":"org.openqa.selenium.remote.ErrorHandler","hCode":1091067095,"lineNumber":168,"class":"java.lang.StackTraceElement"},{"fileName":"RemoteWebDriver.java","nativeMethod":false,"methodName":"execute","className":"org.openqa.selenium.remote.RemoteWebDriver","hCode":1767885122,"lineNumber":635,"class":"java.lang.StackTraceElement"},{"fileName":"RemoteWebDriver.java","nativeMethod":false,"methodName":"execute","className":"org.openqa.selenium.remote.RemoteWebDriver","hCode":1767885145,"lineNumber":658,"class":"java.lang.StackTraceElement"},{"fileName":"RemoteWebDriver.java","nativeMethod":false,"methodName":"maximize","className":"org.openqa.selenium.remote.RemoteWebDriver$RemoteWebDriverOptions$RemoteWindow","hCode":1281052034,"lineNumber":882,"class":"java.lang.StackTraceElement"},{"fileName":"EventFiringWebDriver.java","nativeMethod":false,"methodName":"maximize","className":"org.openqa.selenium.support.events.EventFiringWebDriver$EventFiringWindow","hCode":1480076851,"lineNumber":640,"class":"java.lang.StackTraceElement"},{"fileName":"MaximizeWindow.java","nativeMethod":false,"methodName":"call","className":"org.openqa.selenium.remote.server.handler.MaximizeWindow","hCode":653753663,"lineNumber":30,"class":"java.lang.StackTraceElement"},{"fileName":"MaximizeWindow.java","nativeMethod":false,"methodName":"call","className":"org.openqa.selenium.remote.server.handler.MaximizeWindow","hCode":653753655,"lineNumber":22,"class":"java.lang.StackTraceElement"},{"fileName":"FutureTask.java","nativeMethod":false,"methodName":"run","className":"java.util.concurrent.FutureTask","hCode":-820313554,"lineNumber":266,"class":"java.lang.StackTraceElement"},{"fileName":"DefaultSession.java","nativeMethod":false,"methodName":"run","className":"org.openqa.selenium.remote.server.DefaultSession$1","hCode":-255143467,"lineNumber":176,"class":"java.lang.StackTraceElement"},{"fileName":"ThreadPoolExecutor.java","nativeMethod":false,"methodName":"runWorker","className":"java.util.concurrent.ThreadPoolExecutor","hCode":-1285150184,"lineNumber":1142,"class":"java.lang.StackTraceElement"},{"fileName":"ThreadPoolExecutor.java","nativeMethod":false,"methodName":"run","className":"java.util.concurrent.ThreadPoolExecutor$Worker","hCode":-242190645,"lineNumber":617,"class":"java.lang.StackTraceElement"},{"fileName":"Thread.java","nativeMethod":false,"methodName":"run","className":"java.lang.Thread","hCode":-82946320,"lineNumber":745,"class":"java.lang.StackTraceElement"}],"suppressed":[],"message":"unknown error: failed to change window state to maximized, current state is normal\n  (Session info: chrome=71.0.3578.20)\n  (Driver info: chromedriver=2.42.591059 (a3d9684d10d61aa0c45f6723b327283be1ebaad8),platform=Mac OS X 10.14.0 x86_64) (WARNING: The server did not provide any stacktrace information)\nCommand duration or timeout: 183 milliseconds\nBuild info: version: '3.0.1', revision: '1969d75', time: '2016-10-18 09:48:19 -0700'\nSystem info: host: 'mac-185-44-130-194.browserstack.com', ip: '185.44.130.194', os.name: 'Mac OS X', os.arch: 'x86_64', os.version: '10.14', java.version: '1.8.0_51'\nDriver info: org.openqa.selenium.chrome.ChromeDriver\nCapabilities [{mobileEmulationEnabled=false, hasTouchScreen=false, platform=MAC, acceptSslCerts=false, goog:chromeOptions={debuggerAddress=localhost:51142}, acceptInsecureCerts=false, webStorageEnabled=true, browserName=chrome, takesScreenshot=true, javascriptEnabled=true, setWindowRect=true, unexpectedAlertBehaviour=, applicationCacheEnabled=false, rotatable=false, networkConnectionEnabled=false, chrome={chromedriverVersion=2.42.591059, userDataDir=/var/folders/yj/h3bj394n2tn74bp3vdngj35c0000jy/T/.org.chromium.Chromium.UuLkvy}, takesHeapSnapshot=true, pageLoadStrategy=normal, databaseEnabled=false, handlesAlerts=true, version=71.0.3578.20, browserConnectionEnabled=false, nativeEvents=true, locationContextEnabled=true, cssSelectorsEnabled=true}]\nSession ID: c3f2df94bddd40d33c73727b1010e330","hCode":1953207403,"class":"org.openqa.selenium.WebDriverException","buildInformation":{"buildRevision":"1969d75","buildTime":"2016-10-18 09:48:19 -0700","releaseLabel":"3.0.1","hCode":1225834052,"class":"org.openqa.selenium.internal.BuildInfo"},"screen":null},"class":"org.openqa.selenium.remote.Response","status":13}
(node:1537) [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.
Running tests failed { Error: The Chrome 71.0.3578 / Mac OS X 10.14.0 (https://automate.browserstack.com/builds/[build-id]/sessions/[session-id]) browser disconnected. This problem may appear when a browser hangs or is closed, or due to network issues.
    at Timeout.heartbeatTimeout.setTimeout ([...]/node_modules/testcafe/lib/browser/connection/index.js:150:32)
    at ontimeout (timers.js:475:11)
    at tryOnTimeout (timers.js:310:5)
    at Timer.listOnTimeout (timers.js:270:5) constructor: [Function: GeneralError] }

Due to the error message, I think it happens when trying to maximize the window in the test. (But that's not really the problem...)

When digging into the code, I think the problem lies in this line. Here, there is no handling of rejections of requestAPI.

My proposal would be that the test run fails if requestAPI fails and that the remote session is stopped properly. (Currently, the test run hangs due to the unhandled promise rejection and the browserstack session is also not stopped.)

[chheller]

I have also noticed this, running against Chrome 67 with version 1.5.1 of this pacakge and 0.23.0 of Testcafe

 message: '500 - "<html>\\r\\n<head><title>500 Internal Server Error</title></head>\\r\\n<body bgcolor=\\"white\\">\\r\\n<center><h1>500 Internal Server Error</h1></center>\\r\\n<hr><center>nginx/1.10.1</center>\\r\\n</body>\\r\\n</html>\\r\\n"',
  error: '<html>\r\n<head><title>500 Internal Server Error</title></head>\r\n<body bgcolor="white">\r\n<center><h1>500 Internal Server Error</h1></center>\r\n<hr><center>nginx/1.10.1</center>\r\n</body>\r\n</html>\r\n',
  options: 
   { auth: { user: '[secure]', pass: '[secure]' },
     qs: {},
     method: 'POST',
     json: true,
     uri: 'http://hub-cloud.browserstack.com/wd/hub/session/f79dfbecff756f569721b47a14aee573b1aac120/window/current/maximize',
     callback: [Function: RP$callback],
     transform: undefined,
     simple: true,
     resolveWithFullResponse: false,
     transform2xxOnly: false },

The request URL to me suggests that is happening in the maximizeWindow function which similarly lacks error handling, though Lukas could be correct as I haven't done much digging beyond matching the request URL to the only function that explicitly uses it.

[AndreyBelym]

Thank you so much @Lukas-Kullmann @chheller, I've reproduced this problem with the latest Firefox.

By design, all provider methods that implement the Browser Provider API (maximizeWindow, resizeWindow, etc.) shouldn't have an explicit error handling, because all errors must be propagated to TestCafe (thanks to Promises and async/await) and TestCafe should properly catch them and display them in a test report. But there is a bug in the provider or in TestCafe that breaks error propagation and it leads to uncaught exceptions.

About the hack with getURL invoked in the setInterval callback in this line - I agree with @Lukas-Kullmann, it needs some explicit exception handling. However, I'm not quite sure what we should in the case when getURL fails to execute - I guess it means that the browser can't respond to WebDriver requests and it is in the "Application Not Responding" state or disconnected from the network, so we can't do anything with it and should terminate the test session.

[github-actions[bot]]

This issue has been automatically marked as stale because it has not had any activity for a long period. It will be closed and archived if no further activity occurs. However, we may return to this issue in the future. If it still affects you or you have any additional information regarding it, please leave a comment and we will keep it open.

[github-actions[bot]]

We're closing this issue after a prolonged period of inactivity. If it still affects you, please add a comment to this issue with up-to-date information. Thank you.