{"action":"created","issue":{"url":"https://api.github.com/repos/e-mission/e-mission-data-collection/issues/95","repository_url":"https://api.github.com/repos/e-mission/e-mission-data-collection","labels_url":"https://api.github.com/repos/e-mission/e-mission-data-collection/issues/95/labels{/name}","comments_url":"https://api.github.com/repos/e-mission/e-mission-data-collection/issues/95/comments","events_url":"https://api.github.com/repos/e-mission/e-mission-data-collection/issues/95/events","html_url":"https://github.com/e-mission/e-mission-data-collection/issues/95","id":136611565,"number":95,"title":"iOS native code init takes a long time","user":{"login":"shankari","id":2423263,"avatar_url":"https://avatars.githubusercontent.com/u/2423263?v=3","gravatar_id":"","url":"https://api.github.com/users/shankari","html_url":"https://github.com/shankari","followers_url":"https://api.github.com/users/shankari/followers","following_url":"https://api.github.com/users/shankari/following{/other_user}","gists_url":"https://api.github.com/users/shankari/gists{/gist_id}","starred_url":"https://api.github.com/users/shankari/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/shankari/subscriptions","organizations_url":"https://api.github.com/users/shankari/orgs","repos_url":"https://api.github.com/users/shankari/repos","events_url":"https://api.github.com/users/shankari/events{/privacy}","received_events_url":"https://api.github.com/users/shankari/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":4,"created_at":"2016-02-26T06:46:41Z","updated_at":"2016-02-26T09:23:45Z","closed_at":null,"body":"Specially when the app is launched in the background, app init sometimes takes ~ 10-20 minutes. Here's one instance.\r\n\r\n```\r\n8246 \t2016-02-24 13:29:37.780600-08:00 \tReceived transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START\r\n8247 \t2016-02-24 13:29:37.946080-08:00 \tstarted fine location tracking\r\n8248 \t2016-02-24 13:29:38.059400-08:00 \tReceived transition T_TRIP_STARTED in state STATE_WAITING_FOR_TRIP_START\r\n8249 \t2016-02-24 13:29:38.335780-08:00 \tMoved from STATE_WAITING_FOR_TRIP_START to STATE_ONGOING_TRIP\r\n8250 \t2016-02-24 13:29:38.358590-08:00 \tReceived notification T_TRIP_STARTED while processing silent push notification\r\n8251 \t2016-02-24 13:29:38.570830-08:00 \tConsidering region with id = STATIONARY_GEOFENCE_LOCATION, location -121.889543, 37.331404\r\n8252 \t2016-02-24 13:29:38.591660-08:00 \tDeleting it!!\r\n8253 \t2016-02-24 13:29:38.614080-08:00 \tReceived transition T_TRIP_STARTED in state STATE_ONGOING_TRIP\r\n8254 \t2016-02-24 13:29:38.660030-08:00 \tReceived notification T_TRIP_STARTED while processing silent push notification\r\n8255 \t2016-02-24 13:29:38.682070-08:00 \tReceived notification T_EXITED_GEOFENCE while processing silent push notification\r\n8256 \t2016-02-24 13:29:38.713460-08:00 \tCurrent state of region STATIONARY_GEOFENCE_LOCATION is 2 (outside)\r\n8257 \t2016-02-24 13:29:38.729120-08:00 \tReceived OUTSIDE geofence state when currState = STATE_ONGOING_TRIP\r\n8258 \t2016-02-24 13:29:38.844450-08:00 \tReceived transition T_TRIP_RESTARTED in state STATE_ONGOING_TRIP\r\n8259 \t2016-02-24 13:29:39.007380-08:00 \tReceived notification T_TRIP_RESTARTED while processing silent push notification\r\n8260 \t2016-02-24 13:29:39.043600-08:00 \tSuccessfully registered remote push notifications with parse\r\n8261 \t2016-02-24 13:29:39.061620-08:00 \tRecieved location <+37.32935173,-121.89529055> +/- 65.00m (speed -1.00 mps / course -1.00) @ 2/24/16, 1:36:37 PM Pacific Standard Time, ongoing trip = true\r\n8262 \t2016-02-24 13:44:19.405650-08:00 \tfinished init of iOS native code\r\n8263 \t2016-02-24 13:44:19.508920-08:00 \tApplication launched with LaunchOptionsLocationKey = YES\r\n8264 \t2016-02-24 13:44:19.527900-08:00 \ttripDiaryStateMachine = (null), relaunchLocationManager = 1, recreating the state machine\r\n8265 \t2016-02-24 13:44:19.584380-08:00 \tRestart = 1, initializing TripDiaryStateMachine with state = STATE_ONGOING_TRIP\r\n8266 \t2016-02-24 13:44:19.605660-08:00 \tstarted fine location tracking\r\n```\r\n\r\nBecause of this, the trip back from the tech was largely a straight line with very little data. Need to investigate why this happens."},"comment":{"url":"https://api.github.com/repos/e-mission/e-mission-data-collection/issues/comments/189184681","html_url":"https://github.com/e-mission/e-mission-data-collection/issues/95#issuecomment-189184681","issue_url":"https://api.github.com/repos/e-mission/e-mission-data-collection/issues/95","id":189184681,"user":{"login":"shankari","id":2423263,"avatar_url":"https://avatars.githubusercontent.com/u/2423263?v=3","gravatar_id":"","url":"https://api.github.com/users/shankari","html_url":"https://github.com/shankari","followers_url":"https://api.github.com/users/shankari/followers","following_url":"https://api.github.com/users/shankari/following{/other_user}","gists_url":"https://api.github.com/users/shankari/gists{/gist_id}","starred_url":"https://api.github.com/users/shankari/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/shankari/subscriptions","organizations_url":"https://api.github.com/users/shankari/orgs","repos_url":"https://api.github.com/users/shankari/repos","events_url":"https://api.github.com/users/shankari/events{/privacy}","received_events_url":"https://api.github.com/users/shankari/received_events","type":"User","site_admin":false},"created_at":"2016-02-26T09:23:45Z","updated_at":"2016-02-26T09:23:45Z","body":"Finally, the one which failed. Note that again, the CommunicationHelper from the previous remote push is invoked as part of this geofence exit callback and the app is suspended in the middle.\r\n\r\n```\r\n8224,1456347610.35,2016-02-24 12:53:10.350020-08:00,finished init of iOS native code\r\n8225,1456347610.46,2016-02-24 12:53:10.460370-08:00,Application launched with LaunchOptionsLocationKey = NO\r\n8226,1456347610.48,2016-02-24 12:53:10.484790-08:00,\"tripDiaryStateMachine = (null), relaunchLocationManager = 0, recreating the state machine\"\r\n8227,1456347610.53,2016-02-24 12:53:10.526250-08:00,\"Restart = 0, initializing TripDiaryStateMachine with state = STATE_WAITING_FOR_TRIP_START\"\r\n8228,1456347610.63,2016-02-24 12:53:10.628160-08:00,\"Received remote push, about to check whether a trip has ended\"\r\n8229,1456347610.67,2016-02-24 12:53:10.665210-08:00,Received transition T_RECEIVED_SILENT_PUSH in state STATE_WAITING_FOR_TRIP_START\r\n8230,1456347610.89,2016-02-24 12:53:10.891640-08:00,backgroundSync called8231,1456347611.1,2016-02-24 12:53:11.104630-08:00,pushAndClearUserCache called\r\n8232,1456347611.45,2016-02-24 12:53:11.446930-08:00,CommunicationHelper.execute called!8233,1456347611.47,2016-02-24 12:53:11.465090-08:00,tryToAuthenticate called8234,1456347611.49,2016-02-24 12:53:11.492990-08:00,\"ready to authenticate, checking expiration\"\r\n8235,1456347611.51,2016-02-24 12:53:11.510550-08:00,\"currAuth = GTMOAuth2Authentication 0x127f70170: {refreshToken=\"\"1/sFWC0Qy3Cvpq-4LEq6dQonUpKFdB5GeRlnmU_L97JtY\"\"}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES\"\r\n8236,1456347611.53,2016-02-24 12:53:11.529640-08:00,\"Existing auth token expired, refreshing\"8237,1456347611.56,2016-02-24 12:53:11.558680-08:00,CommunicationHelper.execute called!\r\n8238,1456347611.58,2016-02-24 12:53:11.575890-08:00,\"currAuth = GTMOAuth2Authentication 0x127f70170: {refreshToken=\"\"1/sFWC0Qy3Cvpq-4LEq6dQonUpKFdB5GeRlnmU_L97JtY\"\"}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES\"\r\n8239,1456347611.59,2016-02-24 12:53:11.590680-08:00,\"Existing auth token expired, refreshing\"8240,1456347611.61,2016-02-24 12:53:11.608620-08:00,Received notification T_RECEIVED_SILENT_PUSH while processing silent push notification8241,1456347611.63,2016-02-24 12:53:11.631710-08:00,Ignoring SILENT_PUSH in the silent push handler\r\n8242,1456349797.41,2016-02-24 13:29:37.408610-08:00,CommunicationHelper.execute called!\r\n[app suspended]\r\n8243,1456349797.65,2016-02-24 13:29:37.653300-08:00,\"currAuth = GTMOAuth2Authentication 0x127f70170: {refreshToken=\"\"1/sFWC0Qy3Cvpq-4LEq6dQonUpKFdB5GeRlnmU_L97JtY\"\"}, canAuthorize = YES, expiresIn = (null), expirationDate = (null), expired = YES\"\r\n8244,1456349797.68,2016-02-24 13:29:37.680410-08:00,\"Existing auth token expired, refreshing\"8245,1456349797.72,2016-02-24 13:29:37.721320-08:00,\"In state STATE_WAITING_FOR_TRIP_START, Recieved location <+37.33204203,-121.89037168> +/- 10.00m (speed 0.34 mps / course 236.95) @ 2/24/16, 9:18:23 AM Pacific Standard Time\"\r\n8246,1456349797.78,2016-02-24 13:29:37.780600-08:00,Received transition T_EXITED_GEOFENCE in state STATE_WAITING_FOR_TRIP_START\r\n```\r\n\r\nThen, we start fine location tracking and get a single update before the app is suspended again.\r\n\r\n```\r\n8247,1456349797.95,2016-02-24 13:29:37.946080-08:00,started fine location tracking\r\n8261,1456349799.06,2016-02-24 13:29:39.061620-08:00,\"Recieved location <+37.32935173,-121.89529055> +/- 65.00m (speed -1.00 mps / course -1.00) @ 2/24/16, 1:36:37 PM Pacific Standard Time, ongoing trip = true\"\r\n[app suspended]\r\n8262,1456350679.41,2016-02-24 13:44:19.405650-08:00,finished init of iOS native code\r\n8263,1456350679.51,2016-02-24 13:44:19.508920-08:00,Application launched with LaunchOptionsLocationKey = YES\r\n```\r\n\r\nAnd then as part of the visit notification, the fine location tracking starts in earnest.\r\n\r\n```\r\n8259,1456349799.01,2016-02-24 13:29:39.007380-08:00,Received notification T_TRIP_RESTARTED while processing silent push notification\r\n8260,1456349799.04,2016-02-24 13:29:39.043600-08:00,Successfully registered remote push notifications with parse\r\n8261,1456349799.06,2016-02-24 13:29:39.061620-08:00,\"Recieved location <+37.32935173,-121.89529055> +/- 65.00m (speed -1.00 mps / course -1.00) @ 2/24/16, 1:36:37 PM Pacific Standard Time, ongoing trip = true\"\r\n[app suspended]\r\n8262,1456350679.41,2016-02-24 13:44:19.405650-08:00,finished init of iOS native code\r\n8263,1456350679.51,2016-02-24 13:44:19.508920-08:00,Application launched with LaunchOptionsLocationKey = YES\r\n8264,1456350679.53,2016-02-24 13:44:19.527900-08:00,\"tripDiaryStateMachine = (null), relaunchLocationManager = 1, recreating the state machine\"\r\n8265,1456350679.58,2016-02-24 13:44:19.584380-08:00,\"Restart = 1, initializing TripDiaryStateMachine with state = STATE_ONGOING_TRIP\"\r\n8266,1456350679.61,2016-02-24 13:44:19.605660-08:00,started fine location tracking\r\n8267,1456350680.13,2016-02-24 13:44:20.128470-08:00,\"Received visit notification = <+37.33145220,-121.88961989> +/- 30.92m (2016-02-24 17:21:01 +0000 to 2016-02-24 21:33:22 +0000)\"\r\n8268,1456350680.19,2016-02-24 13:44:20.188450-08:00,Received transition T_VISIT_ENDED in state STATE_ONGOING_TRIP\r\n8269,1456350680.67,2016-02-24 13:44:20.667830-08:00,\"Recieved location <+37.32935173,-121.89529055> +/- 65.00m (speed -1.00 mps / course -1.00) @ 2/24/16, 1:36:37 PM Pacific Standard Time, ongoing trip = true\"\r\n8270,1456350680.79,2016-02-24 13:44:20.791340-08:00,\"Recieved location <+37.33000082,-121.89575416> +/- 225.17m (speed -1.00 mps / course -1.00) @ 2/24/16, 1:37:14 PM Pacific Standard Time, ongoing trip = true\"\r\n```\r\n\r\nI wonder if the app was killed in the middle. There is no corresponding log message, but we are not guaranteed to have one if the app is already suspended. Or is the location update actually from the fine location tracking, or is it from the significant location changes? Or ???\r\n\r\n> applicationWillTerminate:—Lets you know that your app is being terminated. This method is not called if your app is suspended.\r\n\r\nhttps://developer.apple.com/library/ios/documentation/iPhone/Conceptual/iPhoneOSProgrammingGuide/TheAppLifeCycle/TheAppLifeCycle.html"}}