[TIMOB-23146] iOS/WatchOS: Installing to Simulators hangs since Xcode 7.3

GitHub Issue	n/a
Type	Bug
Priority	Critical
Status	Closed
Resolution	Fixed
Resolution Date	2016-04-12T02:49:20.000+0000
Affected Version/s	Release 5.2.1
Fix Version/s	Release 5.3.0, ioslib 0.10.4, ioslib 0.10.5
Components	iOS, Tooling
Labels	qe-5.3.0
Reporter	Fokke Zandbergen
Assignee	Chee Kiat Ng
Created	2016-04-05T09:16:01.000+0000
Updated	2016-05-25T05:07:38.000+0000

Description

[~cng] [~htbryant] and myself can't get the [Titanium 5.2.0 Sample](https://github.com/appcelerator-developer-relations/appc-sample-ti520) to install the WatchOS2 app to the Simulator anymore. This was also reported on [TiSlack](https://ti-slack.slack.com/archives/general/p1459847345001026) by Erik Storli and he found that downgrading Xcode to 7.2.1 resolved it. So something changed in 7.3 that breaks ioslib. When you build the [Titanium 5.2.0 Sample](https://github.com/appcelerator-developer-relations/appc-sample-ti520) using ti build -p ios --launch-watch-app it will hang at _Waiting for Watch App to install_:

[INFO]  Launching iOS Simulator
[TRACE] [ioslib] Found watchOS 2.2 app: com.appcelerator.sample.ti520.watchkitapp
[TRACE] [ioslib] Selected iOS Simulator: iPhone 6s Plus
[TRACE] [ioslib]   UDID    = C7ECC4A2-E0F1-4248-B51E-5873696E719E
[TRACE] [ioslib]   iOS     = 9.3
[TRACE] [ioslib] Selected WatchOS Simulator: Apple Watch - 42mm
[TRACE] [ioslib]   UDID    = 7BCFC934-2DDA-4768-A7CA-929DA315E8A4
[TRACE] [ioslib]   WatchOS = 2.2
[TRACE] [ioslib] Autoselected Xcode: 7.3
[TRACE] [ioslib] iOS and watchOS simulators already paired
[TRACE] [ioslib] Tailing iPhone 6s Plus Simulator system log: /Users/fokkezb/Library/Logs/CoreSimulator/C7ECC4A2-E0F1-4248-B51E-5873696E719E/system.log
[TRACE] [ioslib] Running: /Applications/Xcode.app/Contents/Developer/usr/bin/simctl shutdown C7ECC4A2-E0F1-4248-B51E-5873696E719E
[TRACE] [ioslib] iPhone 6s Plus Simulator was already shutdown
[TRACE] [ioslib] Running: /Applications/Xcode.app/Contents/Developer/Applications/Simulator.app/Contents/MacOS/Simulator -CurrentDeviceUDID C7ECC4A2-E0F1-4248-B51E-5873696E719E
[TRACE] [ioslib] iPhone 6s Plus Simulator started
[TRACE] [ioslib] Tailing Apple Watch - 42mm Simulator system log: /Users/fokkezb/Library/Logs/CoreSimulator/7BCFC934-2DDA-4768-A7CA-929DA315E8A4/system.log
[TRACE] [ioslib] Running: /Applications/Xcode.app/Contents/Developer/usr/bin/simctl shutdown 7BCFC934-2DDA-4768-A7CA-929DA315E8A4
[TRACE] [ioslib] Apple Watch - 42mm Simulator was already shutdown
[TRACE] [ioslib] Running: /Applications/Xcode.app/Contents/Developer/Applications/Simulator (Watch).app/Contents/MacOS/Simulator (Watch) -CurrentDeviceUDID 7BCFC934-2DDA-4768-A7CA-929DA315E8A4
[TRACE] [ioslib] Apple Watch - 42mm Simulator started
[TRACE] [ioslib] Running: osascript "/Users/fokkezb/Library/Application Support/Titanium/mobilesdk/osx/5.2.0.GA/node_modules/ioslib/lib/sim_focus.scpt" "Simulator (Watch)"
[TRACE] [ioslib] Apple Watch - 42mm Simulator successfully focused
[TRACE] [ioslib] Running: osascript "/Users/fokkezb/Library/Application Support/Titanium/mobilesdk/osx/5.2.0.GA/node_modules/ioslib/lib/sim_focus.scpt" "Simulator"
[TRACE] [ioslib] iPhone 6s Plus Simulator successfully focused
[TRACE] [ioslib] Running: /Applications/Xcode.app/Contents/Developer/usr/bin/simctl install C7ECC4A2-E0F1-4248-B51E-5873696E719E /Users/fokkezb/dev/samples/appc-sample-ti520/build/iphone/build/Products/Debug-iphonesimulator/Ti 5.2.0.app
[TRACE] [ioslib] App installed
[TRACE] [ioslib] Waiting for Watch App to install…

