HelloCordova appium switchContext hang

appium.log

2020-01-09 03:33:13:744 - [HTTP] --> POST /wd/hub/session
2020-01-09 03:33:13:744 - [HTTP] {"capabilities":{"alwaysMatch":{"platformName":"iOS","platformVersion":"13.3","app":"/var/tmp/Debug-iphonesimulator/HelloCordova.app","deviceName":"iPhone 11","newCommandTimeout":360000},"firstMatch":[{}]},"desiredCapabilities":{"platformName":"iOS","platformVersion":"13.3","app":"/var/tmp/Debug-iphonesimulator/HelloCordova.app","deviceName":"iPhone 11","newCommandTimeout":360000}}
2020-01-09 03:33:13:746 - [debug] [W3C] Calling AppiumDriver.createSession() with args: [{"platformName":"iOS","platformVersion":"13.3","app":"/var/tmp/Debug-iphonesimulator/HelloCordova.app","deviceName":"iPhone 11","newCommandTimeout":360000},null,{"alwaysMatch":{"platformName":"iOS","platformVersion":"13.3","app":"/var/tmp/Debug-iphonesimulator/HelloCordova.app","deviceName":"iPhone 11","newCommandTimeout":360000},"firstMatch":[{}]}]
2020-01-09 03:33:13:746 - [debug] [BaseDriver] Event 'newSessionRequested' logged at 1578540793746 (14:33:13 GMT+1100 (Australian Eastern Daylight Time))
2020-01-09 03:33:13:749 - [BaseDriver] The capabilities ["platformVersion","app","deviceName","newCommandTimeout"] are not standard capabilities and should have an extension prefix
2020-01-09 03:33:13:753 - [Appium] DeprecationWarning: 'automationName' capability was not provided. Future versions of Appium will require 'automationName' capability to be set for iOS sessions.
2020-01-09 03:33:13:753 - [Appium] Requested iOS support with version >= 10, using 'XCUITest' driver instead of UIAutomation-based driver, since the latter is unsupported on iOS 10 and up.
2020-01-09 03:33:14:311 - [Appium] Appium v1.16.0 creating new XCUITestDriver (v3.10.1) session
2020-01-09 03:33:14:314 - [debug] [BaseDriver] W3C capabilities and MJSONWP desired capabilities were provided
2020-01-09 03:33:14:314 - [debug] [BaseDriver] Creating session with W3C capabilities: {
2020-01-09 03:33:14:314 - [debug] [BaseDriver]   "alwaysMatch": {
2020-01-09 03:33:14:314 - [debug] [BaseDriver]     "platformName": "iOS",
2020-01-09 03:33:14:315 - [debug] [BaseDriver]     "appium:platformVersion": "13.3",
2020-01-09 03:33:14:315 - [debug] [BaseDriver]     "appium:app": "/var/tmp/Debug-iphonesimulator/HelloCordova.app",
2020-01-09 03:33:14:315 - [debug] [BaseDriver]     "appium:deviceName": "iPhone 11",
2020-01-09 03:33:14:315 - [debug] [BaseDriver]     "appium:newCommandTimeout": 360000
2020-01-09 03:33:14:315 - [debug] [BaseDriver]   },
2020-01-09 03:33:14:315 - [debug] [BaseDriver]   "firstMatch": [
2020-01-09 03:33:14:315 - [debug] [BaseDriver]     {}
2020-01-09 03:33:14:315 - [debug] [BaseDriver]   ]
2020-01-09 03:33:14:315 - [debug] [BaseDriver] }
2020-01-09 03:33:14:323 - [BaseDriver] Session created with session id: 15c1c929-ecb5-46a1-a08e-23175d92a138
2020-01-09 03:33:14:340 - [debug] [XCUITest] Current user: 'mdonnellon'
2020-01-09 03:33:14:414 - [XCUITest] iOS SDK Version set to '13.2'
2020-01-09 03:33:14:670 - [iOSSim] Constructing iOS simulator for Xcode version 11.3 with udid 'C20E708A-651B-4895-AE76-E7578D3BB0D6'
2020-01-09 03:33:14:670 - [XCUITest] Determining device to run tests on: udid: 'C20E708A-651B-4895-AE76-E7578D3BB0D6', real device: false
2020-01-09 03:33:14:671 - [debug] [BaseDriver] Event 'xcodeDetailsRetrieved' logged at 1578540794671 (14:33:14 GMT+1100 (Australian Eastern Daylight Time))
2020-01-09 03:33:14:673 - [BaseDriver] Using local app '/var/tmp/Debug-iphonesimulator/HelloCordova.app'
2020-01-09 03:33:14:675 - [debug] [BaseDriver] Event 'appConfigured' logged at 1578540794675 (14:33:14 GMT+1100 (Australian Eastern Daylight Time))
2020-01-09 03:33:14:675 - [debug] [XCUITest] Checking whether app '/var/tmp/Debug-iphonesimulator/HelloCordova.app' is actually present on file system
2020-01-09 03:33:14:675 - [debug] [XCUITest] App is present
2020-01-09 03:33:14:677 - [debug] [iOS] Getting bundle ID from app '/var/tmp/Debug-iphonesimulator/HelloCordova.app': 'com.example.cordova'
2020-01-09 03:33:14:678 - [debug] [BaseDriver] Event 'resetStarted' logged at 1578540794678 (14:33:14 GMT+1100 (Australian Eastern Daylight Time))
2020-01-09 03:33:14:923 - [XCUITest] Not scrubbing third party app in anticipation of uninstall
2020-01-09 03:33:14:923 - [debug] [BaseDriver] Event 'resetComplete' logged at 1578540794923 (14:33:14 GMT+1100 (Australian Eastern Daylight Time))
2020-01-09 03:33:15:066 - [debug] [IOSSimulatorLog] Starting log capture for iOS Simulator with udid 'C20E708A-651B-4895-AE76-E7578D3BB0D6', using 'xcrun simctl spawn C20E708A-651B-4895-AE76-E7578D3BB0D6 log stream --style compact'
2020-01-09 03:33:15:409 - [debug] [BaseDriver] Event 'logCaptureStarted' logged at 1578540795409 (14:33:15 GMT+1100 (Australian Eastern Daylight Time))
2020-01-09 03:33:15:409 - [XCUITest] Setting up simulator
2020-01-09 03:33:15:410 - [debug] [iOS] No reason to set locale
2020-01-09 03:33:15:410 - [debug] [iOS] No iOS / app preferences to set
2020-01-09 03:33:15:410 - [debug] [iOS] Setting did not need to be updated
2020-01-09 03:33:15:411 - [debug] [iOSSim] Setting preferences of C20E708A-651B-4895-AE76-E7578D3BB0D6 Simulator to {"ConnectHardwareKeyboard":false}
2020-01-09 03:33:15:411 - [debug] [iOSSim] Setting common Simulator preferences to {"RotateWindowWhenSignaledByGuest":true,"ConnectHardwareKeyboard":false}
2020-01-09 03:33:15:431 - [debug] [iOSSim] Updated C20E708A-651B-4895-AE76-E7578D3BB0D6 Simulator preferences at '/Users/mdonnellon/Library/Preferences/com.apple.iphonesimulator.plist' with {"DevicePreferences":{"C20E708A-651B-4895-AE76-E7578D3BB0D6":{"ConnectHardwareKeyboard":false}},"RotateWindowWhenSignaledByGuest":true,"ConnectHardwareKeyboard":false}
2020-01-09 03:33:15:599 - [debug] [iOSSim] Got Simulator UI client PID: 427
2020-01-09 03:33:15:599 - [iOSSim] Both Simulator with UDID C20E708A-651B-4895-AE76-E7578D3BB0D6 and the UI client are currently running
2020-01-09 03:33:15:599 - [debug] [BaseDriver] Event 'simStarted' logged at 1578540795599 (14:33:15 GMT+1100 (Australian Eastern Daylight Time))
2020-01-09 03:33:15:601 - [debug] [XCUITest] Verifying application platform
2020-01-09 03:33:15:603 - [debug] [XCUITest] CFBundleSupportedPlatforms: ["iPhoneSimulator"]
2020-01-09 03:33:15:720 - [debug] [XCUITest] Reset requested. Removing app with id 'com.example.cordova' from the device
2020-01-09 03:33:16:867 - [debug] [XCUITest] Installing '/var/tmp/Debug-iphonesimulator/HelloCordova.app' on Simulator with UUID 'C20E708A-651B-4895-AE76-E7578D3BB0D6'...
2020-01-09 03:33:18:275 - [debug] [XCUITest] The app has been installed successfully.
2020-01-09 03:33:18:276 - [debug] [BaseDriver] Event 'appInstalled' logged at 1578540798276 (14:33:18 GMT+1100 (Australian Eastern Daylight Time))
2020-01-09 03:33:18:277 - [XCUITest] Using WDA path: '/Users/mdonnellon/.nvm/versions/node/v10.17.0/lib/node_modules/appium/node_modules/appium-xcuitest-driver/node_modules/appium-webdriveragent'
2020-01-09 03:33:18:277 - [XCUITest] Using WDA agent: '/Users/mdonnellon/.nvm/versions/node/v10.17.0/lib/node_modules/appium/node_modules/appium-xcuitest-driver/node_modules/appium-webdriveragent/WebDriverAgent.xcodeproj'
2020-01-09 03:33:18:408 - [debug] [XCUITest] No obsolete cached processes from previous WDA sessions listening on port 8100 have been found
2020-01-09 03:33:18:408 - [DevCon Factory] Requesting connection for device C20E708A-651B-4895-AE76-E7578D3BB0D6 on local port 8100, device port 8100
2020-01-09 03:33:18:408 - [debug] [DevCon Factory] Cached connections count: 0
2020-01-09 03:33:18:408 - [DevCon Factory] Successfully requested the connection for C20E708A-651B-4895-AE76-E7578D3BB0D6:8100
2020-01-09 03:33:18:409 - [debug] [XCUITest] Starting WebDriverAgent initialization with the synchronization key 'XCUITestDriver'
2020-01-09 03:33:18:411 - [debug] [WD Proxy] Matched '/status' to command name 'getStatus'
2020-01-09 03:33:18:412 - [debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
2020-01-09 03:33:18:425 - [debug] [WD Proxy] Got response with status 200: {
2020-01-09 03:33:18:425 - [debug] [WD Proxy]   "value" : {
2020-01-09 03:33:18:425 - [debug] [WD Proxy]     "message" : "WebDriverAgent is ready to accept commands",
2020-01-09 03:33:18:425 - [debug] [WD Proxy]     "state" : "success",
2020-01-09 03:33:18:426 - [debug] [WD Proxy]     "os" : {
2020-01-09 03:33:18:426 - [debug] [WD Proxy]       "name" : "iOS",
2020-01-09 03:33:18:426 - [debug] [WD Proxy]       "version" : "13.3",
2020-01-09 03:33:18:426 - [debug] [WD Proxy]       "sdkVersion" : "13.0"
2020-01-09 03:33:18:426 - [debug] [WD Proxy]     },
2020-01-09 03:33:18:426 - [debug] [WD Proxy]     "ios" : {
2020-01-09 03:33:18:426 - [debug] [WD Proxy]       "simulatorVersion" : "13.3",
2020-01-09 03:33:18:426 - [debug] [WD Proxy]       "ip" : "192.168.16.194"
2020-01-09 03:33:18:426 - [debug] [WD Proxy]     },
2020-01-09 03:33:18:426 - [debug] [WD Proxy]     "ready" : true,
2020-01-09 03:33:18:426 - [debug] [WD Proxy]     "build" : {
2020-01-09 03:33:18:426 - [debug] [WD Proxy]       "upgradedAt" : "1578444897345",
2020-01-09 03:33:18:427 - [debug] [WD Proxy]       "time" : "Jan  9 2020 09:25:16",
2020-01-09 03:33:18:427 - [debug] [WD Proxy]       "productBundleIdentifier" : "com.facebook.WebDriverAgentRunner"
2020-01-09 03:33:18:427 - [debug] [WD Proxy]     }
2020-01-09 03:33:18:427 - [debug] [WD Proxy]   },
2020-01-09 03:33:18:427 - [debug] [WD Proxy]   "sessionId" : "001790C0-138E-4D60-9B86-EB944100B695"
2020-01-09 03:33:18:427 - [debug] [WD Proxy] }
2020-01-09 03:33:18:428 - [debug] [XCUITest] Upgrade timestamp of the currently bundled WDA: 1578444897345
2020-01-09 03:33:18:428 - [debug] [XCUITest] Upgrade timestamp of the WDA on the device: 1578444897345
2020-01-09 03:33:18:429 - [XCUITest] Will reuse previously cached WDA instance at 'http://localhost:8100/' with 'com.facebook.WebDriverAgentRunner'. Set the wdaLocalPort capability to a value different from 8100 if this is an undesired behavior.
2020-01-09 03:33:18:429 - [debug] [XCUITest] Trying to start WebDriverAgent 2 times with 10000ms interval
2020-01-09 03:33:18:429 - [debug] [XCUITest] These values can be customized by changing wdaStartupRetries/wdaStartupRetryInterval capabilities
2020-01-09 03:33:18:429 - [debug] [BaseDriver] Event 'wdaStartAttempted' logged at 1578540798429 (14:33:18 GMT+1100 (Australian Eastern Daylight Time))
2020-01-09 03:33:18:429 - [XCUITest] Using provided WebdriverAgent at 'http://localhost:8100/'
2020-01-09 03:33:18:430 - [debug] [WD Proxy] Matched '/status' to command name 'getStatus'
2020-01-09 03:33:18:430 - [debug] [WD Proxy] Proxying [GET /status] to [GET http://localhost:8100/status] with no body
2020-01-09 03:33:18:434 - [debug] [WD Proxy] Got response with status 200: {
2020-01-09 03:33:18:434 - [debug] [WD Proxy]   "value" : {
2020-01-09 03:33:18:434 - [debug] [WD Proxy]     "message" : "WebDriverAgent is ready to accept commands",
2020-01-09 03:33:18:434 - [debug] [WD Proxy]     "state" : "success",
2020-01-09 03:33:18:434 - [debug] [WD Proxy]     "os" : {
2020-01-09 03:33:18:434 - [debug] [WD Proxy]       "name" : "iOS",
2020-01-09 03:33:18:434 - [debug] [WD Proxy]       "version" : "13.3",
2020-01-09 03:33:18:435 - [debug] [WD Proxy]       "sdkVersion" : "13.0"
2020-01-09 03:33:18:435 - [debug] [WD Proxy]     },
2020-01-09 03:33:18:435 - [debug] [WD Proxy]     "ios" : {
2020-01-09 03:33:18:435 - [debug] [WD Proxy]       "simulatorVersion" : "13.3",
2020-01-09 03:33:18:435 - [debug] [WD Proxy]       "ip" : "192.168.16.194"
2020-01-09 03:33:18:435 - [debug] [WD Proxy]     },
2020-01-09 03:33:18:435 - [debug] [WD Proxy]     "ready" : true,
2020-01-09 03:33:18:435 - [debug] [WD Proxy]     "build" : {
2020-01-09 03:33:18:435 - [debug] [WD Proxy]       "upgradedAt" : "1578444897345",
2020-01-09 03:33:18:435 - [debug] [WD Proxy]       "time" : "Jan  9 2020 09:25:16",
2020-01-09 03:33:18:436 - [debug] [WD Proxy]       "productBundleIdentifier" : "com.facebook.WebDriverAgentRunner"
2020-01-09 03:33:18:436 - [debug] [WD Proxy]     }
2020-01-09 03:33:18:436 - [debug] [WD Proxy]   },
2020-01-09 03:33:18:436 - [debug] [WD Proxy]   "sessionId" : "001790C0-138E-4D60-9B86-EB944100B695"
2020-01-09 03:33:18:436 - [debug] [WD Proxy] }
2020-01-09 03:33:18:436 - [debug] [BaseDriver] Event 'wdaSessionAttempted' logged at 1578540798436 (14:33:18 GMT+1100 (Australian Eastern Daylight Time))
2020-01-09 03:33:18:437 - [debug] [XCUITest] Sending createSession command to WDA
2020-01-09 03:33:18:438 - [debug] [WD Proxy] Matched '/session' to command name 'createSession'
2020-01-09 03:33:18:438 - [debug] [WD Proxy] Proxying [POST /session] to [POST http://localhost:8100/session] with body: {"capabilities":{"firstMatch":[{"bundleId":"com.example.cordova","arguments":[],"environment":{},"eventloopIdleDelaySec":0,"shouldWaitForQuiescence":true,"shouldUseTestManagerForVisibilityDetection":false,"maxTypingFrequency":60,"shouldUseSingletonTestManager":true}],"alwaysMatch":{}}}
2020-01-09 03:33:30:692 - [debug] [WD Proxy] Got response with status 200: {"value":{"sessionId":"0AFCC4D8-6F65-453C-987C-84990C29C58F","capabilities":{"device":"iphone","browserName":"HelloCordova","sdkVersion":"13.3","CFBundleIdentifier":"com.example.cordova"}},"sessionId":"0AFCC4D8-6F65-453C-987C-84990C29C58F"}
2020-01-09 03:33:30:693 - [WD Proxy] Determined the downstream protocol as 'W3C'
2020-01-09 03:33:30:693 - [debug] [BaseDriver] Event 'wdaSessionStarted' logged at 1578540810693 (14:33:30 GMT+1100 (Australian Eastern Daylight Time))
2020-01-09 03:33:30:693 - [debug] [BaseDriver] Event 'wdaStarted' logged at 1578540810693 (14:33:30 GMT+1100 (Australian Eastern Daylight Time))
2020-01-09 03:33:30:693 - [XCUITest] Skipping setting of the initial display orientation. Set the "orientation" capability to either "LANDSCAPE" or "PORTRAIT", if this is an undesired behavior.
2020-01-09 03:33:30:694 - [debug] [BaseDriver] Event 'orientationSet' logged at 1578540810693 (14:33:30 GMT+1100 (Australian Eastern Daylight Time))
2020-01-09 03:33:30:694 - [Appium] New XCUITestDriver session created successfully, session 15c1c929-ecb5-46a1-a08e-23175d92a138 added to master session list
2020-01-09 03:33:30:695 - [debug] [BaseDriver] Event 'newSessionStarted' logged at 1578540810695 (14:33:30 GMT+1100 (Australian Eastern Daylight Time))
2020-01-09 03:33:30:696 - [debug] [W3C (15c1c929)] Cached the protocol value 'W3C' for the new session 15c1c929-ecb5-46a1-a08e-23175d92a138
2020-01-09 03:33:30:696 - [debug] [W3C (15c1c929)] Responding to client with driver.createSession() result: {"capabilities":{"webStorageEnabled":false,"locationContextEnabled":false,"browserName":"","platform":"MAC","javascriptEnabled":true,"databaseEnabled":false,"takesScreenshot":true,"networkConnectionEnabled":false,"platformName":"iOS","platformVersion":"13.3","app":"/var/tmp/Debug-iphonesimulator/HelloCordova.app","deviceName":"iPhone 11","newCommandTimeout":360000,"udid":"C20E708A-651B-4895-AE76-E7578D3BB0D6"}}
2020-01-09 03:33:30:699 - [HTTP] <-- POST /wd/hub/session 200 16954 ms - 475
2020-01-09 03:33:30:699 - [HTTP] 
2020-01-09 03:33:32:338 - [HTTP] --> GET /wd/hub/session/15c1c929-ecb5-46a1-a08e-23175d92a138/contexts
2020-01-09 03:33:32:338 - [HTTP] {}
2020-01-09 03:33:32:345 - [debug] [W3C (15c1c929)] Calling AppiumDriver.getContexts() with args: ["15c1c929-ecb5-46a1-a08e-23175d92a138"]
2020-01-09 03:33:32:345 - [debug] [XCUITest] Executing command 'getContexts'
2020-01-09 03:33:32:346 - [debug] [iOS] Getting list of available contexts
2020-01-09 03:33:32:346 - [debug] [iOS] Retrieving contexts and views
2020-01-09 03:33:32:346 - [debug] [XCUITest] Selecting by url: false 
2020-01-09 03:33:32:391 - [RemoteDebugger] Remote Debugger version 7.3.1
2020-01-09 03:33:32:392 - [debug] [RemoteDebugger] useNewSafari --> false
2020-01-09 03:33:32:393 - [debug] [RemoteDebugger] Checking which communication style to use (non-Safari on platform version '13.3')
2020-01-09 03:33:32:393 - [debug] [RemoteDebugger] Platform version equal or higher than '12.2': true
2020-01-09 03:33:32:394 - [RemoteDebugger] Setting communication protocol: using full Web Inspector protocol communication
2020-01-09 03:33:32:394 - [debug] [RemoteDebugger] Connecting to remote debugger through unix domain socket: '/private/tmp/com.apple.launchd.mqUUTxlAOr/com.apple.webinspectord_sim.socket'
2020-01-09 03:33:32:400 - [debug] [RemoteDebugger] Debugger socket connected
2020-01-09 03:33:32:400 - [debug] [RemoteDebugger] Sending connection key request
2020-01-09 03:33:32:402 - [debug] [RemoteDebugger] Sending '_rpc_reportIdentifier:' message (id: 0)
2020-01-09 03:33:32:411 - [debug] [RemoteDebugger] Sending to Web Inspector took 10ms
2020-01-09 03:33:32:411 - [debug] [RemoteDebugger] Sending connection key request
2020-01-09 03:33:32:411 - [debug] [RemoteDebugger] Sending '_rpc_reportIdentifier:' message (id: 1)
2020-01-09 03:33:32:416 - [debug] [RemoteDebugger] Sending to Web Inspector took 5ms
2020-01-09 03:33:32:417 - [debug] [RemoteDebugger] Selecting application
2020-01-09 03:33:32:417 - [debug] [RemoteDebugger] No applications currently connected.
2020-01-09 03:33:32:417 - [debug] [XCUITest] No web frames found.
2020-01-09 03:33:32:419 - [debug] [W3C (15c1c929)] Responding to client with driver.getContexts() result: ["NATIVE_APP"]
2020-01-09 03:33:32:420 - [HTTP] <-- GET /wd/hub/session/15c1c929-ecb5-46a1-a08e-23175d92a138/contexts 200 82 ms - 24
2020-01-09 03:33:32:420 - [HTTP] 
2020-01-09 03:33:32:456 - [debug] [RemoteDebugger] Received connected applications list: PID:43515, PID:35007, PID:35004, PID:43518
2020-01-09 03:33:32:457 - [debug] [RemoteDebugger] Received connected driver list: {}
2020-01-09 03:33:33:430 - [HTTP] --> GET /wd/hub/session/15c1c929-ecb5-46a1-a08e-23175d92a138/contexts
2020-01-09 03:33:33:430 - [HTTP] {}
2020-01-09 03:33:33:431 - [debug] [W3C (15c1c929)] Calling AppiumDriver.getContexts() with args: ["15c1c929-ecb5-46a1-a08e-23175d92a138"]
2020-01-09 03:33:33:431 - [debug] [XCUITest] Executing command 'getContexts'
2020-01-09 03:33:33:431 - [debug] [iOS] Getting list of available contexts
2020-01-09 03:33:33:431 - [debug] [iOS] Retrieving contexts and views
2020-01-09 03:33:33:431 - [debug] [XCUITest] Selecting by url: false 
2020-01-09 03:33:33:431 - [debug] [RemoteDebugger] Sending connection key request
2020-01-09 03:33:33:432 - [debug] [RemoteDebugger] Sending '_rpc_reportIdentifier:' message (id: 2)
2020-01-09 03:33:33:435 - [debug] [RemoteDebugger] Sending to Web Inspector took 3ms
2020-01-09 03:33:33:435 - [debug] [RemoteDebugger] Selecting application
2020-01-09 03:33:33:436 - [debug] [RemoteDebugger] Current applications available:
2020-01-09 03:33:33:436 - [debug] [RemoteDebugger]     Application: 'PID:43515'
2020-01-09 03:33:33:436 - [debug] [RemoteDebugger]         id: "PID:43515"
2020-01-09 03:33:33:437 - [debug] [RemoteDebugger]         isProxy: false
2020-01-09 03:33:33:437 - [debug] [RemoteDebugger]         name: "HelloCordova"
2020-01-09 03:33:33:437 - [debug] [RemoteDebugger]         bundleId: "com.example.cordova"
2020-01-09 03:33:33:437 - [debug] [RemoteDebugger]         hostId: undefined
2020-01-09 03:33:33:437 - [debug] [RemoteDebugger]         isActive: 2
2020-01-09 03:33:33:437 - [debug] [RemoteDebugger]         isAutomationEnabled: "Unknown"
2020-01-09 03:33:33:437 - [debug] [RemoteDebugger]     Application: 'PID:35007'
2020-01-09 03:33:33:438 - [debug] [RemoteDebugger]         id: "PID:35007"
2020-01-09 03:33:33:438 - [debug] [RemoteDebugger]         isProxy: true
2020-01-09 03:33:33:438 - [debug] [RemoteDebugger]         name: "com.apple.WebKit.WebContent"
2020-01-09 03:33:33:438 - [debug] [RemoteDebugger]         bundleId: "process-com.apple.WebKit.WebContent"
2020-01-09 03:33:33:438 - [debug] [RemoteDebugger]         hostId: "PID:35004"
2020-01-09 03:33:33:438 - [debug] [RemoteDebugger]         isActive: 0
2020-01-09 03:33:33:438 - [debug] [RemoteDebugger]         isAutomationEnabled: "Unknown"
2020-01-09 03:33:33:439 - [debug] [RemoteDebugger]     Application: 'PID:35004'
2020-01-09 03:33:33:439 - [debug] [RemoteDebugger]         id: "PID:35004"
2020-01-09 03:33:33:439 - [debug] [RemoteDebugger]         isProxy: false
2020-01-09 03:33:33:439 - [debug] [RemoteDebugger]         name: "Kudos Boards"
2020-01-09 03:33:33:439 - [debug] [RemoteDebugger]         bundleId: "com.kudosboards.pwa"
2020-01-09 03:33:33:439 - [debug] [RemoteDebugger]         hostId: undefined
2020-01-09 03:33:33:439 - [debug] [RemoteDebugger]         isActive: 0
2020-01-09 03:33:33:440 - [debug] [RemoteDebugger]         isAutomationEnabled: "Unknown"
2020-01-09 03:33:33:440 - [debug] [RemoteDebugger]     Application: 'PID:43518'
2020-01-09 03:33:33:440 - [debug] [RemoteDebugger]         id: "PID:43518"
2020-01-09 03:33:33:440 - [debug] [RemoteDebugger]         isProxy: true
2020-01-09 03:33:33:440 - [debug] [RemoteDebugger]         name: "com.apple.WebKit.WebContent"
2020-01-09 03:33:33:440 - [debug] [RemoteDebugger]         bundleId: "process-com.apple.WebKit.WebContent"
2020-01-09 03:33:33:440 - [debug] [RemoteDebugger]         hostId: "PID:43515"
2020-01-09 03:33:33:440 - [debug] [RemoteDebugger]         isActive: 2
2020-01-09 03:33:33:441 - [debug] [RemoteDebugger]         isAutomationEnabled: "Unknown"
2020-01-09 03:33:33:441 - [debug] [RemoteDebugger] Checking for bundle identifiers: com.example.cordova, *
2020-01-09 03:33:33:441 - [debug] [RemoteDebugger] Found app id key 'PID:43515' for bundle 'com.example.cordova'
2020-01-09 03:33:33:442 - [debug] [RemoteDebugger] Found separate bundleId 'process-com.apple.WebKit.WebContent' acting as proxy for 'com.example.cordova', with app id 'PID:43518'
2020-01-09 03:33:33:442 - [debug] [RemoteDebugger] Found app id key 'PID:35007' for bundle '*'
2020-01-09 03:33:33:442 - [debug] [RemoteDebugger] Trying out the possible app ids: PID:43515, PID:43518, PID:35007 (try #1 of 20)
2020-01-09 03:33:33:442 - [debug] [RemoteDebugger] Attempting app 'PID:43515'
2020-01-09 03:33:33:443 - [debug] [RemoteDebugger] Sending '_rpc_forwardGetListing:' message to app 'PID:43515' (id: 3)
2020-01-09 03:33:33:451 - [debug] [RemoteDebugger] Received response from send (id: 3): '["PID:43515",{"2":{"WIRTitleKey":"","WIRTypeKey":"WIRTypeWeb","WIRURLKey":"file:///Users/mdonnellon/Library/Developer/CoreSimulator/Devices/C20E708A-651B-4895-AE76-E7578D3BB0D6/data/Containers/Bund...'
2020-01-09 03:33:33:452 - [debug] [RemoteDebugger] Page changed: {
2020-01-09 03:33:33:453 - [debug] [RemoteDebugger]   "2": {
2020-01-09 03:33:33:453 - [debug] [RemoteDebugger]     "WIRTitleKey": "",
2020-01-09 03:33:33:453 - [debug] [RemoteDebugger]     "WIRTypeKey": "WIRTypeWeb",
2020-01-09 03:33:33:453 - [debug] [RemoteDebugger]     "WIRURLKey": "file:///Users/mdonnellon/Library/Developer/CoreSimulator/Devices/C20E708A-651B-4895-AE76-E7578D3BB0D6/data/Containers/Bundle/Application/C9F1EB5C-4313-4109-9AC2-4F756D1C86EF/HelloCordova.app/www/index.html",
2020-01-09 03:33:33:453 - [debug] [RemoteDebugger]     "WIRPageIdentifierKey": 2
2020-01-09 03:33:33:453 - [debug] [RemoteDebugger]   }
2020-01-09 03:33:33:453 - [debug] [RemoteDebugger] }
2020-01-09 03:33:33:454 - [debug] [XCUITest] Remote debugger notified us of a new page listing: {"appIdKey":"43515","pageArray":[{"id":2,"title":"","url":"file:///Users/mdonnellon/Library/Developer/CoreSimulator/Devices/C20E708A-651B-4895-AE76-E7578D3BB0D6/data/Containers/Bundle/Application/C9F1EB5C-4313-4109-9AC2-4F756D1C86EF/HelloCordova.app/www/index.html","isKey":false}]}
2020-01-09 03:33:33:455 - [debug] [XCUITest] No key id found. Choosing first id from page array
2020-01-09 03:33:33:455 - [debug] [XCUITest] We do not appear to have window set yet, ignoring
2020-01-09 03:33:33:455 - [debug] [RemoteDebugger] Sending to Web Inspector took 12ms
2020-01-09 03:33:33:456 - [debug] [RemoteDebugger] Received altered app id, updating from 'null' to 'PID:43515'
2020-01-09 03:33:33:456 - [debug] [RemoteDebugger] Current applications available:
2020-01-09 03:33:33:456 - [debug] [RemoteDebugger]     Application: 'PID:43515'
2020-01-09 03:33:33:456 - [debug] [RemoteDebugger]         id: "PID:43515"
2020-01-09 03:33:33:456 - [debug] [RemoteDebugger]         isProxy: false
2020-01-09 03:33:33:457 - [debug] [RemoteDebugger]         name: "HelloCordova"
2020-01-09 03:33:33:457 - [debug] [RemoteDebugger]         bundleId: "com.example.cordova"
2020-01-09 03:33:33:457 - [debug] [RemoteDebugger]         hostId: undefined
2020-01-09 03:33:33:457 - [debug] [RemoteDebugger]         isActive: 2
2020-01-09 03:33:33:457 - [debug] [RemoteDebugger]         isAutomationEnabled: "Unknown"
2020-01-09 03:33:33:457 - [debug] [RemoteDebugger]         pageArray:
2020-01-09 03:33:33:457 - [debug] [RemoteDebugger]           - id: 2
2020-01-09 03:33:33:458 - [debug] [RemoteDebugger]             title: ""
2020-01-09 03:33:33:458 - [debug] [RemoteDebugger]             url: "file:///Users/mdonnellon/Library/Developer/CoreSimulator/Devices/C20E708A-651B-4895-AE76-E7578D3BB0D6/data/Containers/Bundle/Application/C9F1EB5C-4313-4109-9AC2-4F756D1C86EF/HelloCordova.app/www/index.html"
2020-01-09 03:33:33:458 - [debug] [RemoteDebugger]             isKey: false
2020-01-09 03:33:33:458 - [debug] [RemoteDebugger]     Application: 'PID:35007'
2020-01-09 03:33:33:458 - [debug] [RemoteDebugger]         id: "PID:35007"
2020-01-09 03:33:33:458 - [debug] [RemoteDebugger]         isProxy: true
2020-01-09 03:33:33:458 - [debug] [RemoteDebugger]         name: "com.apple.WebKit.WebContent"
2020-01-09 03:33:33:458 - [debug] [RemoteDebugger]         bundleId: "process-com.apple.WebKit.WebContent"
2020-01-09 03:33:33:459 - [debug] [RemoteDebugger]         hostId: "PID:35004"
2020-01-09 03:33:33:459 - [debug] [RemoteDebugger]         isActive: 0
2020-01-09 03:33:33:459 - [debug] [RemoteDebugger]         isAutomationEnabled: "Unknown"
2020-01-09 03:33:33:459 - [debug] [RemoteDebugger]     Application: 'PID:35004'
2020-01-09 03:33:33:459 - [debug] [RemoteDebugger]         id: "PID:35004"
2020-01-09 03:33:33:459 - [debug] [RemoteDebugger]         isProxy: false
2020-01-09 03:33:33:459 - [debug] [RemoteDebugger]         name: "Kudos Boards"
2020-01-09 03:33:33:459 - [debug] [RemoteDebugger]         bundleId: "com.kudosboards.pwa"
2020-01-09 03:33:33:459 - [debug] [RemoteDebugger]         hostId: undefined
2020-01-09 03:33:33:460 - [debug] [RemoteDebugger]         isActive: 0
2020-01-09 03:33:33:460 - [debug] [RemoteDebugger]         isAutomationEnabled: "Unknown"
2020-01-09 03:33:33:460 - [debug] [RemoteDebugger]     Application: 'PID:43518'
2020-01-09 03:33:33:460 - [debug] [RemoteDebugger]         id: "PID:43518"
2020-01-09 03:33:33:460 - [debug] [RemoteDebugger]         isProxy: true
2020-01-09 03:33:33:460 - [debug] [RemoteDebugger]         name: "com.apple.WebKit.WebContent"
2020-01-09 03:33:33:460 - [debug] [RemoteDebugger]         bundleId: "process-com.apple.WebKit.WebContent"
2020-01-09 03:33:33:460 - [debug] [RemoteDebugger]         hostId: "PID:43515"
2020-01-09 03:33:33:460 - [debug] [RemoteDebugger]         isActive: 2
2020-01-09 03:33:33:461 - [debug] [RemoteDebugger]         isAutomationEnabled: "Unknown"
2020-01-09 03:33:33:461 - [debug] [RemoteDebugger] Finally selecting app PID:43515: [{"id":2,"title":"","url":"file:///Users/mdonnellon/Library/Developer/CoreSimulator/Devices/C20E708A-651B-4895-AE76-E7578D3BB0D6/data/Containers/Bundle/Application/C9F1EB5C-4313-4109-9AC2-4F756D1C86EF/HelloCordova.app/www/index.html","isKey":false}]
2020-01-09 03:33:33:461 - [debug] [RemoteDebugger] Selected app after 25ms
2020-01-09 03:33:33:461 - [debug] [W3C (15c1c929)] Responding to client with driver.getContexts() result: ["NATIVE_APP","WEBVIEW_43515.2"]
2020-01-09 03:33:33:462 - [HTTP] <-- GET /wd/hub/session/15c1c929-ecb5-46a1-a08e-23175d92a138/contexts 200 32 ms - 42
2020-01-09 03:33:33:462 - [HTTP] 
2020-01-09 03:33:33:465 - [HTTP] --> POST /wd/hub/session/15c1c929-ecb5-46a1-a08e-23175d92a138/context
2020-01-09 03:33:33:466 - [HTTP] {"name":"WEBVIEW_43515.2"}
2020-01-09 03:33:33:466 - [debug] [W3C (15c1c929)] Calling AppiumDriver.setContext() with args: ["WEBVIEW_43515.2","15c1c929-ecb5-46a1-a08e-23175d92a138"]
2020-01-09 03:33:33:466 - [debug] [XCUITest] Executing command 'setContext'
2020-01-09 03:33:33:467 - [debug] [XCUITest] Attempting to set context to 'WEBVIEW_43515.2' from 'NATIVE_APP'
2020-01-09 03:33:33:468 - [debug] [RemoteDebugger] Selecting page '2' on app 'PID:43515' and forwarding socket setup
2020-01-09 03:33:33:468 - [debug] [RemoteDebugger] Sending '_rpc_forwardSocketSetup:' message to app 'PID:43515', page '2' (id: 4)
2020-01-09 03:33:33:475 - [debug] [RemoteDebugger] Sending to Web Inspector took 6ms
2020-01-09 03:33:33:475 - [debug] [RemoteDebugger] Sender key set
2020-01-09 03:33:33:476 - [debug] [RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:43515', page '2' (id: 5)
2020-01-09 03:33:33:497 - [debug] [RemoteDebugger] Target created for app 'PID:43515' and page '2': {"targetId":"page-12","type":"page"}
2020-01-09 03:33:33:527 - [RemoteDebugger] Setting communication protocol: using Target-based communication
2020-01-09 03:33:33:527 - [debug] [RemoteDebugger] Sending '_rpc_forwardSocketData:' message to app 'PID:43515', page '2', target 'page-12' (id: 7)
2020-01-09 03:33:33:708 - [debug] [RemoteDebugger] Page changed: {
2020-01-09 03:33:33:708 - [debug] [RemoteDebugger]   "2": {
2020-01-09 03:33:33:709 - [debug] [RemoteDebugger]     "WIRTitleKey": "",
2020-01-09 03:33:33:709 - [debug] [RemoteDebugger]     "WIRTypeKey": "WIRTypeWeb",
2020-01-09 03:33:33:709 - [debug] [RemoteDebugger]     "WIRURLKey": "file:///Users/mdonnellon/Library/Developer/CoreSimulator/Devices/C20E708A-651B-4895-AE76-E7578D3BB0D6/data/Containers/Bundle/Application/C9F1EB5C-4313-4109-9AC2-4F756D1C86EF/HelloCordova.app/www/index.html",
2020-01-09 03:33:33:709 - [debug] [RemoteDebugger]     "WIRPageIdentifierKey": 2,
2020-01-09 03:33:33:709 - [debug] [RemoteDebugger]     "WIRConnectionIdentifierKey": "23214f31-6914-4f7b-92aa-4d7c41648dcb"
2020-01-09 03:33:33:709 - [debug] [RemoteDebugger]   }
2020-01-09 03:33:33:709 - [debug] [RemoteDebugger] }
2020-01-09 03:33:33:709 - [debug] [XCUITest] Remote debugger notified us of a new page listing: {"appIdKey":"43515","pageArray":[{"id":2,"title":"","url":"file:///Users/mdonnellon/Library/Developer/CoreSimulator/Devices/C20E708A-651B-4895-AE76-E7578D3BB0D6/data/Containers/Bundle/Application/C9F1EB5C-4313-4109-9AC2-4F756D1C86EF/HelloCordova.app/www/index.html","isKey":true}]}
2020-01-09 03:33:33:709 - [debug] [XCUITest] We are in the middle of selecting a page, ignoring
2020-01-09 03:33:58:799 - [Appium] Received SIGINT - shutting down
2020-01-09 03:33:58:831 - [HTTP] <-- POST /wd/hub/session/15c1c929-ecb5-46a1-a08e-23175d92a138/context - - ms - -
2020-01-09 03:33:58:831 - [HTTP] 

wdio.log

Execution of 1 spec files started at 2020-01-09T03:33:11.458Z

2020-01-09T03:33:11.460Z DEBUG @wdio/utils:initialiseServices: initialise wdio service "appium"
2020-01-09T03:33:11.473Z INFO @wdio/cli:launcher: Run onPrepare hook
2020-01-09T03:33:11.474Z DEBUG @wdio/appium-service: Will spawn Appium process: appium --log-level debug --log-timestamp
2020-01-09T03:33:13.148Z DEBUG @wdio/appium-service: Appium started with ID: 43452
2020-01-09T03:33:13.149Z DEBUG @wdio/appium-service: Appium logs written to: /Users/mdonnellon/Documents/projects/cordova-sample/testing/appium.txt
2020-01-09T03:33:13.155Z INFO @wdio/local-runner: Start worker 0-0 with arg: 
[0-0] 2020-01-09T03:33:13.571Z INFO @wdio/local-runner: Run worker command: run
[0-0] RUNNING in /var/tmp/Debug-iphonesimulator/HelloCordova.app - /src/switch-context.ts
[0-0] 2020-01-09T03:33:13.700Z DEBUG @wdio/local-runner:utils: init remote session
[0-0] 2020-01-09T03:33:13.702Z INFO webdriverio: Initiate new session using the webdriver protocol
[0-0] 2020-01-09T03:33:13.705Z INFO webdriver: [POST] http://127.0.0.1:4723/wd/hub/session
[0-0] 2020-01-09T03:33:13.705Z INFO webdriver: DATA { capabilities:
   { alwaysMatch:
      { platformName: 'iOS',
        platformVersion: '13.3',
        app: '/var/tmp/Debug-iphonesimulator/HelloCordova.app',
        deviceName: 'iPhone 11',
        newCommandTimeout: 360000 },
     firstMatch: [ {} ] },
  desiredCapabilities:
   { platformName: 'iOS',
     platformVersion: '13.3',
     app: '/var/tmp/Debug-iphonesimulator/HelloCordova.app',
     deviceName: 'iPhone 11',
     newCommandTimeout: 360000 } }
[0-0] hello!
[0-0] 2020-01-09T03:33:32.331Z INFO webdriver: COMMAND getContexts()
[0-0] 2020-01-09T03:33:32.332Z INFO webdriver: [GET] http://127.0.0.1:4723/wd/hub/session/15c1c929-ecb5-46a1-a08e-23175d92a138/contexts
[0-0] 2020-01-09T03:33:32.421Z INFO webdriver: RESULT [ 'NATIVE_APP' ]
[0-0] 2020-01-09T03:33:33.427Z INFO webdriver: COMMAND getContexts()
[0-0] 2020-01-09T03:33:33.427Z INFO webdriver: [GET] http://127.0.0.1:4723/wd/hub/session/15c1c929-ecb5-46a1-a08e-23175d92a138/contexts
[0-0] 2020-01-09T03:33:33.462Z INFO webdriver: RESULT [ 'NATIVE_APP', 'WEBVIEW_43515.2' ]
[0-0] 2020-01-09T03:33:33.463Z INFO webdriver: COMMAND switchContext("WEBVIEW_43515.2")
[0-0] 2020-01-09T03:33:33.463Z INFO webdriver: [POST] http://127.0.0.1:4723/wd/hub/session/15c1c929-ecb5-46a1-a08e-23175d92a138/context
[0-0] 2020-01-09T03:33:33.463Z INFO webdriver: DATA { name: 'WEBVIEW_43515.2' }
^C

Ending WebDriver sessions gracefully ...
(press ctrl+c again to hard kill the runner)
2020-01-09T03:33:58.799Z INFO @wdio/local-runner: Shutting down spawned worker
[0-0] 2020-01-09T03:33:58.799Z INFO @wdio/local-runner: Received SIGINT, giving process 5000ms to shutdown gracefully
2020-01-09T03:33:58.800Z INFO @wdio/local-runner: Run worker command: endSession
2020-01-09T03:33:58.801Z INFO webdriver: COMMAND deleteSession()
2020-01-09T03:33:58.801Z INFO webdriver: [DELETE] http://127.0.0.1:4723/wd/hub/session/15c1c929-ecb5-46a1-a08e-23175d92a138
[0-0] 2020-01-09T03:33:58.807Z WARN webdriver: Request failed due to connect ECONNREFUSED 127.0.0.1:4723
[0-0] 2020-01-09T03:33:58.807Z INFO webdriver: Retrying 1/3
2020-01-09T03:33:58.807Z INFO webdriver: [DELETE] http://127.0.0.1:4723/wd/hub/session/15c1c929-ecb5-46a1-a08e-23175d92a138
[0-0] 2020-01-09T03:33:58.810Z WARN webdriver: Request failed due to connect ECONNREFUSED 127.0.0.1:4723
[0-0] 2020-01-09T03:33:58.810Z INFO webdriver: Retrying 2/3
2020-01-09T03:33:58.810Z INFO webdriver: [DELETE] http://127.0.0.1:4723/wd/hub/session/15c1c929-ecb5-46a1-a08e-23175d92a138
[0-0] 2020-01-09T03:33:58.812Z WARN webdriver: Request failed due to connect ECONNREFUSED 127.0.0.1:4723
[0-0] 2020-01-09T03:33:58.812Z INFO webdriver: Retrying 3/3
2020-01-09T03:33:58.812Z INFO webdriver: [DELETE] http://127.0.0.1:4723/wd/hub/session/15c1c929-ecb5-46a1-a08e-23175d92a138
[0-0] 2020-01-09T03:33:58.813Z ERROR webdriver: Request failed due to Error: connect ECONNREFUSED 127.0.0.1:4723
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1107:14)
2020-01-09T03:33:58.813Z ERROR @wdio/local-runner: Failed launching test session: Error: connect ECONNREFUSED 127.0.0.1:4723
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1107:14)
2020-01-09T03:33:58.832Z DEBUG @wdio/local-runner: Runner 0-0 finished with exit code 1
[0-0] FAILED in /var/tmp/Debug-iphonesimulator/HelloCordova.app - /src/switch-context.ts
2020-01-09T03:33:58.834Z INFO @wdio/cli:launcher: Run onComplete hook
2020-01-09T03:33:58.834Z DEBUG @wdio/appium-service: Appium (pid: 43451) killed

Spec Files:      0 passed, 1 failed, 1 total (100% completed) in 00:00:47 

npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! [email protected] wdio: `wdio`
npm ERR! Exit status 1
npm ERR! 
npm ERR! Failed at the [email protected] wdio script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     /Users/mdonnellon/.npm/_logs/2020-01-09T03_33_58_851Z-debug.log
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! [email protected] build:appium: `cordova prepare ios && cd platforms/ios && rm -Rf /var/tmp/Debug-iphonesimulator* && xcodebuild -workspace "HelloCordova.xcworkspace" -scheme "HelloCordova" -configuration "Debug" -sdk iphonesimulator SYMROOT='/var/tmp/' build && cd ../.. && cd testing && npm run wdio`
npm ERR! Exit status 1
npm ERR! 
npm ERR! Failed at the [email protected] build:appium script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     /Users/mdonnellon/.npm/_logs/2020-01-09T03_33_58_873Z-debug.log