SSL connection issues (android only?)

[PatGendre]

@shankari
we have a user doing a benchmark of 5 mobility tracking apps : itinerum, travelvu, motiontag, woorti, and e-mission/fabmob. She has 9 phones (2 Iphone, 7 android).

She called me this week because the app was very slow and in practice so slow it was not usable.
After her call, I realised that she started the tests but in early september, but I did notice it because no users were added on the server side in mongo (and there is no sign of activity in the server logs for these users). On several if not all of her phones, the app is launched since 2 weeks and has accumulated data locally but is actually not connected to the server.

What seem to be the explanation is that she actually created the users in our openid keycloak server in July, and installed the apps on the phones also in July, just a few days before our mongo db was dropped by an indonesian attacker. Loic restored previous data but we lost 15 days, including the 9 test users.

As I said, in the webserver logs we don't see the test users, and we don't find it either in the uuid collection.
In the app logs we have this error: ServerSyncAdapter : IO Error java.net.SocketTimeoutException: SSL handshake timed out while posting converted trips to JSON
I cannot find this particular error in the server sync plugin code, what does it mean?

The problem may be in the openid auth code, either on the server or on the app side ?
In our case here : when the user opens the app, accepts the terms of use and logs in, the openid will validate the credentials, but then there is no user with this e-mail in mongo. So the correct behavior should then be to create a new e-mission user, but apparently this is not what happens. No user is added, but the user is allowed to use the app although he/she is not connected.

Thanks in advance when you have time to investigate this.

[shankari]

Hm, this is super interesting and weird. First, some comments about the architecture:

• Yes, the app works even when the user is not actively connected. This is by design to ensure robustness - e.g. you want data collection to work even in conditions with poor/no connectivity and recover gracefully when conditions are correct again
• the desired behavior that you outline does happen when the user logs in. So if the user selects the "login via X" option and logs in, and there is no existing user in the database, the user will be created. After all, that is what happens when the user logs in for the first time.

Second, if the user has already logged in, but the user mapping in the uuid_db is removed, then we don't currently create a new user. Instead, the getUUID(request) call - e.g. in
https://github.com/e-mission/e-mission-server/blob/e05cf31486f74342d2749a672c27cdd3b75090e3/emission/net/api/cfc_webapp.py#L238
will return None and the call will fail. This is not specific to the OpenID auth case; it happens for any auth method if the underlying DB is deleted.

A workaround should be to logout and login again. As Yann points out, logging out will not delete any of the store information, logging in will restore the entry to the uuid db and then all the accumulated data should slowly make its way to the server.

[shankari]

It should also be possible to change /usercache/put so that it creates a user if one does not exist. However, given that this is a corner case (underlying values deleted from database), it seems like requiring a login before accepting data is a reasonable restriction.

[PatGendre]

Thanks for the explanation, I understand why the app should even if no connection is available.

A workaround should be to logout and login again.
Unfortunately the user has tried to logout and login again and it seems it didn't work. Do you see why it could be?
Anyhow I have ask her to try again, I'll tell you if this works... Otherwise she will create new logins and lose the accumulated tracks, it is not so big a problem: more annoying is the fact that she lost time with an app not working as it should.

[shankari]

Unfortunately the user has tried to logout and login again and it seems it didn't work. Do you see why it could be?

I can't figure that out without logs. Some potential investigation avenues are:

• confirm that you are in fact getting a successful /usercache/put call that errors out with a None response from getUUID(request)
  • this will ensure that the call is making it through to the server correctly and the failure mode is indeed because of the missing entries in the uuid_db
• look for /profile/create and /profile/update calls from around the time that the user tried to logout and login
  • that will let you know why the logout/login did not work

[PatGendre]

Ok thank you!

• looking for a None response from getUUID(request) implies to add a log instruction in the code I suppose, I will check that next week with Yann (but I am again in Paris next monday+tuesday...)
  I hope I can solve that next week, though.

[PatGendre]

UPDATE : I now see the test user in the webserver logs, so she has tried again to logout and login, and this has worked :-))

[PatGendre]

@shankari I was too optimistic :
I see several lines like this in the logs
2019-09-20 18:32:21,386:DEBUG:139931868665600:decoded_json = {'jti': 'bfa0795a-a78b-47db-b717-f3ccd203065c', 'exp': 1568997434, 'nbf': 0, 'iat': 1568997134, 'iss': 'https://id.indie.host/auth/realms/fabmob-io', 'aud': 'traceur', 'sub': 'f3abc6a4-9e7d-4156-970a-21a8f362df03', 'typ': 'ID', 'azp': 'traceur', 'auth_time': 1563884632, 'session_state': 'fa4cd62b-b0a6-45d2-a70d-fc1de4e441ac', 'acr': '1', 'email_verified': False, 'name': 'Cerema Teltest05', 'preferred_username': 'teltest05', 'given_name': 'Cerema', 'family_name': 'Teltest05', 'email': 'teltestcerema05@gmail.com'} 2019-09-20 18:32:21,386:DEBUG:139931868665600:After verifying claim, returning valid email = teltestcerema05@gmail.com 2019-09-20 00:21:38,357:DEBUG:139931877058304:retUUID = None 2019-09-20 00:21:38,357:DEBUG:139931877058304:END POST /usercache/put None 1.2417240142822266
So I can suppose that she did NOT logout ?
And actually I don't see any profile/creata

[shankari]

Yes, I don't think she logged out. This log snippet indicates that the token was decoded correctly and mapped to the teltestcerema05@gmail.com email address. But then that email address was not mapped to a UUID (retUUID = None).

Are there entries for teltestcerema05@gmail.com in the uuid db?

Also, do you see any recent calls to /usercache/put or /usercache/get?

[PatGendre]

Are there entries for teltestcerema05@gmail.com in the uuid db?

No

do you see any recent calls to /usercache/put or /usercache/get?

no, not really. But I noticed that another user had a None retuuid :-( So I contacted him and asked him to logout/login...

[shankari]

no, not really. But I noticed that another user had a None retuuid :-( So I contacted him and asked him to logout/login...

So then she really hasn't logged out/logged in. Maybe she just killed the app? That doesn't really change anything.

[PatGendre]

Hi, I called the test user again this morning, we tested together both on android and ios.
Reinstalling the app (or updating it on iOS), deleting all cache+user data on android both in the OS parameters and in the app in the Profile, but when she reconnects it still does not work. Her actions are not logged by the webserver, no new user is created in mongodb. We tested that her credentials are correct on the openid auth web client (in firefox).
So the error is mysterious for me, I suppose we need to log more info to understand what happens, I will see with Yann what we can do.

[shankari]

Reinstalling the app (or updating it on iOS), deleting all cache+user data on android both in the OS parameters and in the app in the Profile, but when she reconnects it still does not work.

Wait, so you uninstalled and reinstalled the app and there are still no connections to the webserver? That seems wrong. Can you check which host she is connected to? (Open Developer Zone and scroll to the bottom)