Comments

Chee Kiat Ng 2016-04-06

I believe the system log has changed between Xcode 7.2.1 and Xcode 7.3 This is where the if statement never gets hit https://github.com/appcelerator/ioslib/blob/master/lib/simulator.js#L961

Chee Kiat Ng 2016-04-06

Here's the simulator system log for Xcode 7.3 just before it got stuck.

   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x70000021d000 -[ACXServerInstallOperation _onQueue_prepForTransferAndInstall]: Acquiring socket for com.appcelerator.sg.testwatch2 (placeholder = YES)
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x700000094000 -[ACXIDSSocketManager _onInternalQueue_initiateConnectionWithCompletionBlock:]: Starting socket bringup
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x700000094000 -[ACXIDSSocketManager _sendMessage:messageDictionary:error:]: Sent message with IDS GUID A6224558-480B-440E-AF7A-A05B582E6D5D
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x70000019a000 -[ACXIDSSocketManager handleIDSRelayConnectionResponse:fromID:UUID:socketPath:context:]: Got connection response with IDS ID DA5FCE2A-3E51-4E6C-8127-B40D60A64AE5
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x70000019a000 -[ACXIDSSocketManager handleIDSRelayConnectionResponse:fromID:UUID:socketPath:context:]: Connecting to socket at /tmp/appconduit_61F8CAD9-D7B5-4BB0-9A6F-52BC139389CA.sock
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x70000019a000 __77-[ACXIDSSocketManager beginUsingSocketAsDelegate:onQueue:tryWiFi:completion:]_block_invoke_2: Socket setup successful
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x700000094000 -[ACXServerInstallOperation _onQueue_doTransferAndInstallForWatchKitAppWithBundleID:size:]: com.appcelerator.sg.testwatch2: Sending Hello
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x700000094000 -[ACXServerInstallOperation receivedDictionaryOrData:]: com.appcelerator.sg.testwatch2: Starting streaming zip stream
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x700000094000 -[ACXServerInstallOperation receivedDictionaryOrData:]: com.appcelerator.sg.testwatch2: transferred 38037 bytes in 0.01 seconds (3529.27 KiB/sec); 0.95x compression
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x700000094000 -[ACXServerInstallOperation _onQueue_startInstall]: com.appcelerator.sg.testwatch2: Sending install start
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x700000094000 -[ACXServerInstallOperation receivedDictionaryOrData:]: com.appcelerator.sg.testwatch2: Got install done
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x70000021d000 __48-[ACXInstallQueue _onQueue_deQueueNextOperation]_block_invoke_2: Finished placeholder install for com.appcelerator.sg.testwatch2.watchkitapp; enqueueing actual install
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x70000021d000 -[ACXInstallQueue _onQueue_deQueueNextOperation]: Dequeued install operation for com.appcelerator.sg.testwatch2.watchkitapp (0 remaining in queue)
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro installd[43192]: 0x700000094000 -[MIClientConnection snapshotWKAppInCompanionAppID:toURL:options:completion:]: Snapshot requested for com.appcelerator.sg.testwatch2 by appconduitd (pid 43308) to /Users/kiat/Library/Developer/CoreSimulator/Devices/7C85302F-79EB-4187-B8B2-EA13F9D69D1C/data/Library/Caches/com.apple.AppConduit.staging/com.appcelerator.sg.testwatch2_cEYllD/Transfer with options {
   	    CreatePlaceholderOption = 0;
   	}
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro com.apple.MobileInstallationHelperService[43232]: 0x70000021d000 -[MobileInstallationHelperService createAppSnapshotWithBundleID:snapshotToURL:onlyV1AppIfPresent:placeholderOnly:completion:]: Snapshot requested for com.appcelerator.sg.testwatch2 to /Users/kiat/Library/Developer/CoreSimulator/Devices/7C85302F-79EB-4187-B8B2-EA13F9D69D1C/data/Library/Caches/com.apple.AppConduit.staging/com.appcelerator.sg.testwatch2_cEYllD/Transfer. V1: 0, placeholder: 0
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x70000021d000 -[ACXServerInstallOperation _onQueue_prepForTransferAndInstall]: Acquiring socket for com.appcelerator.sg.testwatch2 (placeholder = NO)
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x700000094000 -[ACXServerInstallOperation _onQueue_doTransferAndInstallForWatchKitAppWithBundleID:size:]: com.appcelerator.sg.testwatch2: Sending Hello
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x700000094000 -[ACXServerInstallOperation receivedDictionaryOrData:]: com.appcelerator.sg.testwatch2: Starting streaming zip stream
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x700000094000 -[ACXServerInstallOperation receivedDictionaryOrData:]: com.appcelerator.sg.testwatch2: transferred 52583 bytes in 0.02 seconds (2382.17 KiB/sec); 1.75x compression
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x700000094000 __48-[ACXInstallQueue _onQueue_deQueueNextOperation]_block_invoke: Starting pending install timer for com.appcelerator.sg.testwatch2.watchkitapp
   Apr  6 14:20:37 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x700000094000 -[ACXServerInstallOperation _onQueue_startInstall]: com.appcelerator.sg.testwatch2: Sending install start
   Apr  6 14:20:38 AppcAdmins-MacBook-Pro containermanagerd[43220]: 0x700000323000 systemGroupContainerPath: com.apple.containermanagerd.internal is not entitled for system group identifier: systemgroup.com.apple.lsd
   Apr  6 14:20:38 AppcAdmins-MacBook-Pro lsd[43221]: LaunchServices:(called by PID 43206) Identifiers file does not exist, creating file.
   Apr  6 14:20:38 AppcAdmins-MacBook-Pro containermanagerd[43220]: 0x700000323000 systemGroupContainerPath: com.apple.containermanagerd.internal is not entitled for system group identifier: systemgroup.com.apple.lsd
   Apr  6 14:20:38 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x700000094000 -[ACXIDSMessaging service:account:incomingMessage:fromID:context:]: Received message with ID 0575DF13-6ABE-4AA2-93E5-8E2C2B5F36EF
   Apr  6 14:20:38 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x70000021d000 -[ACXCompanionSyncConnection _onQueue_handleAppInstallMessage:]: Setting state to installed for com.appcelerator.sg.testwatch2.watchkitapp
   Apr  6 14:20:38 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x70000021d000 __54-[ACXInstallQueue acknowledgeInstallationForWatchApp:]_block_invoke: Installation of com.appcelerator.sg.testwatch2.watchkitapp acknowledged.
   Apr  6 14:20:38 AppcAdmins-MacBook-Pro nanoprefsyncd[43267]: (Error) <NPSServer.m -[NPSServer handleUnserializedUserDefaultsMsg:]:1036> Domain (com.apple.Carousel) not whitelisted; dropping incoming message
   Apr  6 14:20:38 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x70000021d000 -[ACXGizmoState _onQueue_setInstallStatusForApps:sendNotification:withUpdatePredicate:]: Posting ACXApplicationsUpdatedDarwinNotification
   Apr  6 14:20:38 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x70000019a000 __71+[ACXDeviceConnectionClient messageAllObserversWithInstallStateUpdate:]_block_invoke: Messaging observers with update {
   	    "com.appcelerator.sg.testwatch2.watchkitapp" = 2;
   	}
   Apr  6 14:20:38 AppcAdmins-MacBook-Pro companionappd[43271]: -[SPApplicationManager newGizmoPersistentDomain] - results = {
   	    "com.appcelerator.sg.testwatch2.watchkitapp" =     {
   	        SPApplicationTeamID = WP4952RUHJ;
   	        SPApplicationUniqueID = 118ad9ec8e490ee4bd960d62ebf5c753;
   	        SPContainerAppBundleId = "com.appcelerator.sg.testwatch2";
   	        SPPluginBundleIdKey = "com.appcelerator.sg.testwatch2.watchkitapp.watchkitextension";
   	        WKBetaAppKey = 0;
   	        WKWatchKitVersion = "2.0";
   	        i = "com.appcelerator.sg.testwatch2.watchkitapp";
   	        n = testwatch2;
   	        s = 2;
   	        saw = 1;
   	    };
   	    "com.apple.stocks.watchapp" =     {
   	        SPApplicationTeamID = "";
   	        SPApplicationUniqueID = d0e42d83b56b97f4ffe42a7ecd8ee539;
   	        SPContainerAppBundleId = "com.apple.stocks";
   	        SPPluginBundleIdKey = "com.apple.stocks.watchkitextension";
   	        WKBetaAppKey = 0;
   	        WKWatchKitVersion = "2.0";
   	        s = 3;
   	        saw = 1;
   	    };
   	}
   Apr  6 14:20:38 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x70000019a000 -[ACXServerInstallOperation receivedDictionaryOrData:]: com.appcelerator.sg.testwatch2: Got install done
   Apr  6 14:20:38 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x700000094000 __48-[ACXInstallQueue _onQueue_deQueueNextOperation]_block_invoke_2: Finished install for com.appcelerator.sg.testwatch2.watchkitapp
   Apr  6 14:20:38 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x700000094000 -[ACXInstallQueue _onQueue_deQueueNextOperation]: Nothing remaining in install queue.
   [TRACE] [ioslib] App installed

