IOS Driver Hangs Randomly

[Joel Miele]

Every once in a while the server seems to hang up after launching the application.  This leads to a slew of "error: Failed to start an Appium session, err was: Error: Requested a new session but one was in progress" errors in the output.  I can't see a reason why the first test seemed to get stalled.  This is the output of the driver up until the first session error:

info: Instruments is at: /Applications/Xcode.app/Contents/Developer/usr/bin/instruments

info: [INSTSERVER] Instruments socket server started at /tmp/instruments_sock

info: Attempting to run app on iPhone Retina (4-inch) - Simulator - iOS 7.1

info: Spawning instruments with command: /Applications/Xcode.app/Contents/Developer/usr/bin/instruments -t /Applications/Xcode.app/Contents/Applications/Instruments.app/Contents/PlugIns/AutomationInstrument.bundle/Contents/Resources/Automation.tracetemplate -w iPhone Retina (4-inch) - Simulator - iOS 7.1 /Users/jmiele/AYI_Appium_iPhone/app/AYI.app -e UIASCRIPT /Users/jmiele/appium/node_modules/appium-uiauto/uiauto/bootstrap.js -e UIARESULTSPATH /tmp/appium-instruments

info: And extra without-delay env: {"DYLD_INSERT_LIBRARIES":"/Users/jmiele/appium/node_modules/appium-instruments/thirdparty/iwd/InstrumentsShim.dylib","LIB_PATH":"/Users/jmiele/appium/node_modules/appium-instruments/thirdparty/iwd"}

info: And launch timeouts (in ms): {"global":90000}

POST /wd/hub/session 200 60000ms

debug: Appium request initiated at /wd/hub/session

debug: Request received with params: {"desiredCapabilities":{"device":"iPhone Simulator","platform":"Mac","version":"7.1","app":"/Users/jmiele/AYI_Appium_iPhone/app/AYI.app","bundleId":"com.snap-interactive.AreYouInterested","locationServicesEnabled":true,"locationServicesAuthorized":true}}

However I've noticed that this bit is missing (this is pulled from a successful launch):

info: [INST STDERR] 2014-04-14 17:48:11.281 ScriptAgent[22998:3007] CLTilesManagerClient: initialize, sSharedTilesManagerClient

info: [INST STDERR] 2014-04-14 17:48:11.282 ScriptAgent[22998:3007] CLTilesManagerClient: init

info: [INST STDERR] 2014-04-14 17:48:11.282 ScriptAgent[22998:3007] CLTilesManagerClient: reconnecting, 0xac46db0

info: [INST] 2014-04-14 21:48:11 +0000 Start: Bootstrapping uiauto

info: [INST] 2014-04-14 21:48:11 +0000 Start: Got user: jmiele

info: [INST] 2014-04-14 21:48:11 +0000 Start: Not using settings file.

info: [INST] 2014-04-14 21:48:11 +0000 Start: isVerbose:false

info: [INST] 2014-04-14 21:48:11 +0000 Start: Using node at: /usr/local/Cellar/node/0.10.26/bin/node

info: [INSTSERVER] Instruments is ready to receive commands

info: Instruments launched. Starting poll loop for new commands.

Any idea what might be causing the hang up?  It happens pretty randomly from what I can tell.

[Jonathan Lipps]

What happens in the logs after this?

--
http://appium.io
---
You received this message because you are subscribed to the Google Groups "Appium-discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to appium-discus...@googlegroups.com.
Visit this group at http://groups.google.com/group/appium-discuss.
For more options, visit https://groups.google.com/d/optout.

[Joel Miele]

For each test in the folder it fails with "Session already in progress" and then at the end there's an error about instruments not starting.

I will get the exact output as soon as I experience it again.

[Vic Wong]

In my experience usually these occurred when I didn't tear down drivers properly after tests, or there was an app crash and the driver did not recover.

In any case, have you tried using the appium --session-override parameter? That will clobber existing sessions and allow the rest of your suite to run. Doesn't work in all situations I've found, but did seem to improve things.

-v

[Joel Miele]

This was the latest one to stall out

info: Responding to client with error: {"status":33,"value":{"message":"A new session could not be created. (Original error: Requested a new session but one was in progress)","origValue":"Requested a new session but one was in progress"},"sessionId":"d9499d26-b511-45c9-b7f9-783aa0e02f56"}

POST /wd/hub/session 500 23ms - 278b

debug: Appium request initiated at /wd/hub/session/8697551c-b693-49e7-af47-9756cafc086a

debug: Request received with params: {}

DELETE /wd/hub/session/8697551c-b693-49e7-af47-9756cafc086a 404 1ms - 53b

warn: Instruments socket client never checked in; timing out (global)

