Trips not recorded on iOS

[MythriNagaraju]

@shankari : After I merged changes to update the sdk to 26 and switch dynamic permissions, the iOS app is not recording trips at all. I also do not see any errors in the XCode log. Is anyone else running into this issue?

[shankari]

@MythriNagaraju none of the changes to update the SDK to 26 applied to iOS, so I have not tested or released a new iOS version. I can't think of any obvious reasons why the plugin updates (the only changes to iOS) should have broken tracking, but you might want to try syncing to tag 2.7.1 (https://github.com/e-mission/e-mission-phone/releases/tag/v2.7.1) and rebuilding on iOS.

That is the version currently in the stores and being tested by users. If that also does not work for you, let me know and I can help you troubleshoot.

[MythriNagaraju]

Thanks @shankari , I'll try doing that. I am using cordova version 8.0.0. Could that be a problem?

[shankari]

@MythriNagaraju I don't think so - the README recommends using cordova 8.0.0 since Jan 2018
https://github.com/e-mission/e-mission-phone/blame/master/README.md#L159
so that is what I must have used to build the working version in the stores.

[MythriNagaraju]

Okay, this time I double checked that the location tracking button was on and both iOS and android apps are recording trips. Although nothing is being logged on the server. I emailed you the log. Would you be able to take a look please? Thanks!

[shankari]

@MythriNagaraju I checked your logs and there was an network error while connecting to the server.

412,1555353367.36028,2019-04-15 11:36:07.360280-07:53,postToHost called with url = /usercache/put -- <redacted>
413,1555353367.37789,2019-04-15 11:36:07.377890-07:53,received response for server_to_phone
414,1555353367.39146,2019-04-15 11:36:07.391460-07:53,"Got error Error Domain=NSURLErrorDomain Code=-1009 ""The Internet connection appears to be offline."" UserInfo={_kCFStreamErrorCodeKey=50, NSUnderlyingError=0x28316b360 {Error Domain=kCFErrorDomainCFNetwork Code=-1009 ""(null)"" UserInfo={_kCFStreamErrorCodeKey=50, _kCFStreamErrorDomainKey=1}}, _NSURLErrorFailingURLSessionTaskErrorKey=LocalDataTask <B7967537-6011-4C6D-86DA-AEC1B3485708>.<1>, _NSURLErrorRelatedURLSessionTaskErrorKey=(
    ""LocalDataTask <B7967537-6011-4C6D-86DA-AEC1B3485708>.<1>""
), NSLocalizedDescription=The Internet connection appears to be offline., NSErrorFailingURLStringKey=<redacted>, NSErrorFailingURLKey=<redacted>, _kCFStreamErrorDomainKey=1} while retrieving data"
415,1555353367.4030302,2019-04-15 11:36:07.403030-07:53,"Got error Error Domain=NSURLErrorDomain Code=-1009 ""The Internet connection appears to be offline."" UserInfo={_kCFStreamErrorCodeKey=50, NSUnderlyingError=0x2831b1fb0 {Error Domain=kCFErrorDomainCFNetwork Code=-1009 ""(null)"" UserInfo={_kCFStreamErrorCodeKey=50, _kCFStreamErrorDomainKey=1}}, _NSURLErrorFailingURLSessionTaskErrorKey=LocalDataTask <8BB727BD-06B0-4842-93C8-1226CF2E1E98>.<1>, _NSURLErrorRelatedURLSessionTaskErrorKey=(
    ""LocalDataTask <8BB727BD-06B0-4842-93C8-1226CF2E1E98>.<1>""
), NSLocalizedDescription=The Internet connection appears to be offline., NSErrorFailingURLStringKey=<redacted>, NSErrorFailingURLKey=<redacted>/usercache/put, _kCFStreamErrorDomainKey=1} while pushing changes to server, retaining data"
416,1555353367.4209301,2019-04-15 11:36:07.420930-07:53,"After clear complete, cache has entries stats/client_nav_event, connection_settings, config/sensor_config, statemachine/transition, background/battery, config/sync_config, stats/client_time, intro_done, config/consent, data_collection_consented_protocol, diary_tutorial_done, background/location, background/filtered_location"

[shankari]

@MythriNagaraju You can check the logs yourself and confirm. There is documentation on how to make the emailed database human readable in