Chee Kiat Ng 2016-04-07

For Xcode 7.2.1, the log we are looking for is: Apr 7 15:24:50 AppcAdmins-MacBook-Pro companionappd[2266]: (Note ) WatchKit: application (com.appcelerator.sg.testwatch2.watchkitapp), install status: 2, message: application install success which is completely non-existent in Xcode 7.3. In Xcode 7.3, it seems generic so far. Apr 6 14:20:38 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x70000019a000 -[ACXServerInstallOperation receivedDictionaryOrData:]: com.appcelerator.sg.testwatch2: Got install done
Chee Kiat Ng 2016-04-07

PR here: https://github.com/appcelerator/ioslib/pull/31 Not the best fix but, the new system log is just....unbearably terrible compared to Xcode 7.2.1 and earlier. So much so that it's nearly impossible to find valid info in the log that confirms that the watchapp is installed, other than Installation of com.appcelerator.sg.testwatch2.watchkitapp acknowledged.
Chee Kiat Ng 2016-04-07

Will do TIMOB PR if PR is ok.

Chris Barber 2016-04-07

Why the like that says the installation is acknowledged? There's a line towards the end that seems even better to test for:

   Apr  6 14:20:38 AppcAdmins-MacBook-Pro appconduitd[43308]: 0x700000094000 __48-[ACXInstallQueue _onQueue_deQueueNextOperation]_block_invoke_2: Finished install for com.appcelerator.sg.testwatch2.watchkitapp

