We’re seeing an intermittent issue on our CI runs where the IOSDriver takes 20 minutes to start up. Has anyone else seen it? I haven’t been able to observe it real-time so it’s difficult to tell what’s going on. But the appium logs just show an inexplicable set of 9-10 minute delays during the launch process.
Log attached. Note the 9-minute delay after the 2nd “Cleaning simulator” entry followed by a 10-minute delay after “Calling AppiumDriver.createSession()”. This all results from a single call to instantiate a new IOSDriver
We’re running Xcode 7.0 / Appium 1.5.3
2016-06-30 15:09:59:379 - [HTTP] → POST /wd/hub/session {“desiredCapabilities”:{“automationName”:“Appium”,“newCommandTimeout”:120,“platformVersion”:“9.0”,“app”:“/builds/MyApp.app”,“platform”:“MAC”,“platformName”:“iOS”,“deviceName”:“iPad Air”,“fullReset”:“true”,“appiumVersion”:“1.5.3”,“launchTimeout”:90000}}
2016-06-30 15:09:59:380 - [MJSONWP] Calling AppiumDriver.createSession() with args: [{“automationName”:“Appium”…
2016-06-30 15:09:59:383 - [Appium] Creating new IosDriver session
2016-06-30 15:09:59:384 - [Appium] Capabilities:
2016-06-30 15:09:59:385 - [Appium] automationName: ‘Appium’
2016-06-30 15:09:59:385 - [Appium] newCommandTimeout: 120
2016-06-30 15:09:59:385 - [Appium] platformVersion: ‘9.0’
2016-06-30 15:09:59:386 - [Appium] app: ‘/builds/MyApp.app’
2016-06-30 15:09:59:387 - [Appium] platform: ‘MAC’
2016-06-30 15:09:59:387 - [Appium] platformName: ‘iOS’
2016-06-30 15:09:59:387 - [Appium] deviceName: ‘iPad Air’
2016-06-30 15:09:59:388 - [Appium] fullReset: ‘true’
2016-06-30 15:09:59:388 - [Appium] appiumVersion: ‘1.5.3’
2016-06-30 15:09:59:388 - [Appium] launchTimeout: 90000
2016-06-30 15:09:59:394 - [BaseDriver] Capability ‘fullReset’ changed from string to boolean. This may cause unexpected behavior
2016-06-30 15:09:59:399 - [BaseDriver] The following capabilities were provided, but are not recognized by appium: platform, appiumVersion.
2016-06-30 15:09:59:401 - [BaseDriver] Session created with session id: 7bd658d8-eeab-4718-83f1-4524144c343a
2016-06-30 15:09:59:406 - [BaseDriver] Using local app ‘/builds/MyApp.app’
2016-06-30 15:10:00:801 - [iOSSim] Retrieving device name string for Xcode version 7.0
2016-06-30 15:10:01:146 - [iOSSim] Constructing iOS simulator for Xcode version 7.0
2016-06-30 15:10:01:154 - [iOS] Could not file localizable strings file ‘Localizable.strings’!
2016-06-30 15:10:01:162 - [iOS] Extracted bundleID: com.MyApp from app: /builds/MyApp.app
2016-06-30 15:10:01:735 - [iOSSim] Cleaning simulator 45C8B918-65A0-4EC7-99D5-7EA837051F52
2016-06-30 15:10:02:671 - [Instruments] Launching instruments
2016-06-30 15:10:02:679 - [Instruments] On xcode 7.0+, instruments-without-delay does not work, skipping instruments-without-delay
2016-06-30 15:10:34:011 - [UIAuto] Instruments is ready to receive commands
2016-06-30 15:10:46:938 - [iOSSim] Cleaning simulator 45C8B918-65A0-4EC7-99D5-7EA837051F52
2016-06-30 15:19:59:349 - [HTTP] ← POST /wd/hub/session - - ms - -
2016-06-30 15:20:01:387 - [HTTP] → POST /wd/hub/session {“desiredCapabilities”:{“automationName”:“Appium”,“newCommandTimeout”:120,“platformVersion”:“9.0”,“app”:“/builds/MyApp.app”,“platform”:“MAC”,“platformName”:“iOS”,“deviceName”:“iPad Air”,“fullReset”:“true”,“appiumVersion”:“1.5.3”,“launchTimeout”:90000}}
2016-06-30 15:20:01:390 - [MJSONWP] Calling AppiumDriver.createSession() with args: [{“automationName”:“Appium”…
2016-06-30 15:30:01:381 - [HTTP] ← POST /wd/hub/session - - ms - -
2016-06-30 15:30:07:857 - [Appium] Welcome to Appium v1.5.3 (REV 9c663cf18eb426f32a37779504fadd053204655b)
But I’m still seeing the issue. Also, I found some situations where this happens mid-test. Appium hangs for 10 minutes and eventually times out for basic commands like AppiumDriver.title()
Console (9876 is my appium port):
03:42:22 Jul 14, 2016 3:42:21 AM org.apache.http.impl.execchain.RetryExec execute
03:42:22 INFO: I/O exception (org.apache.http.NoHttpResponseException) caught when processing request to {}->http://127.0.0.1:9876: The target server failed to respond
03:42:22 Jul 14, 2016 3:42:21 AM org.apache.http.impl.execchain.RetryExec execute
03:42:22 INFO: Retrying request to {}->http://127.0.0.1:9876
03:52:22 Jul 14, 2016 3:52:21 AM org.apache.http.impl.execchain.RetryExec execute
03:52:22 INFO: I/O exception (org.apache.http.NoHttpResponseException) caught when processing request to {}->http://127.0.0.1:9876: The target server failed to respond
03:52:22 Jul 14, 2016 3:52:21 AM org.apache.http.impl.execchain.RetryExec execute
03:52:22 INFO: Retrying request to {}->http://127.0.0.1:9876
04:02:22 Jul 14, 2016 4:02:21 AM org.apache.http.impl.execchain.RetryExec execute
04:02:22 INFO: I/O exception (org.apache.http.NoHttpResponseException) caught when processing request to {}->http://127.0.0.1:9876: The target server failed to respond
04:02:22 Jul 14, 2016 4:02:21 AM org.apache.http.impl.execchain.RetryExec execute
04:02:22 INFO: Retrying request to {}->http://127.0.0.1:9876
Appium log:
2016-07-14 03:32:21:253 - [MJSONWP] Calling AppiumDriver.click() with args: [“5002”,"f8fe3d86-b2fd-45b3…
2016-07-14 03:32:21:766 - [MJSONWP] Responding to client with driver.click() result: null
2016-07-14 03:32:21:767 - [HTTP] ← POST /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/element/5002/click 200 514 ms - 76
2016-07-14 03:32:21:770 - [HTTP] → GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/context {}
2016-07-14 03:32:21:771 - [MJSONWP] Calling AppiumDriver.getCurrentContext() with args: ["f8fe3d86-b2fd-45b3-89ca-6…
2016-07-14 03:32:21:772 - [MJSONWP] Responding to client with driver.getCurrentContext() result: “WEBVIEW_78595.1”
2016-07-14 03:32:21:774 - [HTTP] ← GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/context 200 3 ms - 89
2016-07-14 03:32:21:777 - [HTTP] → GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/title {}
2016-07-14 03:32:21:778 - [MJSONWP] Calling AppiumDriver.title() with args: ["f8fe3d86-b2fd-45b3-89ca-6…
2016-07-14 03:42:21:772 - [HTTP] ← GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/title - - ms - -
2016-07-14 03:42:21:806 - [HTTP] → GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/title {}
2016-07-14 03:42:21:808 - [MJSONWP] Calling AppiumDriver.title() with args: ["f8fe3d86-b2fd-45b3-89ca-6…
2016-07-14 03:52:21:804 - [HTTP] ← GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/title - - ms - -
2016-07-14 03:52:21:807 - [HTTP] → GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/title {}
2016-07-14 03:52:21:807 - [MJSONWP] Calling AppiumDriver.title() with args: ["f8fe3d86-b2fd-45b3-89ca-6…
2016-07-14 04:02:21:804 - [HTTP] ← GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/title - - ms - -
2016-07-14 04:02:21:806 - [HTTP] → GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/title {}
2016-07-14 04:02:21:807 - [MJSONWP] Calling AppiumDriver.title() with args: ["f8fe3d86-b2fd-45b3-89ca-6…
2016-07-14 04:12:21:804 - [HTTP] ← GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/title - - ms - -
2016-07-14 04:12:23:814 - [HTTP] → GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/title {}
2016-07-14 04:12:23:815 - [MJSONWP] Calling AppiumDriver.title() with args: ["f8fe3d86-b2fd-45b3-89ca-6…
2016-07-14 04:22:23:809 - [HTTP] ← GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/title - - ms - -
2016-07-14 04:22:23:815 - [HTTP] → GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/title {}
2016-07-14 04:22:23:816 - [MJSONWP] Calling AppiumDriver.title() with args: ["f8fe3d86-b2fd-45b3-89ca-6…
2016-07-14 04:32:23:805 - [HTTP] ← GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/title - - ms - -
2016-07-14 04:32:23:811 - [HTTP] → GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/title {}
2016-07-14 04:32:23:812 - [MJSONWP] Calling AppiumDriver.title() with args: ["f8fe3d86-b2fd-45b3-89ca-6…
2016-07-14 04:42:23:804 - [HTTP] ← GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/title - - ms - -
2016-07-14 04:42:23:806 - [HTTP] → GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/title {}
2016-07-14 04:42:23:807 - [MJSONWP] Calling AppiumDriver.title() with args: ["f8fe3d86-b2fd-45b3-89ca-6…
2016-07-14 04:52:23:802 - [HTTP] ← GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/title - - ms - -
2016-07-14 04:52:23:965 - [HTTP] → GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/context {}
2016-07-14 04:52:23:965 - [MJSONWP] Calling AppiumDriver.getCurrentContext() with args: ["f8fe3d86-b2fd-45b3-89ca-6…
2016-07-14 05:02:23:962 - [HTTP] ← GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/context - - ms - -
2016-07-14 05:02:23:966 - [HTTP] → GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/context {}
2016-07-14 05:02:23:968 - [MJSONWP] Calling AppiumDriver.getCurrentContext() with args: ["f8fe3d86-b2fd-45b3-89ca-6…
2016-07-14 05:12:23:962 - [HTTP] ← GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/context - - ms - -
2016-07-14 05:12:23:965 - [HTTP] → GET /wd/hub/session/f8fe3d86-b2fd-45b3-89ca-6e1255caca19/context {}
Very strange! Can I ask if you’ve updated Xcode recently? I’ve had problems with the ‘update’ and now I just delete Xcode and then install the new version from scratch. It seems strange but somehow it makes a difference.