info: Killall instruments

info: [INSTSERVER] Instruments exited with code null

info: Killall instruments

info: Attempting to retry launching instruments, this is retry #1

info: Killall iPhoneSimulator

[Joel Miele]

Another example - I will try using the session-override arg.

debug: Appium request initiated at /wd/hub/session

debug: Request received with params: {"desiredCapabilities":{"device":"iPhone Simulator","deviceName":"iPad Retina - Simulator - IOS 7.1","platform":"Mac","version":"7.1","app":"/Users/jmiele/AYI_Appium_iPhone/app/AYI.app","bundleId":"com.snap-interactive.AreYouInterested","locationServicesEnabled":true,"locationServicesAuthorized":true}}

info: Using local app from desired caps: /Users/jmiele/AYI_Appium_iPhone/app/AYI.app

info: Creating new appium session cb4d8660-7c0e-4d05-b2d8-d8af181b4034

info: Removing any remaining instruments sockets

info: Cleaned up instruments socket /tmp/instruments_sock

info: Cleaning up any tracedirs

info: Cleaned up /Users/jmiele/appium/instrumentscli0.trace

info: Setting Xcode folder

info: Setting Xcode version

info: Setting iOS SDK Version

info: iOS SDK Version set to 7.1

info: Detecting automation tracetemplate

info: Not auto-detecting udid, running on sim

warn: Could not parse plist file at /Users/jmiele/AYI_Appium_iPhone/app/AYI.app/en.lproj/Localizable.strings

info: Not setting locale

debug: Creating instruments

info: Setting iOS and app preferences

info: Setting location services to 1

info: Updating settings for locationServices

info: Getting current settings for locationServices from /Users/jmiele/Library/Application Support/iPhone Simulator/7.1/Library/Preferences/com.apple.locationd.plist

info: Writing settings for locationServices to /Users/jmiele/Library/Application Support/iPhone Simulator/7.1/Library/Preferences/com.apple.locationd.plist:

info: {"LastSystemVersion":"Mac OS X10.8.5/12F45","LocationServicesEnabled":1,"ObsoleteDataDeleted":true,"LocationServicesEnabledIn7.0":1}

info: Authorizing location services for app

info: Getting current settings for locationCache from /Users/jmiele/Library/Application Support/iPhone Simulator/7.1/Library/Preferences/cache.plist

info: Getting current settings for locationCache from /Users/jmiele/Library/Application Support/iPhone Simulator/7.1/Library/Caches/locationd/cache.plist

info: Getting current settings for locationClients from /Users/jmiele/Library/Application Support/iPhone Simulator/7.1/Library/Caches/locationd/clients.plist

info: Writing settings for locationClients to /Users/jmiele/Library/Application Support/iPhone Simulator/7.1/Library/Caches/locationd/clients.plist:

info: {"com.apple.locationd.bundle-/System/Library/PrivateFrameworks/AOSNotification.framework":{"BundlePath":"/System/Library/PrivateFrameworks/AOSNotification.framework","Whitelisted":false,"Executable":"","Registered":""},"com.snap-interactive.AreYouInterested":{"BundleId":"com.snap-interactive.AreYouInterested","Authorized":true,"Whitelisted":false},"Executable":"","Registered":""}

info: Writing settings for locationCache to /Users/jmiele/Library/Application Support/iPhone Simulator/7.1/Library/Preferences/cache.plist:

info: {"LastFenceActivityTimestamp":412122103.232983,"CleanShutdown":true}

info: Writing settings for locationCache to /Users/jmiele/Library/Application Support/iPhone Simulator/7.1/Library/Caches/locationd/cache.plist:

info: {"LastFenceActivityTimestamp":412122103.232983,"CleanShutdown":false}

info: Starting iOS 7.* simulator log capture

info: Killing the simulator process

info: Killing any other simulator daemons

debug: Checking whether instruments supports our device string

info: Getting list of devices instruments supports

info: Instruments is at: /Applications/Xcode.app/Contents/Developer/usr/bin/instruments

debug: No device id or app, not installing to real device.

debug: Starting instruments

info: Instruments is at: /Applications/Xcode.app/Contents/Developer/usr/bin/instruments

info: [INSTSERVER] Instruments socket server started at /tmp/instruments_sock

info: Attempting to run app on iPad Retina - Simulator - iOS 7.1

info: Spawning instruments with command: /Applications/Xcode.app/Contents/Developer/usr/bin/instruments -t /Applications/Xcode.app/Contents/Applications/Instruments.app/Contents/PlugIns/AutomationInstrument.bundle/Contents/Resources/Automation.tracetemplate -w iPad Retina - Simulator - iOS 7.1 /Users/jmiele/AYI_Appium_iPhone/app/AYI.app -e UIASCRIPT /Users/jmiele/appium/node_modules/appium-uiauto/uiauto/bootstrap.js -e UIARESULTSPATH /tmp/appium-instruments