What about if the watchkit app fails to install?

Chee Kiat Ng 2016-04-08

As discussed the day before, "Finished install" can imply both success and failure, so acknowledged is still a better choice. and since we are unable to produce a fail case, this approach is the best way forward. Chris has done the code review and he's ok. [~hansknoechel] can you do an FR? Thanks.
Chris Barber 2016-04-12

titanium_mobile PRs: Master: https://github.com/appcelerator/titanium_mobile/pull/7936 5_3_X: https://github.com/appcelerator/titanium_mobile/pull/7937
Chee Kiat Ng 2016-04-12

PRs merged.
Harry Bryant 2016-05-19

I receive the following error when trying to build the sample app with ti build -p ios --launch-watch-app through the CLI. There are no errors when building through Studio or through the CLI with *appc run* -p ios --launch-watch-app : [DEBUG] module.js:328 [DEBUG] throw err; [DEBUG] ^ [ERROR] : Cannot find module '/Users/harrybryant/Documents/Appcelerator_Studio_Workspace/Apple WatchOS2/undefined' [DEBUG] at Function.Module._resolveFilename (module.js:326:15) [DEBUG] at Function.Module._load (module.js:277:25) [DEBUG] at Function.Module.runMain (module.js:442:10) [DEBUG] at startup (node.js:136:18) [DEBUG] at node.js:966:3 [ERROR] Alloy compiler failed Tested On: iPhone 6S (9.3) Simulator & Watch OS2.2 Simulator Mac OSX El Capitan 10.11.3 (15D21) Ti SDK: 5.3.0.v20160517124218 Appc Studio: 4.6.0.201605180604 Appc NPM: 4.2.5-5 App CLI: 5.3.0-45 Xcode 7.3 Node v4.2.6 production
Chee Kiat Ng 2016-05-20

[~htbryant] where's the "following error" which you indicated in your comment? Did you mean the same problem as the ticket?
Harry Bryant 2016-05-20

[~cng] Apologies, I forgot to include the error, I've amended my previous comment.
Chee Kiat Ng 2016-05-23

[~htbryant] Just a hunch, but can you try not to have a spacing in the project name see if that works? also, give *appc ti build -p ios --launch-watch-app* a shot too. Thanks.
Harry Bryant 2016-05-23

[~cng] Running appc ti build -p ios --launch-watch-app works absolutely fine. Removed the space in the project name and ran ti build -p ios --launch-watch-app and ran into the same error.
Harry Bryant 2016-05-24

Watch OS apps can be built to simulators successfully using appc run -p ios --launch-watch-app. Tested on: OS X El Capitan Version 10.11.4 iPhone 6S Simulator and Watch OS 2.2 Simulator Appc Studio: 4.6.0.201605201934 Ti SDK: 5.3.0.v20160517124218 Appc NPM: 4.2.5-5 Appc Core: 5.3.0-46 Node: v4.4.4 *Closing Ticket.*
Fokke Zandbergen 2016-05-25

So, we close this ticket as fixed as appc run and appc ti build work, even though ti build does not? That troubles me for 2 reasons: * We're ignoring an OSS tooling bug. * We're not investigating *why* appc ti build and ti build differ, possibly leaving fundamental architecture flaws uncovered.

JSON Source