NO TRIPS RECORDED! updated cistup-ec new mode and purpose changes made out of master.

[deepalics0044]

Something flaky in the new update in cistup-ec. Trips not being recorded.

[shankari]

It is very unlikely that the new update to cistup-ec broke the trip recording, since it was a UI only change that did not change the native plugins in any way.

[shankari]

Here's what I see from the logs that were sent to me.

It looks like this was a new install and not an existing app update

0,1562362157.768,2019-07-06T02:59:17.768000+05:30,BuiltinUserCache : Added value for key stats/client_nav_event at time 1.562362157757E9
1,1562362157.769,2019-07-06T02:59:17.769000+05:30,TripDiaryStateMachineRcvr : Comparing installed version 0 with new version 99

The FSM gets initialized properly and is in waiting_for_trip_start

184,1562362371.385,2019-07-06T03:02:51.385000+05:30,TripDiaryStateMachineService : newState after handling action is local.state.waiting_for_trip_start
185,1562362371.391,2019-07-06T03:02:51.391000+05:30,TripDiaryStateMachineService : newState saved in prefManager is local.state.waiting_for_trip_start

However, we are unable to contact the server during the onboarding. This is the first call to CommunicationHelper so I am pretty sure it deals with registering the app to the server.

193,1562362374.0679998,2019-07-06T03:02:54.068000+05:30,"ConnectionSettings : in getConnectURL, returning http://emission.cistup.iisc.ac.in:8080"
195,1562362374.664,2019-07-06T03:02:54.664000+05:30,CommunicationHelper : Got response org.apache.http.message.BasicHttpResponse@4e4587 with status HTTP/1.0 503 Service Unavailable
197,1562362374.691,2019-07-06T03:02:54.691000+05:30,BuiltinUserCache : Added value for key intro_done at time 1.562362374691E9
198,1562362374.694,2019-07-06T03:02:54.694000+05:30,js : About to navigate to preferred tab

We continue getting 503 errors.

224,1562362374.867,2019-07-06T03:02:54.867000+05:30,CommunicationHelper : Got response org.apache.http.message.BasicHttpResponse@d3f3baa with status HTTP/1.0 503 Service Unavailable
225,1562362374.867,2019-07-06T03:02:54.867000+05:30,class edu.berkeley.eecs.embase.R : Failed to get JSON object
233,1562362374.961,2019-07-06T03:02:54.961000+05:30,CommunicationHelper : Got response org.apache.http.message.BasicHttpResponse@796639b with status HTTP/1.0 503 Service Unavailable
234,1562362374.9620001,2019-07-06T03:02:54.962000+05:30,class edu.berkeley.eecs.embase.R : Failed to get JSON object

Including when we try to access the diary.

237,1562362375.286,2019-07-06T03:02:55.286000+05:30,"js : while reading data from server for 1562351400000 error = ""While pushing/getting from server HTTP/1.0 503 Service Unavailable"""
238,1562362375.2910001,2019-07-06T03:02:55.291000+05:30,"js : found 0 trips, last_processed_ts = Sat Jul 06 2019 00:00:00 GMT+0530"

This pattern continues for a while, but then the connection issue is resolved.

272,1562362378.29,2019-07-06T03:02:58.290000+05:30,CommunicationHelper : Got response org.apache.http.message.BasicHttpResponse@44d1367 with status HTTP/1.0 503 Service Unavailable
317,1562362382.391,2019-07-06T03:03:02.391000+05:30,CommunicationHelper : Got response org.apache.http.message.BasicHttpResponse@2442e80 with status HTTP/1.0 503 Service Unavailable
323,1562362387.226,2019-07-06T03:03:07.226000+05:30,CommunicationHelper : Got response org.apache.http.message.BasicHttpResponse@7acd42d with status HTTP/1.0 200 OK
345,1562362387.8660002,2019-07-06T03:03:07.866000+05:30,CommunicationHelper : Got response org.apache.http.message.BasicHttpResponse@a291edc with status HTTP/1.0 200 OK

apparently while trying to retrieve data for Jul 1st.

364,1562362393.5089998,2019-07-06T03:03:13.509000+05:30,js : complete_ts = null(Thu Jan 01 1970 05:30:00 GMT+0530) end of current day = 1562005799(Mon Jul 01 2019 23:59:59 GMT+0530) retVal = false

and there is no data on the server. That doesn't seem surprising given that the app was installed fresh on 6th July. Is there data on the server from a prior installation?