info: And extra without-delay env: {"DYLD_INSERT_LIBRARIES":"/Users/jmiele/appium/node_modules/appium-instruments/thirdparty/iwd/InstrumentsShim.dylib","LIB_PATH":"/Users/jmiele/appium/node_modules/appium-instruments/thirdparty/iwd"}

info: And launch timeouts (in ms): {"global":90000}

POST /wd/hub/session 200 60002ms

debug: Appium request initiated at /wd/hub/session/0e28059a-1ce4-44a6-88d5-9fcde662a810

debug: Request received with params: {}

DELETE /wd/hub/session/0e28059a-1ce4-44a6-88d5-9fcde662a810 404 1ms - 53b

debug: Appium request initiated at /wd/hub/session

debug: Request received with params: {"desiredCapabilities":{"device":"iPhone Simulator","deviceName":"iPad Retina - Simulator - IOS 7.1","platform":"Mac","version":"7.1","app":"/Users/jmiele/AYI_Appium_iPhone/app/AYI.app","bundleId":"com.snap-interactive.AreYouInterested","locationServicesEnabled":true,"locationServicesAuthorized":true}}

error: Failed to start an Appium session, err was: Error: Requested a new session but one was in progress

info: Error: Requested a new session but one was in progress

    at Appium.start (/Users/jmiele/appium/lib/appium.js:112:15)

    at exports.createSession (/Users/jmiele/appium/lib/server/controller.js:151:16)

    at callbacks (/Users/jmiele/appium/node_modules/express/lib/router/index.js:164:37)

    at param (/Users/jmiele/appium/node_modules/express/lib/router/index.js:138:11)

    at pass (/Users/jmiele/appium/node_modules/express/lib/router/index.js:145:5)

    at nextRoute (/Users/jmiele/appium/node_modules/express/lib/router/index.js:100:7)

    at callbacks (/Users/jmiele/appium/node_modules/express/lib/router/index.js:167:11)

    at /Users/jmiele/appium/lib/server/controller.js:37:7

    at callbacks (/Users/jmiele/appium/node_modules/express/lib/router/index.js:164:37)

    at param (/Users/jmiele/appium/node_modules/express/lib/router/index.js:138:11)

info: Responding to client with error: {"status":33,"value":{"message":"A new session could not be created. (Original error: Requested a new session but one was in progress)","origValue":"Requested a new session but one was in progress"},"sessionId":"cb4d8660-7c0e-4d05-b2d8-d8af181b4034"}

POST /wd/hub/session 500 8ms - 278b

debug: Appium request initiated at /wd/hub/session/0e28059a-1ce4-44a6-88d5-9fcde662a810

debug: Request received with params: {}

DELETE /wd/hub/session/0e28059a-1ce4-44a6-88d5-9fcde662a810 404 1ms - 53b

debug: Appium request initiated at /wd/hub/session

debug: Request received with params: {"desiredCapabilities":{"device":"iPhone Simulator","deviceName":"iPad Retina - Simulator - IOS 7.1","platform":"Mac","version":"7.1","app":"/Users/jmiele/AYI_Appium_iPhone/app/AYI.app","bundleId":"com.snap-interactive.AreYouInterested","locationServicesEnabled":true,"locationServicesAuthorized":true}}

error: Failed to start an Appium session, err was: Error: Requested a new session but one was in progress

info: Error: Requested a new session but one was in progress

    at Appium.start (/Users/jmiele/appium/lib/appium.js:112:15)

    at exports.createSession (/Users/jmiele/appium/lib/server/controller.js:151:16)

    at callbacks (/Users/jmiele/appium/node_modules/express/lib/router/index.js:164:37)

    at param (/Users/jmiele/appium/node_modules/express/lib/router/index.js:138:11)

    at pass (/Users/jmiele/appium/node_modules/express/lib/router/index.js:145:5)

    at nextRoute (/Users/jmiele/appium/node_modules/express/lib/router/index.js:100:7)

    at callbacks (/Users/jmiele/appium/node_modules/express/lib/router/index.js:167:11)

    at /Users/jmiele/appium/lib/server/controller.js:37:7

    at callbacks (/Users/jmiele/appium/node_modules/express/lib/router/index.js:164:37)

    at param (/Users/jmiele/appium/node_modules/express/lib/router/index.js:138:11)