https://github.com/e-mission/e-mission-docs/blob/master/docs/e-mission-phone/troubleshooting_tips_faq.md#reading-the-log-on-your-computer

You can also browse logs using the Profile -> Developer Zone -> Check Log

[MythriNagaraju]

Thank you - I am looking at the .csv file now. I was connected to the server when I force-synced. And force-sync worked from the android app at the same time.

[shankari]

But was your iPhone connected to WiFi or a data plan?

[MythriNagaraju]

Yes!

[shankari]

were you able to access the server (https://....) from safari on the iPhone?

[MythriNagaraju]

Yes, I was able to.

Also, I see this error in the logs while trying to push data to the server:

Error Domain=com.google.HTTPStatus Code=413 ""(null)""

Have you seen this before?

[shankari]

hm, status code 413 is "Payload Too Large"
https://developer.mozilla.org/en-US/docs/Web/HTTP/Status/413

That is basically a dup of #283
They were using e-mission behind a reverse proxy, and hadn't bumped up the max request size on the proxy to match the size in e-mission.

They submitted a doc fix (#47) I requested changes, but haven't received a response yet. But you can use the doc fix directly :)

[shankari]

I am not quite sure about why you should be hitting this though. The previous team that ran into this was returning survey results, and our speculation was that the survey result sizes were big. But you are not using surveys. Let me take a closer look.

[shankari]

But you should definitely bump up the max size in the short-term because I know that will fix it.

[MythriNagaraju]

I did bump up the max size in cfc_webapp.py , but that will not work because the server is behind a reverse proxy. I cannot use that doc fix though because in my case the web server is on a windows server and behind a IIS webserver proxy.

[MythriNagaraju]

I am looking into how I can increase request size in IIS webserver proxy

[shankari]

I also took a slightly closer look at this, and there were apparently two failures because of internet connectivity issues.

412,1555353367.36028,2019-04-15 11:36:07.360280-07:53,postToHost called with url = /usercache/put -- https://databucket.lbl.gov
413,1555353367.37789,2019-04-15 11:36:07.377890-07:53,received response for server_to_phone
414,1555353367.39146,2019-04-15 11:36:07.391460-07:53,"Got error Error Domain=NSURLErrorDomain Code=-1009 ""The Internet connection appears to be offline."" 
--
553,1555353809.46131,2019-04-15 11:43:29.461310-07:53,postToHost called with url = /usercache/put -- https://databucket.lbl.gov
554,1555353809.48131,2019-04-15 11:43:29.481310-07:53,received response for server_to_phone
555,1555353809.4922302,2019-04-15 11:43:29.492230-07:53,"Got error Error Domain=NSURLErrorDomain Code=-1009 ""The Internet connection appears to be offline.""

And then after that was resolved, we started getting the 413 error

771,1555355376.78225,2019-04-15 12:09:36.782250-07:53,postToHost called with url = /usercache/put -- https://databucket.lbl.gov
772,1555355376.84644,2019-04-15 12:09:36.846440-07:53,"Got error Error Domain=com.google.HTTPStatus Code=413 ""(null)"" UserInfo={data=<54686520 70616765 20776173 206e6f74 20646973 706c6179 65642062 65636175 73652074 68652072 65717565 73742065 6e746974 79206973 20746f6f 206c6172 67652e>, data_content_type=text/html} while pushing changes to server, retaining data"
773,1555355376.8812802,2019-04-15 12:09:36.881280-07:53,received response for server_to_phone
774,1555355376.88684,2019-04-15 12:09:36.886840-07:53,Got non NULL data while retrieving data

--
794,1555355438.91301,2019-04-15 12:10:38.913010-07:53,postToHost called with url = /usercache/put -- https://databucket.lbl.gov
795,1555355438.97838,2019-04-15 12:10:38.978380-07:53,"Got error Error Domain=com.google.HTTPStatus Code=413 ""(null)"" UserInfo={data=<54686520 70616765 20776173 206e6f74 20646973 706c6179 65642062 65636175 73652074 68652072 65717565 73742065 6e746974 79206973 20746f6f 206c6172 67652e>, data_content_type=text/html} while pushing changes to server, retaining data"
796,1555355439.00019,2019-04-15 12:10:39.000190-07:53,received response for server_to_phone
797,1555355439.0062,2019-04-15 12:10:39.006200-07:53,Got non NULL data while retrieving data

Looking at the actual data sent for the last two calls, we find

769,1555355376.7695,2019-04-15 12:09:36.769500-07:53,159 locationArray + 26 motionEntries = 185 combinedArray
792,1555355438.89831,2019-04-15 12:10:38.898310-07:53,165 locationArray + 28 motionEntries = 193 combinedArray

Those don't seem to be abnormally high.
@MythriNagaraju since you are building your own app, you can add a log statement just before sending the data to see the data size.
https://github.com/e-mission/cordova-server-communication/blob/master/src/ios/BEMCommunicationHelper.m#L168

[MythriNagaraju]

thanks for looking into this @shankari. I'll try that. So far, I tried bumping up the max size and re-starting the server , but haven't taken any trips since.

[shankari]

@MythriNagaraju you don't need to take any more trips - all the data from your previous trips is still cached in the app. You can try "Force sync" and see if the push works this time.

[MythriNagaraju]

Did not work. Same error again

**CommunicationHelper : Got response org.apache.http.message.BasicHttpResponse@23a5fa6 with statusHTTP/1.1 413 Request Entity Too Large

ServerSyncAdapter : IO Error java.io.IOException while posting converted trips to JSON**

On iOS , I get this error additionally. Fails on this line if (entry.metadata.key == getEndTransition()) {.

I also noticed that the trip ends are not detected correctly on iOS but they are on Android. Is that expected.

[MythriNagaraju]

Could be also related to this ? #333

[shankari]

@MythriNagaraju

**CommunicationHelper : Got response org.apache.http.message.BasicHttpResponse@23a5fa6 with statusHTTP/1.1 413 Request Entity Too Large

in that case you have not bumped up the max size correctly. Have you bumped up the max size on the reverse proxy? the max size on e-mission should be fine.

On iOS , I get this error additionally. Fails on this line if (entry.metadata.key == getEndTransition()) {.

Well, I don't think that is an additional error. The force sync is failing, and you are getting an error popup. I would defer the investigation of #378 until you get the force sync to actually work.

[MythriNagaraju]

sorry, I meant on Android I don't get an error on Force Sync but on iOS I do.

[shankari]

@MythriNagaraju no I don't think this is related to #333 since according to the iOS documentation, it uses UTF-8 by default. And you are not using a locale that would generate non-ASCII characters. And even if it were, we would get error 500, not error 413.

You just have to figure out how to bump up the max size on your reverse proxy.

[shankari]

@MythriNagaraju a quick way to confirm whether the issue is with the app or with the reverse proxy is to configure the app to connect directly to the e-mission server, skipping the reverse proxy. This may only work when you are on the LBL campus, connected to the local network, but you can use "Force Sync" at work, for example.

• If the connection directly to the e-mission server works, you need to reconfigure the reverse proxy.
• If even the connection directly to the e-mission server does not work, then we should debug that case further.

[shankari]

@MythriNagaraju if I don't get updates from you on this by EOD, I plan to close this issue since it is not related to the platform in general, but rather to your specific configuration.
Apparently, the standard IIS message size is 64kb and there are well known techniques for increasing it, even for specific end points.
https://duckduckgo.com/?q=IIS+message+size&t=ffsb&ia=web

[MythriNagaraju]

I still haven't tried connecting to the e-mission-server directly, but I am going to try now. Thank you for that IIS link!

[shankari]

@MythriNagaraju what was the result of the test?

[MythriNagaraju]

I bumped up the size and I no longer get the http 413 error, but I still don't see trips in the usercache on the server. Doing some more testing. Will report back.

[MythriNagaraju]

Now, connection to server is timing out!

[MythriNagaraju]

Trying another config change. Since this is all specific to IIS webserver, if you want , you can close this issue. Or when I get it to work, I can document what worked.

[shankari]

would be great if you could document what worked!

[MythriNagaraju]

I modified the config on the IIS server to increase the max size and I am no longer running into the HTTP 413 error, although now I see a 403 forbidden error. The app server is up and running without any issues. I can also see "inserting entry" in the web server logs. Have you run into this before?

loggerDB (5).withdate.log

[shankari]

@MythriNagaraju "403 forbidden" typically means that the authentication is not working properly. Are your phone and server authentications consistent? Just because you can see "inserting entry" in the web server logs doesn't mean that the data is getting to the server - we also insert entries for the server api time, for example.

You need to look at the messages around auth and the mapping from the email to the uuid at
https://github.com/e-mission/e-mission-docs/blob/master/docs/e-mission-server/troubleshooting_tips_FAQ.md

[MythriNagaraju]

@shankari how do I make sure that the phone and server authentications are consistent?

[MythriNagaraju]

@shankari Is there anything in the logs apart from the 403 error that you think is unusual?

loggerDB (7).withdate.log

[shankari]

@MythriNagaraju you should have configured the phone and server authentications using
https://github.com/e-mission/e-mission-docs/blob/487edf956bf92c2f8f06647f25e33b7330729e4f/docs/e-mission-both/configuring_authentication.md
so you would ensure that you have configured them using the same method...

[shankari]

@MythriNagaraju I would suggest doing further debugging on the server, not the phone.

You need to look at the messages around auth and the mapping from the email to the uuid at
https://github.com/e-mission/e-mission-docs/blob/master/docs/e-mission-server/troubleshooting_tips_FAQ.md

[MythriNagaraju]

thanks @shankari . Currently, the auth method in conf/net/api/webserver.conf is "skip" and the auth method in connectionConfig.json is "prompted-auth". Is that correct?

[shankari]

that should be fine (it is basically no authentication). What do you see in

the messages around auth and the mapping from the email to the uuid at
https://github.com/e-mission/e-mission-docs/blob/master/docs/e-mission-server/troubleshooting_tips_FAQ.md

[MythriNagaraju]

I see this:

2019-04-30 01:14:13,804:DEBUG:10128:START POST /usercache/get
2019-04-30 01:14:13,805:DEBUG:10128:Called userCache.get
2019-04-30 01:14:13,805:DEBUG:10128:methodName = skip, returning <class 'emission.net.auth.skip.SkipMethod'>
2019-04-30 01:14:13,805:DEBUG:10128:Using the skip method to verify id token my3_apr19_android:5723 of length 22
2019-04-30 01:14:13,807:DEBUG:10128:retUUID = None
2019-04-30 01:14:13,807:DEBUG:10128:END POST /usercache/get None 0.0030012130737304688

It never finds/returns the UUID?

[shankari]

did you register to this server with the username my3_apr19_android:5723 before? (e.g. go through the onboarding successfully?)

If not, please log out and log in again.
Also, in case you are doing this, please use different tokens for android and iOS - logging in with the same token can break the analysis since we don't know which data came from which device.

[MythriNagaraju]

That worked @shankari !

2019-04-30 11:32:17,756:DEBUG:2688:START POST /usercache/get
2019-04-30 11:32:17,757:DEBUG:2688:Called userCache.get
2019-04-30 11:32:17,757:DEBUG:2688:methodName = skip, returning <class 'emission.net.auth.skip.SkipMethod'>
2019-04-30 11:32:17,757:DEBUG:2688:Using the skip method to verify id token my3_apr19_android:5733:5723 of length 27
2019-04-30 11:32:17,759:DEBUG:2688:retUUID = 1a62316b-4bdb-4058-a32f-44a39604b036
2019-04-30 11:32:17,759:DEBUG:2688:user_uuid 1a62316b-4bdb-4058-a32f-44a39604b036
2019-04-30 11:32:17,763:DEBUG:2688:END POST /usercache/get 1a62316b-4bdb-4058-a32f-44a39604b036 0.007007122039794922

I am now able to see the 'background/location' entries in the usercache table for that user too. Thanks so much! Going to test on iOS now.

[shankari]

Yay! obviously, in your real deployment, your users would go through the onboarding on the correct server, so this would not be an issue :)

[MythriNagaraju]

Right!

[MythriNagaraju]

@shankari Are the modes of the trips written to any of the tables in the MongoDB database? Or can they be inferred from the data in the tables in any way?

[shankari]

https://github.com/e-mission/e-mission-server#experimenting-with-loaded-data

Also, did you look for prior issues - e.g.
#350

[shankari]

closing this for now, since trip recording on iOS has obviously been resolved.
Please file a new issue or reopen an existing issue to understand the data access better.

[shankari]

You may also find this useful.
shankari_mobility_diary_pipeline_5_1.pdf