367,1562362394.605,2019-07-06T03:03:14.605000+05:30,"js : while reading data for 1561919400000 from server, got nTrips = 0"
368,1562362394.609,2019-07-06T03:03:14.609000+05:30,"js : found 0 trips, last_processed_ts = Mon Jul 01 2019 00:00:00 GMT+0530"
369,1562362394.611,2019-07-06T03:03:14.611000+05:30,js : about to query for unprocessed trips from Mon Jul 01 2019 00:00:00 GMT+0530 -> Mon Jul 01 2019 23:59:59 GMT+0530
374,1562362402.2610002,2019-07-06T03:03:22.261000+05:30,"CommunicationHelper : Result Summary JSON = {""phone_data"": []} length 19"
375,1562362402.265,2019-07-06T03:03:22.265000+05:30,js : About to dedup localResult = 0remoteResult = 0
376,1562362402.269,2019-07-06T03:03:22.269000+05:30,js : Deduped list = 0
377,1562362402.27,2019-07-06T03:03:22.270000+05:30,js : No unprocessed trips. yay!
378,1562362402.2710001,2019-07-06T03:03:22.271000+05:30,js : tripList.length = 0unprocessedTripList.length = 0

Not sure if this is being reported as "no trips recorded", some additional information on which days you are checking and which trips you expect to see would be helpful.

[deepalics0044]

I couldn't see the update in my app. So I uninstalled it and install it again to test.
In the server terminal I can see

START 2019-07-08 13:16:25.896522 GET /lib/angular-simple-logger/dist/angular-simple-logger.js
END 2019-07-08 13:16:25.923524 GET /lib/angular-simple-logger/dist/angular-simple-logger.js  0.026890993118286133 
START 2019-07-08 13:17:03.702333 POST /pipeline/get_complete_ts
START 2019-07-08 13:17:03.717231 POST /timeline/getTrips/2019-07-08
/home/deepali/e-mission-server/emission/net/auth/google_auth.py:55: ResourceWarning: unclosed <socket.socket fd=14, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.158.21.78', 60092), raddr=('216.58.221.42', 443)>
  tokenFields = goi.verify_oauth2_token(token, gatr.Request())
/home/deepali/e-mission-server/emission/net/auth/google_auth.py:55: ResourceWarning: unclosed <socket.socket fd=21, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.158.21.78', 41040), raddr=('172.217.27.170', 443)>
  tokenFields = goi.verify_oauth2_token(token, gatr.Request())
END 2019-07-08 13:17:04.594817 POST /pipeline/get_complete_ts ea4e449d-63b7-4e2c-892a-85f561029ce1 0.8923594951629639 
END 2019-07-08 13:17:04.654541 POST /timeline/getTrips/2019-07-08 ea4e449d-63b7-4e2c-892a-85f561029ce1 0.9372107982635498 
START 2019-07-08 13:17:04.988078 POST /datastreams/find_entries/timestamp
/home/deepali/e-mission-server/emission/net/auth/google_auth.py:55: ResourceWarning: unclosed <socket.socket fd=20, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.158.21.78', 41214), raddr=('216.58.196.202', 443)>
  tokenFields = goi.verify_oauth2_token(token, gatr.Request())
END 2019-07-08 13:17:05.879414 POST /datastreams/find_entries/timestamp ea4e449d-63b7-4e2c-892a-85f561029ce1 0.8912143707275391 
START 2019-07-08 13:17:06.265063 POST /datastreams/find_entries/timestamp
START 2019-07-08 13:17:06.267027 POST /datastreams/find_entries/timestamp
/home/deepali/e-mission-server/emission/net/auth/google_auth.py:55: ResourceWarning: unclosed <socket.socket fd=21, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.158.21.78', 50414), raddr=('172.217.167.42', 443)>
  tokenFields = goi.verify_oauth2_token(token, gatr.Request())
/home/deepali/e-mission-server/emission/net/auth/google_auth.py:55: ResourceWarning: unclosed <socket.socket fd=20, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.158.21.78', 48898), raddr=('172.217.166.234', 443)>
  tokenFields = goi.verify_oauth2_token(token, gatr.Request())
END 2019-07-08 13:17:07.173235 POST /datastreams/find_entries/timestamp ea4e449d-63b7-4e2c-892a-85f561029ce1 0.9061148166656494 
END 2019-07-08 13:17:07.175360 POST /datastreams/find_entries/timestamp ea4e449d-63b7-4e2c-892a-85f561029ce1 0.9100406169891357 
START 2019-07-08 13:17:09.359293 POST /pipeline/get_complete_ts
START 2019-07-08 13:17:09.361452 POST /timeline/getTrips/2019-07-08
/home/deepali/e-mission-server/emission/net/auth/google_auth.py:55: ResourceWarning: unclosed <socket.socket fd=20, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.158.21.78', 41050), raddr=('172.217.27.170', 443)>
  tokenFields = goi.verify_oauth2_token(token, gatr.Request())