info: Responding to client with error: {"status":33,"value":{"message":"A new session could not be created. (Original error: Requested a new session but one was in progress)","origValue":"Requested a new session but one was in progress"},"sessionId":"cb4d8660-7c0e-4d05-b2d8-d8af181b4034"}

POST /wd/hub/session 500 1ms - 278b

debug: Appium request initiated at /wd/hub/session/0e28059a-1ce4-44a6-88d5-9fcde662a810

debug: Request received with params: {}

DELETE /wd/hub/session/0e28059a-1ce4-44a6-88d5-9fcde662a810 404 1ms - 53b

debug: Appium request initiated at /wd/hub/session

debug: Request received with params: {"desiredCapabilities":{"device":"iPhone Simulator","deviceName":"iPad Retina - Simulator - IOS 7.1","platform":"Mac","version":"7.1","app":"/Users/jmiele/AYI_Appium_iPhone/app/AYI.app","bundleId":"com.snap-interactive.AreYouInterested","locationServicesEnabled":true,"locationServicesAuthorized":true}}

error: Failed to start an Appium session, err was: Error: Requested a new session but one was in progress

info: Error: Requested a new session but one was in progress

    at Appium.start (/Users/jmiele/appium/lib/appium.js:112:15)

    at exports.createSession (/Users/jmiele/appium/lib/server/controller.js:151:16)

    at callbacks (/Users/jmiele/appium/node_modules/express/lib/router/index.js:164:37)

    at param (/Users/jmiele/appium/node_modules/express/lib/router/index.js:138:11)

    at pass (/Users/jmiele/appium/node_modules/express/lib/router/index.js:145:5)

    at nextRoute (/Users/jmiele/appium/node_modules/express/lib/router/index.js:100:7)

    at callbacks (/Users/jmiele/appium/node_modules/express/lib/router/index.js:167:11)

    at /Users/jmiele/appium/lib/server/controller.js:37:7

    at callbacks (/Users/jmiele/appium/node_modules/express/lib/router/index.js:164:37)

    at param (/Users/jmiele/appium/node_modules/express/lib/router/index.js:138:11)

info: Responding to client with error: {"status":33,"value":{"message":"A new session could not be created. (Original error: Requested a new session but one was in progress)","origValue":"Requested a new session but one was in progress"},"sessionId":"cb4d8660-7c0e-4d05-b2d8-d8af181b4034"}

POST /wd/hub/session 500 2ms - 278b

debug: Appium request initiated at /wd/hub/session/0e28059a-1ce4-44a6-88d5-9fcde662a810

debug: Request received with params: {}

DELETE /wd/hub/session/0e28059a-1ce4-44a6-88d5-9fcde662a810 404 1ms - 53b

debug: Appium request initiated at /wd/hub/session

debug: Request received with params: {"desiredCapabilities":{"device":"iPhone Simulator","deviceName":"iPad Retina - Simulator - IOS 7.1","platform":"Mac","version":"7.1","app":"/Users/jmiele/AYI_Appium_iPhone/app/AYI.app","bundleId":"com.snap-interactive.AreYouInterested","locationServicesEnabled":true,"locationServicesAuthorized":true}}

error: Failed to start an Appium session, err was: Error: Requested a new session but one was in progress

info: Error: Requested a new session but one was in progress

    at Appium.start (/Users/jmiele/appium/lib/appium.js:112:15)

    at exports.createSession (/Users/jmiele/appium/lib/server/controller.js:151:16)

    at callbacks (/Users/jmiele/appium/node_modules/express/lib/router/index.js:164:37)

    at param (/Users/jmiele/appium/node_modules/express/lib/router/index.js:138:11)

    at pass (/Users/jmiele/appium/node_modules/express/lib/router/index.js:145:5)

    at nextRoute (/Users/jmiele/appium/node_modules/express/lib/router/index.js:100:7)

    at callbacks (/Users/jmiele/appium/node_modules/express/lib/router/index.js:167:11)

    at /Users/jmiele/appium/lib/server/controller.js:37:7

    at callbacks (/Users/jmiele/appium/node_modules/express/lib/router/index.js:164:37)

    at param (/Users/jmiele/appium/node_modules/express/lib/router/index.js:138:11)

info: Responding to client with error: {"status":33,"value":{"message":"A new session could not be created. (Original error: Requested a new session but one was in progress)","origValue":"Requested a new session but one was in progress"},"sessionId":"cb4d8660-7c0e-4d05-b2d8-d8af181b4034"}

POST /wd/hub/session 500 3ms - 278b

debug: Appium request initiated at /wd/hub/session/0e28059a-1ce4-44a6-88d5-9fcde662a810

debug: Request received with params: {}

DELETE /wd/hub/session/0e28059a-1ce4-44a6-88d5-9fcde662a810 404 0ms - 53b