cerberustesting / cerberus-core

The Open Source Test Automation Platform.
https://cerberus-testing.com
GNU General Public License v3.0
329 stars 101 forks source link

appium session timeout before the end of the test #1557

Closed j0hnsa closed 6 years ago

j0hnsa commented 6 years ago

I've opened one issue about this but it was closed before its resolution (#1527)

On this example if I select test to run for FR,UK,RU it will stop its execution before the 1st test is finished but if I set to run just for FR it will end without any problem.

This would be really important to solve because this is leading me to re-run each test that takes over 5 minutes after the whole campaign run with retries and systematically failed on the longer tests..

Some documentation suggests if we increase newCommandTimeout capability could fix this issue but I've tried all sorts of value here and still no success. What I could se is that after 5 minutes pass of the first test the request to run the 2nd test will come and delete the previous session:

[HTTP] <-- POST /wd/hub/session/a69d67d7-9140-47ea-8316-d20a29fdfb8e/keys 200 4102 ms - 76 [HTTP] --> POST /wd/hub/session/a69d67d7-9140-47ea-8316-d20a29fdfb8e/touch/perform {"actions":[{"action":"tap","options":{"x":296,"y":288}}]} [debug] [MJSONWP] Calling AppiumDriver.performTouch() with args: [[{"action":"tap","options":{"x":296,"y":288}}],"a69d67d7-9140-47ea-8316-d20a29fdfb8e"] [debug] [XCUITest] Executing command 'performTouch' [debug] [XCUITest] Received the following touch action: tap(options={"x":296,"y":288}) [debug] [XCUITest] Found matching gesture: tap [debug] [JSONWP Proxy] Proxying [POST /wda/tap/0] to [POST http://localhost:8003/session/ED22B1F5-6BE8-467C-8A0D-F3187E94826B/wda/tap/0] with body: {"x":296,"y":288} [debug] [JSONWP Proxy] Got response with status 200: {"value":{},"sessionId":"ED22B1F5-6BE8-467C-8A0D-F3187E94826B","status":0} [debug] [MJSONWP] Responding to client with driver.performTouch() result: null [HTTP] <-- POST /wd/hub/session/a69d67d7-9140-47ea-8316-d20a29fdfb8e/touch/perform 200 3798 ms - 76 [HTTP] --> POST /wd/hub/session/a69d67d7-9140-47ea-8316-d20a29fdfb8e/element {"using":"xpath","value":"(//XCUIElementTypeOther[@name='non'])[1]"} [debug] [MJSONWP] Calling AppiumDriver.findElement() with args: ["xpath","(//XCUIElementTypeOther[@name='non'])[1]","a69d67d7-9140-47ea-8316-d20a29fdfb8e"] [debug] [XCUITest] Executing command 'findElement' [debug] [BaseDriver] Valid locator strategies for this request: xpath, id, name, class name, -ios predicate string, -ios class chain, accessibility id [debug] [BaseDriver] Waiting up to 0 ms for condition [debug] [JSONWP Proxy] Proxying [POST /element] to [POST http://localhost:8003/session/ED22B1F5-6BE8-467C-8A0D-F3187E94826B/element] with body: {"using":"xpath","value":"(//XCUIElementTypeOther[@name='non'])[1]"} [debug] [JSONWP Proxy] Got response with status 200: {"value":{"ELEMENT":"1A1AE8CF-7520-41AC-8E08-9A72E60B6A12"},"sessionId":"ED22B1F5-6BE8-467C-8A0D-F3187E94826B","status":0} [debug] [MJSONWP] Responding to client with driver.findElement() result: {"ELEMENT":"1A1AE8CF-7520-41AC-8E08-9A72E60B6A12"} [HTTP] <-- POST /wd/hub/session/a69d67d7-9140-47ea-8316-d20a29fdfb8e/element 200 12634 ms - 122 [HTTP] --> POST /wd/hub/session/a69d67d7-9140-47ea-8316-d20a29fdfb8e/element {"using":"xpath","value":"(//XCUIElementTypeOther[@name='non'])[1]"} [debug] [MJSONWP] Calling AppiumDriver.findElement() with args: ["xpath","(//XCUIElementTypeOther[@name='non'])[1]","a69d67d7-9140-47ea-8316-d20a29fdfb8e"] [debug] [XCUITest] Executing command 'findElement' [debug] [BaseDriver] Valid locator strategies for this request: xpath, id, name, class name, -ios predicate string, -ios class chain, accessibility id [debug] [BaseDriver] Waiting up to 0 ms for condition [debug] [JSONWP Proxy] Proxying [POST /element] to [POST http://localhost:8003/session/ED22B1F5-6BE8-467C-8A0D-F3187E94826B/element] with body: {"using":"xpath","value":"(//XCUIElementTypeOther[@name='non'])[1]"} [HTTP] --> POST /wd/hub/session {"desiredCapabilities":{"automationName":"XCUITest","platform":"MAC","app":"/LaredouteApps/LaRedoute_v8_4_318.ipa","browserName":"iPhone","setValue":true,"udid":"e9f4d10b6ac8f0f45c8da072c9aee0639bd0587f","wdaLocalPort":8003,"version":"","newCommandTimeout":900,"platformVersion":"10.3.1","platformName":"iOS","deviceName":"iPhone 5s","fullReset":true,"clearSystemFiles":true}} [debug] [MJSONWP] Calling AppiumDriver.createSession() with args: [{"automationName":"XCUITest","platform":"MAC","app":"/LaredouteApps/LaRedoute_v8_4_318.ipa","browserName":"iPhone","setValue":true,"udid":"e9f4d10b6ac8f0f45c8da072c9aee0639bd0587f","wdaLocalPort":8003,"version":"","newCommandTimeout":900,"platformVersion":"10.3.1","platformName":"iOS","deviceName":"iPhone 5s","fullReset":true,"clearSystemFiles":true},null,null] [debug] [BaseDriver] Event 'newSessionRequested' logged at 1511198676392 (17:24:36 GMT+0000 (WET)) [Appium] Creating new XCUITestDriver (v2.51.1) session [Appium] Capabilities: [Appium] automationName: 'XCUITest' [Appium] platform: 'MAC' [Appium] app: '/LaredouteApps/LaRedoute_v8_4_318.ipa' [Appium] browserName: 'iPhone' [Appium] setValue: true [Appium] udid: 'e9f4d10b6ac8f0f45c8da072c9aee0639bd0587f' [Appium] wdaLocalPort: 8003 [Appium] version: '' [Appium] newCommandTimeout: 900 [Appium] platformVersion: '10.3.1' [Appium] platformName: 'iOS' [Appium] deviceName: 'iPhone 5s' [Appium] fullReset: true [Appium] clearSystemFiles: true [Appium] xcodeConfigFile: '/Users/itsqdtests/appium/conf/appium2.xconfig' [Appium] useNewWDA: true [Appium] timeout: 60000 [Appium] Session override is on. Deleting other 1 active session. [Appium] Removing session a69d67d7-9140-47ea-8316-d20a29fdfb8e from our master session list [debug] [JSONWP Proxy] Proxying [DELETE /session/a69d67d7-9140-47ea-8316-d20a29fdfb8e] to [DELETE http://localhost:8003/session/ED22B1F5-6BE8-467C-8A0D-F3187E94826B] with no body [debug] [JSONWP Proxy] Got response with status 200: {"value":{"ELEMENT":"EBEF345D-5705-4B1F-82A5-A2CA4BC5FEA8"},"sessionId":"ED22B1F5-6BE8-467C-8A0D-F3187E94826B","status":0} [debug] [MJSONWP] Responding to client with driver.findElement() result: {"ELEMENT":"EBEF345D-5705-4B1F-82A5-A2CA4BC5FEA8"} [HTTP] <-- POST /wd/hub/session/a69d67d7-9140-47ea-8316-d20a29fdfb8e/element 200 12976 ms - 122 [HTTP] --> POST /wd/hub/session/a69d67d7-9140-47ea-8316-d20a29fdfb8e/touch/perform {"actions":[{"action":"tap","options":{"element":"EBEF345D-5705-4B1F-82A5-A2CA4BC5FEA8"}}]} [HTTP] <-- POST /wd/hub/session/a69d67d7-9140-47ea-8316-d20a29fdfb8e/touch/perform 404 11 ms - 131 [debug] [JSONWP Proxy] Got response with status 200: "{\n \"value\" : {\n\n },\n \"sessionId\" : \"072ECA35-1991-490A-974A-999EE30A5699\",\n \"status\" : 0\n}" [XCUITest] Shutting down sub-processes [XCUITest] Shutting down iproxy process (pid 7262) [debug] [XCUITest] iproxy exited with code 'null' [XCUITest] Shutting down xcodebuild process (pid 7263) [XCUITest] xcodebuild exited with code 'null' and signal 'SIGTERM' [XCUITest] Setting '755' permissions to '/Users/itsqdtests/Library/Developer/Xcode/DerivedData/WebDriverAgent-brdadhpuduowllgivnnvuygpwhzy/Logs/Test/Attachments' folder [XCUITest] Cleaning test logs in '/Users/itsqdtests/Library/Developer/Xcode/DerivedData/WebDriverAgent-brdadhpuduowllgivnnvuygpwhzy/Logs' folder [debug] [iOS] Clearing log files [debug] [iOS] Deleting '/Users/itsqdtests/Library/Developer/Xcode/DerivedData/WebDriverAgent-brdadhpuduowllgivnnvuygpwhzy/Logs'. Freeing 10M. [debug] [iOS] Finished clearing log files [debug] [iOSLog] Stopping iOS log capture [BaseDriver] The following capabilities were provided, but are not recognized by appium: platform, setValue, version, timeout. [BaseDriver] Session created with session id: 6d2cf827-54e3-4e3d-9577-de8878b5f9a1 [debug] [XCUITest] Xcode version set to '8.3.2' (tools v9.0.1.0.1.1506734476) [debug] [XCUITest] iOS SDK Version set to '10.3' [debug] [BaseDriver] Event 'xcodeDetailsRetrieved' logged at 1511198682083 (17:24:42 GMT+0000 (WET)) [debug] [XCUITest] Available devices: e9f4d10b6ac8f0f45c8da072c9aee0639bd0587f [debug] [XCUITest] Creating iDevice object with udid 'e9f4d10b6ac8f0f45c8da072c9aee0639bd0587f' [XCUITest] Determining device to run tests on: udid: 'e9f4d10b6ac8f0f45c8da072c9aee0639bd0587f', real device: true [BaseDriver] Using local app '/LaredouteApps/LaRedoute_v8_4_318.ipa' [debug] [BaseDriver] Copying local zip to tmp dir [debug] [BaseDriver] Unzipping /var/folders/qx/ckkqsb5x4rd2pxcfkzn_xgyw0000gn/T/20171020-7243-vgubah.s9se4p9zfr/appium-app.zip [debug] [BaseDriver] Testing zip archive: /var/folders/qx/ckkqsb5x4rd2pxcfkzn_xgyw0000gn/T/20171020-7243-vgubah.s9se4p9zfr/appium-app.zip [HTTP] --> DELETE /wd/hub/session/a69d67d7-9140-47ea-8316-d20a29fdfb8e {} [HTTP] <-- DELETE /wd/hub/session/a69d67d7-9140-47ea-8316-d20a29fdfb8e 404 18 ms - 131 [BaseDriver] Unzipped local app to '/var/folders/qx/ckkqsb5x4rd2pxcfkzn_xgyw0000gn/T/20171020-7243-vgubah.s9se4p9zfr/Payload/LaRedoute.app' [debug] [BaseDriver] Event 'appConfigured' logged at 1511198685257 (17:24:45 GMT+0000 (WET)) [debug] [XCUITest] Checking whether app '/var/folders/qx/ckkqsb5x4rd2pxcfkzn_xgyw0000gn/T/20171020-7243-vgubah.s9se4p9zfr/Payload/LaRedoute.app' is actually present on file system [debug] [XCUITest] App is present [debug] [iOS] Getting bundle ID from app '/var/folders/qx/ckkqsb5x4rd2pxcfkzn_xgyw0000gn/T/20171020-7243-vgubah.s9se4p9zfr/Payload/LaRedoute.app': 'com.Redoute.RedouteIphone' [debug] [BaseDriver] Event 'resetStarted' logged at 1511198685344 (17:24:45 GMT+0000 (WET)) [debug] [XCUITest] Reset: running ios real device reset flow [debug] [XCUITest] Reset: fullReset requested. Will try to uninstall the app 'com.Redoute.RedouteIphone'. [debug] [XCUITest] Reset: removed 'com.Redoute.RedouteIphone' [debug] [BaseDriver] Event 'resetComplete' logged at 1511198686083 (17:24:46 GMT+0000 (WET)) [debug] [iOSLog] Attempting iOS device log capture via libimobiledevice idevicesyslog [debug] [iOSLog] Starting iOS device log capture with: 'idevicesyslog' [debug] [BaseDriver] Event 'logCaptureStarted' logged at 1511198686463 (17:24:46 GMT+0000 (WET)) [XCUITest] Setting up real device [debug] [XCUITest] Installing '/var/folders/qx/ckkqsb5x4rd2pxcfkzn_xgyw0000gn/T/20171020-7243-vgubah.s9se4p9zfr/Payload/LaRedoute.app' on device with UUID 'e9f4d10b6ac8f0f45c8da072c9aee0639bd0587f'... [debug] [XCUITest] The app has been installed successfully. [debug] [BaseDriver] Event 'appInstalled' logged at 1511198695767 (17:24:55 GMT+0000 (WET)) [XCUITest] Using WDA path: '/usr/local/lib/node_modules/appium/node_modules/appium-xcuitest-driver/WebDriverAgent' [XCUITest] Using WDA agent: '/usr/local/lib/node_modules/appium/node_modules/appium-xcuitest-driver/WebDriverAgent/WebDriverAgent.xcodeproj' [debug] [XCUITest] Capability 'useNewWDA' set to true, so uninstalling WDA before proceeding [XCUITest] Shutting down sub-processes [debug] [XCUITest] Removing WDA application from device [debug] [BaseDriver] Event 'wdaUninstalled' logged at 1511198696320 (17:24:56 GMT+0000 (WET)) [debug] [BaseDriver] Event 'wdaStartAttempted' logged at 1511198696322 (17:24:56 GMT+0000 (WET)) [XCUITest] Launching WebDriverAgent on the device [debug] [XCUITest] Carthage found: '/usr/local/bin/carthage' [debug] [XCUITest] Killing running processes 'xcodebuild.e9f4d10b6ac8f0f45c8da072c9aee0639bd0587f, iproxy 8003' for the device e9f4d10b6ac8f0f45c8da072c9aee0639bd0587f... [debug] [XCUITest] 'pgrep -nif xcodebuild.e9f4d10b6ac8f0f45c8da072c9aee0639bd0587f' didn't detect any matching processes. Return code: 1 [debug] [XCUITest] 'pgrep -nif iproxy 8003' didn't detect any matching processes. Return code: 1 [debug] [XCUITest] Starting iproxy to forward traffic from local port 8003 to device port 8100 over USB [debug] [XCUITest] Using Xcode configuration file: '/Users/itsqdtests/appium/conf/appium2.xconfig' [debug] [XCUITest] Beginning test with command 'xcodebuild build-for-testing test-without-building -project /usr/local/lib/node_modules/appium/node_modules/appium-xcuitest-driver/WebDriverAgent/WebDriverAgent.xcodeproj -scheme WebDriverAgentRunner -destination id=e9f4d10b6ac8f0f45c8da072c9aee0639bd0587f IPHONEOS_DEPLOYMENT_TARGET=10.3 -xcconfig /Users/itsqdtests/appium/conf/appium2.xconfig' in directory '/usr/local/lib/node_modules/appium/node_modules/appium-xcuitest-driver/WebDriverAgent' [debug] [XCUITest] Output from xcodebuild will not be logged. To see xcode logging, use 'showXcodeLog' desired capability [debug] [XCUITest] Waiting up to 60000ms for WebDriverAgent to start [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [XCUITest] Log file for xcodebuild test: /Users/itsqdtests/Library/Developer/Xcode/DerivedData/WebDriverAgent-brdadhpuduowllgivnnvuygpwhzy/Logs/Test/F56D7B66-A1E8-4BCA-80D5-4686216ECDCF/Session-WebDriverAgentRunner-2017-11-20_172510-BDRcWR.log [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Proxying [GET /status] to [GET http://localhost:8003/status] with no body [debug] [JSONWP Proxy] Got response with status 200: "{\n \"value\" : {\n \"state\" : \"success\",\n \"os\" : {\n \"name\" : \"iOS\",\n \"version\" : \"10.3.2\"\n },\n \"ios\" : {\n \"simulatorVersion\" : \"10.3.2\",\n \"ip\" : \"192.168.1.186\"\n },\n \"build\" : {\n \"time\" : \"Nov 9 2017 17:01:44\"\n }\n },\n \"sessionId\" : \"CB8AB9B6-71A2-4534-B47B-F527B7813BD3\",\n \"status\" : 0\n}" [debug] [XCUITest] WebDriverAgent running on ip '192.168.1.186' [debug] [XCUITest] WebDriverAgent successfully started after 18283ms [debug] [BaseDriver] Event 'wdaSessionAttempted' logged at 1511198719740 (17:25:19 GMT+0000 (WET)) [debug] [XCUITest] Sending createSession command to WDA [debug] [JSONWP Proxy] Proxying [POST /session] to [POST http://localhost:8003/session] with body: {"desiredCapabilities":{"bundleId":"com.Redoute.RedouteIphone","arguments":[],"environment":{},"shouldWaitForQuiescence":true,"shouldUseTestManagerForVisibilityDetection":false,"maxTypingFrequency":60,"shouldUseSingletonTestManager":true}} [debug] [JSONWP Proxy] Got response with status 200: {"value":{"sessionId":"8D2CF07E-A718-4E90-A905-DDE8D5163B53","capabilities":{"device":"iphone","browserName":"La Redoute","sdkVersion":"10.3.2","CFBundleIdentifier":"com.Redoute.RedouteIphone"}},"sessionId":"8D2CF07E-A718-4E90-A905-DDE8D5163B53","status":0} [debug] [BaseDriver] Event 'wdaSessionStarted' logged at 1511198725483 (17:25:25 GMT+0000 (WET)) [XCUITest] Setting '555' permissions to '/Users/itsqdtests/Library/Developer/Xcode/DerivedData/WebDriverAgent-brdadhpuduowllgivnnvuygpwhzy/Logs/Test/Attachments' folder [debug] [BaseDriver] Event 'wdaPermsAdjusted' logged at 1511198725553 (17:25:25 GMT+0000 (WET)) [debug] [BaseDriver] Event 'wdaStarted' logged at 1511198725555 (17:25:25 GMT+0000 (WET)) [debug] [XCUITest] Setting initial orientation to 'PORTRAIT' [debug] [JSONWP Proxy] Proxying [POST /orientation] to [POST http://localhost:8003/session/8D2CF07E-A718-4E90-A905-DDE8D5163B53/orientation] with body: {"orientation":"PORTRAIT"} [debug] [JSONWP Proxy] Got response with status 200: {"value":{},"sessionId":"8D2CF07E-A718-4E90-A905-DDE8D5163B53","status":0} [debug] [BaseDriver] Event 'orientationSet' logged at 1511198727360 (17:25:27 GMT+0000 (WET)) [Appium] New XCUITestDriver session created successfully, session 6d2cf827-54e3-4e3d-9577-de8878b5f9a1 added to master session list [debug] [BaseDriver] Event 'newSessionStarted' logged at 1511198727362 (17:25:27 GMT+0000 (WET)) [debug] [MJSONWP] Responding to client with driver.createSession() result: {"webStorageEnabled":false,"locationContextEnabled":false,"browserName":"iPhone","platform":"MAC","javascriptEnabled":true,"databaseEnabled":false,"takesScreenshot":true,"networkConnectionEnabled":false,"automationName":"XCUITest","app":"/LaredouteApps/LaRedoute_v8_4_318.ipa","setValue":true,"udid":"e9f4d10b6ac8f0f45c8da072c9aee0639bd0587f","wdaLocalPort":8003,"version":"","newCommandTimeout":900,"platformVersion":"10.3.1","platformName":"iOS","deviceName":"iPhone 5s","fullReset":true,"clearSystemFiles":true,"xcodeConfigFile":"/Users/itsqdtests/appium/conf/appium2.xconfig","useNewWDA":true,"timeout":60000} [HTTP] <-- POST /wd/hub/session 200 50971 ms - 685 [HTTP] --> POST /wd/hub/session/6d2cf827-54e3-4e3d-9577-de8878b5f9a1/element {"using":"xpath","value":"//XCUIElementTypeButton[@label='Ok']/preceding-sibling::XCUIElementTypeStaticText[1]"} [debug] [MJSONWP] Calling AppiumDriver.findElement() with args: ["xpath","//XCUIElementTypeButton[@label='Ok']/preceding-sibling::XCUIElementTypeStaticText[1]","6d2cf827-54e3-4e3d-9577-de8878b5f9a1"] [debug] [XCUITest] Executing command 'findElement' [debug] [BaseDriver] Valid locator strategies for this request: xpath, id, name, class name, -ios predicate string, -ios class chain, accessibility id [debug] [BaseDriver] Waiting up to 0 ms for condition [debug] [JSONWP Proxy] Proxying [POST /element] to [POST http://localhost:8003/session/8D2CF07E-A718-4E90-A905-DDE8D5163B53/element] with body: {"using":"xpath","value":"//XCUIElementTypeButton[@label='Ok']/preceding-sibling::XCUIElementTypeStaticText[1]"} [debug] [JSONWP Proxy] Got response with status 200: {"value":{"ELEMENT":"A24E03E1-A39D-47F7-A5C3-CE187E9D1A90"},"sessionId":"8D2CF07E-A718-4E90-A905-DDE8D5163B53","status":0} [debug] [MJSONWP] Responding to client with driver.findElement() result: {"ELEMENT":"A24E03E1-A39D-47F7-A5C3-CE187E9D1A90"} [HTTP] <-- POST /wd/hub/session/6d2cf827-54e3-4e3d-9577-de8878b5f9a1/element 200 1461 ms - 122 [HTTP] --> GET /wd/hub/session/6d2cf827-54e3-4e3d-9577-de8878b5f9a1/element/A24E03E1-A39D-47F7-A5C3-CE187E9D1A90/name {} [MJSONWP] Driver proxy active, passing request on via HTTP proxy [debug] [XCUITest] Executing command 'proxyReqRes' [debug] [JSONWP Proxy] Proxying [GET /wd/hub/session/6d2cf827-54e3-4e3d-9577-de8878b5f9a1/element/A24E03E1-A39D-47F7-A5C3-CE187E9D1A90/name] to [GET http://localhost:8003/session/8D2CF07E-A718-4E90-A905-DDE8D5163B53/element/A24E03E1-A39D-47F7-A5C3-CE187E9D1A90/name] with body: {} [debug] [JSONWP Proxy] Got response with status 200: "{\n \"value\" : \"XCUIElementTypeStaticText\",\n \"sessionId\" : \"8D2CF07E-A718-4E90-A905-DDE8D5163B53\",\n \"status\" : 0\n}" [JSONWP Proxy] Replacing sessionId 8D2CF07E-A718-4E90-A905-DDE8D5163B53 with 6d2cf827-54e3-4e3d-9577-de8878b5f9a1 [HTTP] <-- GET /wd/hub/session/6d2cf827-54e3-4e3d-9577-de8878b5f9a1/element/A24E03E1-A39D-47F7-A5C3-CE187E9D1A90/name 200 358 ms - 99 [HTTP] --> GET /wd/hub/session/6d2cf827-54e3-4e3d-9577-de8878b5f9a1/element/A24E03E1-A39D-47F7-A5C3-CE187E9D1A90/name {} [MJSONWP] Driver proxy active, passing request on via HTTP proxy [debug] [XCUITest] Executing command 'proxyReqRes'

Any clue how to solve this?

Regards

bcivel commented 6 years ago

Hello @j0hnsa I couldn't confirm because no access to your environment. But it seems you're right. When you run multiple testcase, we create HTTP connection with a timeout set to a piece of time set into parameter (cerberus_queueexecution_timeout). Regarding your description, your value must be set to 300000ms When you run simple testcase, HTTP timeout is managed by glassfish and I don't know the maximum you've set, but probably up to 5 minutes. I advice you to ask your Cerberus admin to set the parameter cerberus_queueexecution_timeout to a biggest value (600000ms >> 10min for exemple)

j0hnsa commented 6 years ago

Hello @bcivel,

It's weird because we have a long timeout set for this parameter: imagem

Do you have any other guess?

Regards,

vertigo17 commented 6 years ago

There are indeed no reason why the test would stop after 5 minutes. We need to investigate more: 1/ Can you provide the link of 2 same executions that take more than 5 minutes. 1 that was executed without queue (single execution from run page) 1 that was executed from the queue. If I understand right, the single execution will work fine till the end when the other stops after 5 minutes. Please confirm my understanding is correct. 1a/ Can you provide the 2 logs. The one that works and the one that stops after 5 minutes ? 2/ Is that systematic ? 3/ Is that always after exactly 5 minutes 4/ does it happened also with GUI application test (Selenium) or even SRV application test (services) ? Can you do all that in new QA (with latest Cerberus version) ?

j0hnsa commented 6 years ago

Hello @vertigo17 ,

Sorry for coming back to this old topic, but this issue is still present:

Executed from Queue: FR: http://192.168.134.17/Cerberus/TestCaseExecution.jsp?executionId=54576104 (5m05s) RU: http://192.168.134.17/Cerberus/TestCaseExecution.jsp?executionId=54576179 (5m26s) UK: http://192.168.134.17/Cerberus/TestCaseExecution.jsp?executionId=54576282 (this was OK took less than 5min) long-test-log.txt

Single execution: FR: http://192.168.134.17/Cerberus/TestCaseExecution.jsp?executionId=54576428 (5m53s) RU: http://192.168.134.17/Cerberus/TestCaseExecution.jsp?executionId=54576530 (7m40s)

single-execs.txt

This doesn't seem to occur with Gui application (added from queue): http://cerberus.siege.red/Cerberus/ReportingExecutionByTag.jsp?Tag=IT140258-2018-01-15T174038 1 test took over 6min

I'll perform the same tests in QA tomorow for comparison.

Regards

vertigo17 commented 6 years ago

I manage to perform a test using BrowserStack that last more than 5 minutes. http://vm.cerberus-testing.org:28082/CerberusPROD/TestCaseExecution.jsp?executionId=26686

There must be a 5 minutes session timeout on your local Appium configuration that could explain that issue. Can you check if this is really linked with long running test. Looks on the logs that you execute every tests in sequence. Does execution fail if you execute a single execution taking more than 5 minutes ?

j0hnsa commented 6 years ago

On single executions this problem does not occur thats why I thought it could be linked to AddtoExecutionQueue. I don't set any kind of timeout also...

Regards

vertigo17 commented 6 years ago

Very good. That gives us an easy way to reproduce. Looks like we are not closing correctly the 1st execution that gets reused in the 2nd execution. We will check and get back to you.

j0hnsa commented 6 years ago

Good news! This is working fine on new cerberus :)

Regards

vertigo17 commented 6 years ago

So I beleive that was a Appium client issue. Can you confirm wich Appium server you are using ? Although, I thought we manage to reproduce on qa.cerberus-testing.org on latest version which is strange.

j0hnsa commented 6 years ago

Yes its strange because it was replicated before but no upgrade was done on my side meanwhile. I'm running the latest stable version of appium currently on 1.7.2.

Regards