END 2019-07-08 13:17:10.295829 POST /timeline/getTrips/2019-07-08 ea4e449d-63b7-4e2c-892a-85f561029ce1 0.9342741966247559 
/home/deepali/e-mission-server/emission/net/auth/google_auth.py:55: ResourceWarning: unclosed <socket.socket fd=21, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.158.21.78', 42902), raddr=('173.194.76.95', 443)>
  tokenFields = goi.verify_oauth2_token(token, gatr.Request())
END 2019-07-08 13:17:10.699677 POST /pipeline/get_complete_ts ea4e449d-63b7-4e2c-892a-85f561029ce1 1.3402705192565918 
START 2019-07-08 13:17:11.401184 POST /datastreams/find_entries/timestamp
/home/deepali/e-mission-server/emission/net/auth/google_auth.py:55: ResourceWarning: unclosed <socket.socket fd=20, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.158.21.78', 34412), raddr=('172.217.160.234', 443)>
  tokenFields = goi.verify_oauth2_token(token, gatr.Request())
END 2019-07-08 13:17:12.255403 POST /datastreams/find_entries/timestamp ea4e449d-63b7-4e2c-892a-85f561029ce1 0.8540947437286377 
START 2019-07-08 13:17:12.740202 POST /datastreams/find_entries/timestamp
START 2019-07-08 13:17:12.764889 POST /datastreams/find_entries/timestamp
/home/deepali/e-mission-server/emission/net/auth/google_auth.py:55: ResourceWarning: unclosed <socket.socket fd=21, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.158.21.78', 47114), raddr=('216.58.200.170', 443)>
  tokenFields = goi.verify_oauth2_token(token, gatr.Request())
END 2019-07-08 13:17:13.623100 POST /datastreams/find_entries/timestamp ea4e449d-63b7-4e2c-892a-85f561029ce1 0.8581020832061768 
/home/deepali/e-mission-server/emission/net/auth/google_auth.py:55: ResourceWarning: unclosed <socket.socket fd=20, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('10.158.21.78', 50422), raddr=('172.217.167.42', 443)>
  tokenFields = goi.verify_oauth2_token(token, gatr.Request())
END 2019-07-08 13:17:13.694623 POST /datastreams/find_entries/timestamp ea4e449d-63b7-4e2c-892a-85f561029ce1 0.954308271408081 

Not sure whether it is a connection to server issue.

[deepalics0044]

After the installation 6th July. I did travel many times.

[deepalics0044]

I don't get "emTripLog has started tracking" prompt when I travel. No trips in the diary.

[shankari]

In terms of trips being tracked in this installation, we got a tracking error fairly soon after the installation.

884,1562362615.8,2019-07-06T03:06:55.800000+05:30,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@5b777f9, Intent { act=local.transition.tracking_error flg=0x10 pkg=edu.berkeley.eecs.embase cmp=edu.berkeley.eecs.embase/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"

which appears to be because location services was turned off (https://github.com/e-mission/e-mission-data-collection/blob/9ffb867e3af7e4c36dc9d9f0f094b7d0510a9287/src/android/location/GeofenceExitIntentService.java#L77)

880,1562362615.7329998,2019-07-06T03:06:55.733000+05:30,GeofenceExitIntentService : got geofence intent callback with type -1 and location null
881,1562362615.735,2019-07-06T03:06:55.735000+05:30,GeofenceExitIntentService : Found error 1000 generating tracking error

During the next periodic check, we do re-initialize the FSM, but that is after noon, so the morning trip is skipped.

914,1562396814.87,2019-07-06T12:36:54.870000+05:30,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
923,1562396814.9029999,2019-07-06T12:36:54.903000+05:30,"TripDiaryStateMachineRcvr : Still in start state, sending initialize..."
1003,1562396815.63,2019-07-06T12:36:55.630000+05:30,TripDiaryStateMachineService : newState after handling action is local.state.waiting_for_trip_start
1004,1562396815.637,2019-07-06T12:36:55.637000+05:30,TripDiaryStateMachineService : newState saved in prefManager is local.state.waiting_for_trip_start

this happens again at

1372,1562397063.018,2019-07-06T12:41:03.018000+05:30,GeofenceExitIntentService : parsedEvent = com.google.android.gms.location.GeofencingEvent@7df085f
1373,1562397063.018,2019-07-06T12:41:03.018000+05:30,GeofenceExitIntentService : got geofence intent callback with type -1 and location null
1374,1562397063.018,2019-07-06T12:41:03.018000+05:30,GeofenceExitIntentService : Found error 1000 generating tracking error

and tracking is only turned on at

1412,1562406038.351,2019-07-06T15:10:38.351000+05:30,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
1422,1562406038.393,2019-07-06T15:10:38.393000+05:30,"TripDiaryStateMachineRcvr : Still in start state, sending initialize..."
1483,1562406038.599,2019-07-06T15:10:38.599000+05:30,TripDiaryStateMachineService : newState after handling action is local.state.waiting_for_trip_start
1484,1562406038.6,2019-07-06T15:10:38.600000+05:30,TripDiaryStateMachineService : newState saved in prefManager is local.state.waiting_for_trip_start

Are you sure your location services are turned on, and you have WiFi and data turned on?

[shankari]

At this point, this does not appear to be related to the UX update, but rather, to the tracking error that is periodically generated on your phone.

[shankari]

And checking the more recent logs that you sent, we got a tracking error

1707,1562411136.917,2019-07-06T16:35:36.917000+05:30,GeofenceExitIntentService : geofence exit intent action = null
1708,1562411136.917,2019-07-06T16:35:36.917000+05:30,GeofenceExitIntentService : parsedEvent = com.google.android.gms.location.GeofencingEvent@6bda092
1709,1562411136.918,2019-07-06T16:35:36.918000+05:30,GeofenceExitIntentService : got geofence intent callback with type -1 and location null
1710,1562411136.918,2019-07-06T16:35:36.918000+05:30,GeofenceExitIntentService : Found error 1000 generating tracking error

and then there are no logs until the 8th when we are launched again for the periodic sync which

1736,1562411137.053,2019-07-06T16:35:37.053000+05:30,TripDiaryStateMachineService : About to stop service after handling [local.transition.tracking_error]
1737,1562411137.056,2019-07-06T16:35:37.056000+05:30,TripDiaryStateMachineService : About to disconnect the api client
1738,1562411137.0570002,2019-07-06T16:35:37.057000+05:30,"TripDiaryStateMachineService : Service destroyed. So long, suckers!"
1739,1562411137.0579998,2019-07-06T16:35:37.058000+05:30,"TripDiaryStateMachineForegroundService : onDestroy called, removing notification"
<---- no logs here ---->
1740,1562569657.309,2019-07-08T12:37:37.309000+05:30,BuiltinUserCache : Added value for key stats/client_nav_event at time 1.5625696573E9
1741,1562569657.311,2019-07-08T12:37:37.311000+05:30,BuiltinUserCache : Added value for key background/battery at time 1.562569657311E9
1742,1562569657.316,2019-07-08T12:37:37.316000+05:30,"ServerSyncAdapter : introDoneResult = {""intro_done"":""2019-07-06T03:04:28+05:30""}"
1743,1562569657.316,2019-07-08T12:37:37.316000+05:30,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
...
1751,1562569657.35,2019-07-08T12:37:37.350000+05:30,"TripDiaryStateMachineRcvr : Still in start state, sending initialize..."

I am not sure why you consistently get an erroneous geofence exit, if you are not turning location services or WiFi on/off, but that is the root cause of your problem.

[deepalics0044]

Okay I again travelled with the location ON and made sure that no Wifi connects to it. I can see the trips and mode and purpose prompt.

[shankari]

I can see the trips and mode and purpose prompt.

Great!

and made sure that no Wifi connects to it

Just to clarify, you should be connected to WiFi. The geofence works best when connected to both WiFi and cellular data.

Also, couple of follow ups from the testing to improve long-term robustness...

• did you see a notification related to the tracking_error, at around these times?

884,1562362615.8,2019-07-06T03:06:55.800000+05:30,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@5b777f9, Intent { act=local.transition.tracking_error flg=0x10 pkg=edu.berkeley.eecs.embase cmp=edu.berkeley.eecs.embase/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"
1375,1562397063.025,2019-07-06T12:41:03.025000+05:30,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@8dbb154, Intent { act=local.transition.tracking_error flg=0x10 pkg=edu.berkeley.eecs.embase cmp=edu.berkeley.eecs.embase/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"
1560,1562406208.055,2019-07-06T15:13:28.055000+05:30,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@8dbb154, Intent { act=local.transition.tracking_error flg=0x10 pkg=edu.berkeley.eecs.embase cmp=edu.berkeley.eecs.embase/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"
1713,1562411136.94,2019-07-06T16:35:36.940000+05:30,"TripDiaryStateMachineRcvr : TripDiaryStateMachineReciever onReceive(android.app.ReceiverRestrictedContext@8dbb154, Intent { act=local.transition.tracking_error flg=0x10 pkg=edu.berkeley.eecs.embase cmp=edu.berkeley.eecs.embase/edu.berkeley.eecs.emission.cordova.tracker.location.TripDiaryStateMachineReceiver }) called"

• I noticed that although the background operations were invoked quite frequently on the 6th, they were not invoked at all on the 7th. This is obviously something that android determines but I'm wondering if there was something that you did on the afternoon/night of the 6th that caused android to deprioritize this app.

/tmp/loggerDB.new_ux_not_working.newlogs.withdate.log:914,1562396814.87,2019-07-06T12:36:54.870000+05:30,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
/tmp/loggerDB.new_ux_not_working.newlogs.withdate.log:930,1562396814.908,2019-07-06T12:36:54.908000+05:30,TripDiaryStateMachineRcvr : END PERIODIC ACTIVITY

******* ~ 1.5 hours ********

/tmp/loggerDB.new_ux_not_working.newlogs.withdate.log:1412,1562406038.351,2019-07-06T15:10:38.351000+05:30,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
/tmp/loggerDB.new_ux_not_working.newlogs.withdate.log:1431,1562406038.4,2019-07-06T15:10:38.400000+05:30,TripDiaryStateMachineRcvr : END PERIODIC ACTIVITY

******* ~ 1 hour ********

/tmp/loggerDB.new_ux_not_working.newlogs.withdate.log:1592,1562409532.7189999,2019-07-06T16:08:52.719000+05:30,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
/tmp/loggerDB.new_ux_not_working.newlogs.withdate.log:1608,1562409532.93,2019-07-06T16:08:52.930000+05:30,TripDiaryStateMachineRcvr : END PERIODIC ACTIVITY

******* ~ 42 hours !!! ********

/tmp/loggerDB.new_ux_not_working.newlogs.withdate.log:1743,1562569657.316,2019-07-08T12:37:37.316000+05:30,TripDiaryStateMachineRcvr : START PERIODIC ACTIVITY
/tmp/loggerDB.new_ux_not_working.newlogs.withdate.log:1759,1562569657.357,2019-07-08T12:37:37.357000+05:30,TripDiaryStateMachineRcvr : END PERIODIC ACTIVITY

Thanks!

[shankari]

Once you answer the followups, I will close this issue

[deepalics0044]

did you see a notification related to the tracking_error, at around these times?

Yup I saw 6 tracking_error altogether.

[shankari]

Also received logs from an iOS phone reporting a similar issue. On investigation, this also turned out to be a similar root cause - the entire app was reinstalled

0,1562578283.76081,2019-07-08T02:31:23.760810-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler
1,1562578283.76504,2019-07-08T02:31:23.765040-07:00,intro_done result = (null)

and there was apparently an issue while creating the geofence.

114,1562578497.6755,2019-07-08T02:34:57.675500-07:00,"Monitoring failed for region CLCircularRegion (identifier:'STATIONARY_GEOFENCE_LOCATION', center:<redacted>, radius:100.00m) with error Error Domain=kCLErrorDomain Code=4 ""(null)"""

Since the geofence creation failed, there was no further tracking.

Judging from the documentation, https://developer.apple.com/documentation/corelocation/clerror?language=objc this corresponds

kCLErrorRegionMonitoringDenied
A constant indicating that access to the region monitoring service was denied by the user.

I suspect that the user has provided only "when in use" permissions, not "always".

[shankari]

It is not clear why users are uninstalling and reinstalling the native app for a UI-only update.
Recall from the architecture of the app that the sensing is in a separate module from the UI and is not typically affected by it. You should be able to click on the button to check for UI updates and update the UI of the existing native app.

[deepalics0044]

It is not clear why users are uninstalling and reinstalling the native app for a UI-only update.

The reason why is we can't see the update for the cistup-ec channel. We didn't go to the updates tab. Whenever I make any new changes to Logtrip I get a UI update prompt but I clearly understand why its not with the emTripLog as we have different channels we need to update from button.

I'll make sure other user while updating use update button.

[deepalics0044]

I suspect that the user has provided only "when in use" permissions, not "always".

Checking on that.

[shankari]

You should also get a prompt to apply the UI-only update when you launch the app. This has clearly worked before (see #359). I'm a bit surprised that it is not working now.

Sometimes, if there are race conditions, the prompt may not display on the first launch after the update, but it should show up in the first couple of launches.

[shankari]

Closing this issue if there are no additional concerns.