Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

❗ Login on fresh install resulting in dashboard error and "not logged in" #1002

Closed
Abby-Wheelis opened this issue Oct 5, 2023 · 24 comments

Comments

@Abby-Wheelis
Copy link
Member

When I uninstalled and reinstalled on my testing iPhone and Samsung devices, I witnessed similar "not logged in" behavior. In both cases, I scanned the opcode and followed the onboarding, but when I landed on the dashboard I saw an error, and when I navigated to the profile page it said "not logged in" where my opcode should display in the first row. In both cases logging out and logging back in restored the app to normal functionality. Screenshots below:

@Abby-Wheelis Abby-Wheelis moved this to Showstoppers for the current release in OpenPATH Tasks Overview Oct 5, 2023
@shankari
Copy link
Contributor

shankari commented Oct 5, 2023

@Abby-Wheelis is this reproducible? If you log out and log in again, does the same thing happen?

@Abby-Wheelis
Copy link
Member Author

Abby-Wheelis commented Oct 5, 2023 via email

@shankari
Copy link
Contributor

shankari commented Oct 5, 2023

if somebody can fix it by tonight, I can include it with e-mission/e-mission-phone#1050

@JGreenlee
Copy link

I have been unable to reproduce it in the devapp, even on a 'production' bundle.

@shankari
Copy link
Contributor

shankari commented Oct 5, 2023

we should look at logs from the test phones (Profile -> Email Log, instructions for looking beta test debugging are in the README). If the logs aren't enough to figure out what is wrong, we should add more logs to this release 😄

@Abby-Wheelis
Copy link
Member Author

I have downloaded the logs, but haven't been able to interpret them at the command line yet. I'll upload them here once I can get them into a readable format with the instructions

@JGreenlee
Copy link

It would be easier if we could just inspect staging releases. Is there a particular reason we don't make them inspectable?

@shankari
Copy link
Contributor

shankari commented Oct 5, 2023

No. I just use the default build settings for cordova. What do I need to do to make them inspectable?
I believe I do have to push a release version to the stores, if that is what is preventing it from being inspectable.

@Abby-Wheelis
Copy link
Member Author

I'll upload them here once I can get them into a readable format

The whole log is uploaded in Teams, and I pulled the coordinates out to include it here

,ts,dt,message
0,1696539118.86788,2023-10-05T13:51:58.867880-07:00,BEMJWTAuth:pluginInitialize singleton -> initialize completion handler
1,1696539118.87597,2023-10-05T13:51:58.875970-07:00,intro_done result = (null)
2,1696539118.87712,2023-10-05T13:51:58.877120-07:00,finished init of iOS native code
3,1696539118.87812,2023-10-05T13:51:58.878120-07:00,truncating obsolete entries before 1693947118.878059
4,1696539118.88209,2023-10-05T13:51:58.882090-07:00,"reqConsent = 2016-07-14, currConfig.approval_date = (null)"
5,1696539118.88315,2023-10-05T13:51:58.883150-07:00,isConsented = NO
6,1696539118.88427,2023-10-05T13:51:58.884270-07:00,intro_done result = (null)
7,1696539119.99035,2023-10-05T13:51:59.990350-07:00,ionicPlatform is ready
8,1696539119.99235,2023-10-05T13:51:59.992350-07:00,"while removing local storage, deleteQuery = DELETE FROM userCache WHERE (key = 'OP_GEOFENCE_CFG' AND type = 'local-storage')"
9,1696539119.99602,2023-10-05T13:51:59.996020-07:00,"STORAGE_PLUGIN: app launched, checking storage sync"
10,1696539120.13926,2023-10-05T13:52:00.139260-07:00,STORAGE_PLUGIN: Comparing web keys  with 
11,1696539120.14079,2023-10-05T13:52:00.140790-07:00,STORAGE_PLUGIN: Found native keys  missing native keys 
12,1696539120.14206,2023-10-05T13:52:00.142060-07:00,STORAGE_PLUGIN: Found web keys  missing web keys 
13,1696539120.14337,2023-10-05T13:52:00.143370-07:00,STORAGE_PLUGIN: Syncing all missing keys 
14,1696539120.14461,2023-10-05T13:52:00.144610-07:00,"STORAGE_PLUGIN: For the record, all unique native keys are stats/client_nav_event"
15,1696539120.14584,2023-10-05T13:52:00.145840-07:00,for key CONFIG_PHONE_UI uc_stored_val = null ls_stored_val = null
16,1696539120.14748,2023-10-05T13:52:00.147480-07:00,"local and native values match, already synced"
17,1696539120.14886,2023-10-05T13:52:00.148860-07:00,"No config found in KVStore, fetching from native storage"
18,1696539120.15017,2023-10-05T13:52:00.150170-07:00,for key CONFIG_PHONE_UI uc_stored_val = null ls_stored_val = null
19,1696539120.15144,2023-10-05T13:52:00.151440-07:00,"local and native values match, already synced"
20,1696539120.15264,2023-10-05T13:52:00.152640-07:00,"No config found in KVStore, fetching from native storage"
21,1696539120.1542,2023-10-05T13:52:00.154200-07:00,for key intro_done uc_stored_val = null ls_stored_val = null
22,1696539120.15559,2023-10-05T13:52:00.155590-07:00,"local and native values match, already synced"
23,1696539120.16021,2023-10-05T13:52:00.160210-07:00,No config found in native storage either. Returning null
24,1696539120.1622,2023-10-05T13:52:00.162200-07:00,No config found in native storage either. Returning null
25,1696539120.1874,2023-10-05T13:52:00.187400-07:00,for key CONFIG_PHONE_UI uc_stored_val = null ls_stored_val = null
26,1696539120.18939,2023-10-05T13:52:00.189390-07:00,"local and native values match, already synced"
27,1696539120.19055,2023-10-05T13:52:00.190550-07:00,"No config found in KVStore, fetching from native storage"
28,1696539120.19226,2023-10-05T13:52:00.192260-07:00,for key CONFIG_PHONE_UI uc_stored_val = null ls_stored_val = null
29,1696539120.19375,2023-10-05T13:52:00.193750-07:00,"local and native values match, already synced"
30,1696539120.19512,2023-10-05T13:52:00.195120-07:00,"No config found in KVStore, fetching from native storage"
31,1696539120.19669,2023-10-05T13:52:00.196690-07:00,for key CONFIG_PHONE_UI uc_stored_val = null ls_stored_val = null
32,1696539120.1987,2023-10-05T13:52:00.198700-07:00,"local and native values match, already synced"
33,1696539120.19987,2023-10-05T13:52:00.199870-07:00,"No config found in KVStore, fetching from native storage"
34,1696539120.20173,2023-10-05T13:52:00.201730-07:00,"required consent version = {""protocol_id"":""2014-04-6267"",""approval_date"":""2016-07-14""}"
35,1696539120.20667,2023-10-05T13:52:00.206670-07:00,No config found in native storage either. Returning null
36,1696539120.20841,2023-10-05T13:52:00.208410-07:00,No config found in native storage either. Returning null
37,1696539120.20994,2023-10-05T13:52:00.209940-07:00,No config found in native storage either. Returning null
38,1696539120.2121,2023-10-05T13:52:00.212100-07:00,for key data_collection_consented_protocol uc_stored_val = null ls_stored_val = null
39,1696539120.21454,2023-10-05T13:52:00.214540-07:00,"local and native values match, already synced"
40,1696539120.23105,2023-10-05T13:52:00.231050-07:00,"Both local and native consent not found, nothing to sync"
41,1696539127.48513,2023-10-05T13:52:07.485130-07:00,Received request to join stage-program
42,1696539127.49515,2023-10-05T13:52:07.495150-07:00,"Running in dev environment, checking for locally hosted config"
43,1696539127.49787,2023-10-05T13:52:07.497870-07:00,Local config not found
44,1696539127.50064,2023-10-05T13:52:07.500640-07:00,Received request to join stage-program
45,1696539127.50298,2023-10-05T13:52:07.502980-07:00,Fetching config from github
46,1696539127.84141,2023-10-05T13:52:07.841410-07:00,"Successfully found config, result is {""version"""
47,1696539127.8509,2023-10-05T13:52:07.850900-07:00,"fetchUrlCached: found no cached data for url json/demo-survey-v2.json, fetching"
48,1696539127.86292,2023-10-05T13:52:07.862920-07:00,Successfully downloaded config with version 1 for Staging environment for testing programs only and data collection URL https://openpath-stage.nrel.gov/api/
49,1696539127.87424,2023-10-05T13:52:07.874240-07:00,"fetchUrlCached: fetched data for url json/demo-survey-v2.json, returning"
50,1696539127.8767,2023-10-05T13:52:07.876700-07:00,"UI_CONFIG: Stored dynamic config in KVStore successfully, result = null"
51,1696539127.88277,2023-10-05T13:52:07.882770-07:00,"required consent version = {""protocol_id"":""2014-04-6267"",""approval_date"":""2016-07-14""}"
52,1696539127.88481,2023-10-05T13:52:07.884810-07:00,for key intro_done uc_stored_val = null ls_stored_val = null
53,1696539127.88665,2023-10-05T13:52:07.886650-07:00,"local and native values match, already synced"
54,1696539127.88854,2023-10-05T13:52:07.888540-07:00,for key data_collection_consented_protocol uc_stored_val = null ls_stored_val = null
55,1696539127.8902,2023-10-05T13:52:07.890200-07:00,"local and native values match, already synced"
56,1696539127.90021,2023-10-05T13:52:07.900210-07:00,"Both local and native consent not found, nothing to sync"
57,1696539127.93017,2023-10-05T13:52:07.930170-07:00,"connectionConfig = {""connectUrl"":""https://openpath-stage.nrel.gov/api/"",""aggregate_call_auth"":""user_only""}"
58,1696539127.93868,2023-10-05T13:52:07.938680-07:00,for key intro_done uc_stored_val = null ls_stored_val = null
59,1696539127.94017,2023-10-05T13:52:07.940170-07:00,"local and native values match, already synced"
60,1696539127.94129,2023-10-05T13:52:07.941290-07:00,"required consent version = {""protocol_id"":""2014-04-6267"",""approval_date"":""2016-07-14""}"
61,1696539127.94307,2023-10-05T13:52:07.943070-07:00,for key data_collection_consented_protocol uc_stored_val = null ls_stored_val = null
62,1696539127.94418,2023-10-05T13:52:07.944180-07:00,"local and native values match, already synced"
63,1696539127.94704,2023-10-05T13:52:07.947040-07:00,"Both local and native consent not found, nothing to sync"
64,1696539130.07196,2023-10-05T13:52:10.071960-07:00,for key intro_done uc_stored_val = null ls_stored_val = null
65,1696539130.07887,2023-10-05T13:52:10.078870-07:00,"local and native values match, already synced"
66,1696539130.08571,2023-10-05T13:52:10.085710-07:00,"required consent version = {""protocol_id"":""2014-04-6267"",""approval_date"":""2016-07-14""}"
67,1696539130.08866,2023-10-05T13:52:10.088660-07:00,for key data_collection_consented_protocol uc_stored_val = null ls_stored_val = null
68,1696539130.09032,2023-10-05T13:52:10.090320-07:00,"local and native values match, already synced"
69,1696539130.10394,2023-10-05T13:52:10.103940-07:00,"Both local and native consent not found, nothing to sync"
70,1696539132.57744,2023-10-05T13:52:12.577440-07:00,"changing consent from null -> {""protocol_id"":""2014-04-6267"",""approval_date"":""2016-07-14""}"
71,1696539132.59143,2023-10-05T13:52:12.591430-07:00,"required consent version = {""protocol_id"":""2014-04-6267"",""approval_date"":""2016-07-14""}"
72,1696539132.59474,2023-10-05T13:52:12.594740-07:00,for key data_collection_consented_protocol uc_stored_val = null ls_stored_val = null
73,1696539132.5965,2023-10-05T13:52:12.596500-07:00,"local and native values match, already synced"
74,1696539132.60891,2023-10-05T13:52:12.608910-07:00,"in getPriorConsent, currConfig = <ConsentConfig: 0x280c797a0>"
75,1696539132.61016,2023-10-05T13:52:12.610160-07:00,registered for visit notifications
76,1696539132.6116,2023-10-05T13:52:12.611600-07:00,initializing TripDiaryStateMachine with state = STATE_START
77,1696539132.63014,2023-10-05T13:52:12.630140-07:00,Returning combination of always = 0 and precise 1
78,1696539132.65818,2023-10-05T13:52:12.658180-07:00,"in getPriorConsent, currConfig = <ConsentConfig: 0x280c57c40>"
79,1696539132.65961,2023-10-05T13:52:12.659610-07:00,"allChecksPass = 0, but location checks fail, generating error and notification, allChecks: [loc settings, loc permissions, motion settings, motion permissions, notification] = (
    1,
    0,
    1,
    0,
    0
)"
80,1696539132.66092,2023-10-05T13:52:12.660920-07:00,"In TripDiaryStateMachine, received transition T_GEOFENCE_CREATION_ERROR in state STATE_START"
81,1696539132.66604,2023-10-05T13:52:12.666040-07:00,Moved from STATE_START to STATE_START
82,1696539132.66745,2023-10-05T13:52:12.667450-07:00,"Found existing field {
    redirectParams =     {
        launchAppStatusModal = 1;
    };
    redirectTo = ""root.main.control"";
}, retaining existing"
83,1696539132.66854,2023-10-05T13:52:12.668540-07:00,"Did not find existing field (null), filling in default {
    type = calendar;
}"
84,1696539132.66963,2023-10-05T13:52:12.669630-07:00,"Did not find existing field (null), filling in default {
    enabled = 0;
}"
85,1696539132.67186,2023-10-05T13:52:12.671860-07:00,"Initialized remote push notification handler <BEMRemotePushNotificationHandler: 0x280e675a0>, finished registering for notifications "
86,1696539132.67312,2023-10-05T13:52:12.673120-07:00,"In checker's didChangeAuthorizationStatus, new authorization status = 0, always = 3"
87,1696539132.67408,2023-10-05T13:52:12.674080-07:00,"No foreground delegate found, calling SensorControlBackgroundChecker from didChangeAuthorizationStatus to verify location service status and permission"
88,1696539132.67647,2023-10-05T13:52:12.676470-07:00,Returning combination of always = 0 and precise 1
89,1696539132.70766,2023-10-05T13:52:12.707660-07:00,"in getPriorConsent, currConfig = <ConsentConfig: 0x280c26760>"
90,1696539132.70886,2023-10-05T13:52:12.708860-07:00,"allChecksPass = 0, but location checks fail, generating error and notification, allChecks: [loc settings, loc permissions, motion settings, motion permissions, notification] = (
    1,
    0,
    1,
    0,
    0
)"
91,1696539132.70991,2023-10-05T13:52:12.709910-07:00,"In TripDiaryStateMachine, received transition T_GEOFENCE_CREATION_ERROR in state STATE_START"
92,1696539132.71303,2023-10-05T13:52:12.713030-07:00,Moved from STATE_START to STATE_START
93,1696539132.71416,2023-10-05T13:52:12.714160-07:00,"Found existing field {
    redirectParams =     {
        launchAppStatusModal = 1;
    };
    redirectTo = ""root.main.control"";
}, retaining existing"
94,1696539132.71539,2023-10-05T13:52:12.715390-07:00,"Did not find existing field (null), filling in default {
    type = calendar;
}"
95,1696539132.71644,2023-10-05T13:52:12.716440-07:00,"Did not find existing field (null), filling in default {
    enabled = 0;
}"
96,1696539132.71904,2023-10-05T13:52:12.719040-07:00,"Both local and native consent not found, nothing to sync"
97,1696539132.72414,2023-10-05T13:52:12.724140-07:00,for key intro_done uc_stored_val = null ls_stored_val = null
98,1696539132.72544,2023-10-05T13:52:12.725440-07:00,"local and native values match, already synced"
99,1696539132.72654,2023-10-05T13:52:12.726540-07:00,"required consent version = {""protocol_id"":""2014-04-6267"",""approval_date"":""2016-07-14""}"
100,1696539132.72979,2023-10-05T13:52:12.729790-07:00,"for key data_collection_consented_protocol uc_stored_val = {""approval_date"":""2016-07-14"",""protocol_id"":""2014-04-6267""} ls_stored_val = {""protocol_id"":""2014-04-6267"",""approval_date"":""2016-07-14""}"
101,1696539132.73092,2023-10-05T13:52:12.730920-07:00,"local and native values match, already synced"
102,1696539132.77695,2023-10-05T13:52:12.776950-07:00,"permissions not done, waiting"
103,1696539132.7923,2023-10-05T13:52:12.792300-07:00,Returning combination of always = 0 and precise 1
104,1696539132.79889,2023-10-05T13:52:12.798890-07:00,Returning combination of always = 0 and precise 1
105,1696539132.82314,2023-10-05T13:52:12.823140-07:00,"permissions not done, waiting"
106,1696539132.88394,2023-10-05T13:52:12.883940-07:00,Returning combination of always = 0 and precise 1
107,1696539134.22481,2023-10-05T13:52:14.224810-07:00,Received callback from user notification settings 
108,1696539134.22738,2023-10-05T13:52:14.227380-07:00,"no foreground delegate callbacks found for notifications, ignoring success..."
109,1696539134.94982,2023-10-05T13:52:14.949820-07:00,Returning combination of always = 0 and precise 1
110,1696539134.95993,2023-10-05T13:52:14.959930-07:00,"in checkLocationSettingsAndPermissions, locationService is enabled, but the permission is 0"
111,1696539136.09404,2023-10-05T13:52:16.094040-07:00,Application went to the background
112,1696539136.97281,2023-10-05T13:52:16.972810-07:00,"Location tracking failed with error Error Domain=kCLErrorDomain Code=1 ""(null)"""
113,1696539139.22609,2023-10-05T13:52:19.226090-07:00,"In checker's didChangeAuthorizationStatus, new authorization status = 3, always = 3"
114,1696539139.25538,2023-10-05T13:52:19.255380-07:00,"1 foreground delegates found, calling didChangeAuthorizationStatus to return the new value 3"
115,1696539139.25699,2023-10-05T13:52:19.256990-07:00,"In delegate didChangeAuthorizationStatus, newStatus = 3"
116,1696539139.26015,2023-10-05T13:52:19.260150-07:00,"status == always, restarting FSM if start state"
117,1696539139.26528,2023-10-05T13:52:19.265280-07:00,"Still in start state, sending initialize..."
118,1696539139.26655,2023-10-05T13:52:19.266550-07:00,"In TripDiaryStateMachine, received transition T_INITIALIZE in state STATE_START"
119,1696539139.27423,2023-10-05T13:52:19.274230-07:00,registered for visit notifications
120,1696539139.28115,2023-10-05T13:52:19.281150-07:00,In createGeofenceHere
122,1696539139.30175,2023-10-05T13:52:19.301750-07:00,BEFORE creating region
124,1696539139.36729,2023-10-05T13:52:19.367290-07:00,AFTER creating region
125,1696539139.37596,2023-10-05T13:52:19.375960-07:00,"Found geofence with id

133,1696539139.39943,2023-10-05T13:52:19.399430-07:00,started monitoring for region STATIONARY_GEOFENCE_LOCATION
134,1696539139.91407,2023-10-05T13:52:19.914070-07:00,Current state of region STATIONARY_GEOFENCE_LOCATION is 1 (inside)
135,1696539139.92016,2023-10-05T13:52:19.920160-07:00,Received INSIDE geofence state when currState = STATE_START
136,1696539139.92401,2023-10-05T13:52:19.924010-07:00,"In TripDiaryStateMachine, received transition T_INIT_COMPLETE in state STATE_START"
137,1696539139.93749,2023-10-05T13:52:19.937490-07:00,Moved from STATE_START to STATE_WAITING_FOR_TRIP_START
138,1696539139.94558,2023-10-05T13:52:19.945580-07:00,Returning combination of always = 1 and precise 1
139,1696539139.955,2023-10-05T13:52:19.955000-07:00,"in getPriorConsent, currConfig = <ConsentConfig: 0x280c318e0>"
140,1696539139.95709,2023-10-05T13:52:19.957090-07:00,"allChecksPass = 0, but location permimssions pass, so one of the non-location checks must be false: [loc settings, loc permissions, motion settings, motion permissions, notification] = (
    1,
    1,
    1,
    0,
    1
)"
141,1696539139.95934,2023-10-05T13:52:19.959340-07:00,"Found existing field {
    redirectParams =     {
        launchAppStatusModal = 1;
    };
    redirectTo = ""root.main.control"";
}, retaining existing"
142,1696539139.96129,2023-10-05T13:52:19.961290-07:00,"Did not find existing field (null), filling in default {
    type = calendar;
}"
143,1696539139.96315,2023-10-05T13:52:19.963150-07:00,"Did not find existing field (null), filling in default {
    enabled = 0;
}"
144,1696539139.96511,2023-10-05T13:52:19.965110-07:00,Current state of region STATIONARY_GEOFENCE_LOCATION is 1 (inside)
145,1696539139.96677,2023-10-05T13:52:19.966770-07:00,Received INSIDE geofence state when currState = STATE_WAITING_FOR_TRIP_START
146,1696539139.96841,2023-10-05T13:52:19.968410-07:00,"In TripDiaryStateMachine, received transition T_NOP in state STATE_WAITING_FOR_TRIP_START"
147,1696539139.97246,2023-10-05T13:52:19.972460-07:00,Current state of region STATIONARY_GEOFENCE_LOCATION is 1 (inside)
148,1696539139.97434,2023-10-05T13:52:19.974340-07:00,Received INSIDE geofence state when currState = STATE_WAITING_FOR_TRIP_START
149,1696539139.97702,2023-10-05T13:52:19.977020-07:00,"In TripDiaryStateMachine, received transition T_NOP in state STATE_WAITING_FOR_TRIP_START"
150,1696539139.98403,2023-10-05T13:52:19.984030-07:00,Current state of region STATIONARY_GEOFENCE_LOCATION is 1 (inside)
151,1696539139.98629,2023-10-05T13:52:19.986290-07:00,Received INSIDE geofence state when currState = STATE_WAITING_FOR_TRIP_START
152,1696539139.98776,2023-10-05T13:52:19.987760-07:00,"In TripDiaryStateMachine, received transition T_NOP in state STATE_WAITING_FOR_TRIP_START"
153,1696539140.10664,2023-10-05T13:52:20.106640-07:00,Application will enter the foreground
154,1696539140.11518,2023-10-05T13:52:20.115180-07:00,Returning combination of always = 1 and precise 1
155,1696539140.12676,2023-10-05T13:52:20.126760-07:00,Returning combination of always = 1 and precise 1
156,1696539140.13402,2023-10-05T13:52:20.134020-07:00,Returning combination of always = 1 and precise 1
157,1696539140.15159,2023-10-05T13:52:20.151590-07:00,"STORAGE_PLUGIN: app has resumed, checking storage sync"
158,1696539140.22824,2023-10-05T13:52:20.228240-07:00,"STORAGE_PLUGIN: Comparing web keys CONFIG_PHONE_UI,data_collection_consented_protocol with CONFIG_PHONE_UI,connection_settings,data_collection_consented_protocol,CURR_GEOFENCE_LOCATION"
159,1696539140.22993,2023-10-05T13:52:20.229930-07:00,"STORAGE_PLUGIN: Found native keys CONFIG_PHONE_UI,data_collection_consented_protocol missing native keys "
160,1696539140.23112,2023-10-05T13:52:20.231120-07:00,"STORAGE_PLUGIN: Found web keys CONFIG_PHONE_UI,data_collection_consented_protocol missing web keys connection_settings,CURR_GEOFENCE_LOCATION"
161,1696539140.23275,2023-10-05T13:52:20.232750-07:00,"STORAGE_PLUGIN: Syncing all missing keys connection_settings,CURR_GEOFENCE_LOCATION"
162,1696539140.23873,2023-10-05T13:52:20.238730-07:00,Logged missing keys to client stats
163,1696539140.2404,2023-10-05T13:52:20.240400-07:00,"STORAGE_PLUGIN: For the record, all unique native keys are stats/client_nav_event,config/app_ui_config,CONFIG_PHONE_UI,connection_settings,config/consent,statemachine/transition,background/battery,data_collection_consented_protocol,CURR_GEOFENCE_LOCATION"
164,1696539140.2427,2023-10-05T13:52:20.242700-07:00,"for key connection_settings uc_stored_val = {""connectUrl"":""https://openpath-stage.nrel.gov/api/"",""aggregate_call_auth"":""user_only""} ls_stored_val = null"
165,1696539140.24399,2023-10-05T13:52:20.243990-07:00,"for key connection_settingsuc_stored_val = {""connectUrl"":""https://openpath-stage.nrel.gov/api/"",""aggregate_call_auth"":""user_only""} ls_stored_val = null copying native connection_settings to local..."

168,1696539142.97682,2023-10-05T13:52:22.976820-07:00,"Motion activity available, checking auth status"
169,1696539142.98303,2023-10-05T13:52:22.983030-07:00,Auth status = 0
170,1696539142.98445,2023-10-05T13:52:22.984450-07:00,"Activity status not determined, initializing to get regular prompt"
171,1696539143.78732,2023-10-05T13:52:23.787320-07:00,activity recognition works fine
172,1696539146.55432,2023-10-05T13:52:26.554320-07:00,for key intro_done uc_stored_val = null ls_stored_val = null
173,1696539146.56104,2023-10-05T13:52:26.561040-07:00,"local and native values match, already synced"
174,1696539146.56326,2023-10-05T13:52:26.563260-07:00,"required consent version = {""protocol_id"":""2014-04-6267"",""approval_date"":""2016-07-14""}"
175,1696539146.56659,2023-10-05T13:52:26.566590-07:00,"for key data_collection_consented_protocol uc_stored_val = {""approval_date"":""2016-07-14"",""protocol_id"":""2014-04-6267""} ls_stored_val = {""protocol_id"":""2014-04-6267"",""approval_date"":""2016-07-14""}"
176,1696539146.56838,2023-10-05T13:52:26.568380-07:00,"local and native values match, already synced"
177,1696539146.59096,2023-10-05T13:52:26.590960-07:00,loadPreviousResponseForSurvey: dataKey = manual/demographic_survey; tq = [object Object]
178,1696539146.60188,2023-10-05T13:52:26.601880-07:00,CommunicationHelper.execute called!
179,1696539146.60429,2023-10-05T13:52:26.604290-07:00,postToHost called with url = https://openpath-stage.nrel.gov/api//datastreams/find_entries/timestamp
180,1696539146.60762,2023-10-05T13:52:26.607620-07:00,About to dedup localResult = 0remoteResult = 0
181,1696539146.60926,2023-10-05T13:52:26.609260-07:00,Deduped list = 0
182,1696539146.63939,2023-10-05T13:52:26.639390-07:00,"fetchUrlCached: found cached data for url json/demo-survey-v2.json, returning"

187,1696539189.92186,2023-10-05T13:53:09.921860-07:00,"local and native values match, already synced"
188,1696539190.03543,2023-10-05T13:53:10.035430-07:00,CommunicationHelper.execute called!
189,1696539190.04174,2023-10-05T13:53:10.041740-07:00,postToHost called with url = https://openpath-stage.nrel.gov/api//pipeline/get_range_ts
190,1696539190.06203,2023-10-05T13:53:10.062030-07:00,"Error while loading pipeline range""While getting pipeline range timestamps, During server call, error *** -[__NSDictionaryM setObject:forKey:]: object cannot be nil (key: user)"""
191,1696539190.06713,2023-10-05T13:53:10.067130-07:00,UI_CONFIG: about to call configReady function in MultiLabelService
192,1696539190.07913,2023-10-05T13:53:10.079130-07:00,About to initialize the MultiLabelService
193,1696539190.0809,2023-10-05T13:53:10.080900-07:00,finished initializing the MultiLabelService
194,1696539190.08455,2023-10-05T13:53:10.084550-07:00,"error {""line"":0,""column"":0} while reading confirm options, reverting to defaults"
195,1696539190.09258,2023-10-05T13:53:10.092580-07:00,"error {""line"":0,""column"":0} while reading confirm options, reverting to defaults"
196,1696539193.84692,2023-10-05T13:53:13.846920-07:00,"No reminder schemes found in config, not scheduling notifications"
197,1696539195.61532,2023-10-05T13:53:15.615320-07:00,About to get email config
198,1696539195.63938,2023-10-05T13:53:15.639380-07:00,"default emailConfigString = {""address"":""shankari@eecs.berkeley.edu""}"
199,1696539197.52822,2023-10-05T13:53:17.528220-07:00,Going to email loggerDB

@Abby-Wheelis
Copy link
Member Author

I can see the leaving and returning as I'm fixing the permissions, and the error that was generated "Error while loading pipeline range""While getting pipeline range timestamps, During server call, error *** -[__NSDictionaryM setObject:forKey:]: object cannot be nil (key: user)""" when I got to the label screen, but I'm not really sure what else to look for. Is there a specific message for when the user gets registered?

Also, is there a chance that this is related to some of the login-flow issues from Launching app with #1032 pops up permission screen in summary? I could see where leaving and coming back or seeing the permissions earlier than expected could create off behavior with regards to logging in properly. When I log in the second time, the permissions are already handled.

@Abby-Wheelis
Copy link
Member Author

I could see where leaving and coming back or seeing the permissions earlier than expected could create off behavior with regards to logging in properly. When I log in the second time, the permissions are already handled.

To try and test this, I just tried logging out, breaking a permission, and logging back in. This had no problems. It's only the fresh install of the app that I've been able to re-create the issue.

@shankari
Copy link
Contributor

shankari commented Oct 5, 2023

189,1696539190.04174,2023-10-05T13:53:10.041740-07:00,postToHost called with url = https://openpath-stage.nrel.gov/api//pipeline/get_range_ts
190,1696539190.06203,2023-10-05T13:53:10.062030-07:00,"Error while loading pipeline range""While getting pipeline range timestamps, During server call, error *** -[__NSDictionaryM setObject:forKey:]: object cannot be nil (key: user)"""

This is an error from the native code (NSDictionary is an iOS class).
And the error is there as well object cannot be nil (key: user), we are trying to fill in user but are unsuccessful
The user is the token
https://github.com/e-mission/cordova-server-communication/blob/72d3a4e73003e99e952f965649ef3ce0ac191a84/src/android/CommunicationHelper.java#L88

        final String userToken = CommunicationHelper.getTokenSync(ctxt);
        filledJsonObject.put("user", userToken);

So on first install, the token is null for some reason. This may be related to the onboarding fixes - maybe we make a call before the token is saved and that error shows up later. But in that case, I would expect that killing and restarting the app would fix it. If it requires a logout + relogin, it seems more likely that it is some error in correctly saving the token in local storage (the auth plugin) during the initial install.

@Abby-Wheelis
Copy link
Member Author

So on first install, the token is null for some reason.

That makes sense since the two biggest problems I noticed were the error on the label screen and the "not logged in" message in Profile where I'd expect to see the token.

I would expect that killing and restarting the app would fix it

I was just able to reproduce again, and confirmed that killing the app and reopening it did not fix the issue.

One of the times I reinstalled just now, I did not get the error, and noted another difference between that an the installs with the error. On the bad installs, I am asked to take the survey again, but on the successful install login it had a stored response for me. It's still at least 75% bad logins on first install for this phone. It seems like the lack of survey found probably has to do with the null token, but maybe it can help further diagnose the issue.

@shankari
Copy link
Contributor

shankari commented Oct 6, 2023

I'm glad that we have a phone where it is 75% reproducible - it would be worse if it were only 1% reproducible on a customer phone 😄

Given that it is not 100% even on this phone, my assumption is that it is some kind of race condition with storing the data in the auth plugin so that it can be read by the native code.

I don't think it is affected by e-mission/e-mission-phone#1050 but I will push that out to staging anyway so we can confirm. In the interim, it would be good if we could also include some additional logs around the code that saves the auth and get them into tonight's release. That way, the logs we get tomorrow will hopefully be more helpful. I would suggest adding logs before saving the auth, in the callback after saving, and when trying to read the survey.

Make sure to use Logger.log (or the equivalent) since console.log will not be saved.

@JGreenlee @Abby-Wheelis LMK if one of you can do this, otherwise I will see if I can make the changes before creating the release.

@Abby-Wheelis
Copy link
Member Author

@shankari I started the draft PR above, with some more log statements around storing and retrieving the config. There is already a log statement with after the response is stored, for my failed login that read UI_CONFIG: Stored dynamic config in KVStore successfully, result = null. I don't see the token involved in getting the old survey, but I could have missed something.

If anyone sees any places we should add logs feel free to let me know or add them to my branch (if you don't have write access I'd be happy to enable that)

@shankari
Copy link
Contributor

shankari commented Oct 6, 2023

the token is stored in the config initially. However, it is (or should be) stored into the auth in the equivalent of here:
https://github.com/e-mission/e-mission-phone/blob/cc0e41935f76e098c06d1c955c720cf6e975a66f/www/js/intro.js#L127

    const EXPECTED_METHOD = "prompted-auth";
    const dbStorageObject = {"token": token};
    KVStore.set(EXPECTED_METHOD, dbStorageObject).then(function(opcode) {
      // ionicToast.show(message, position, stick, time);
      // $scope.next();

that is the location that the native code reads

I'm fixing a showstopper in the admin dashboard, but will take a look after that

@shankari
Copy link
Contributor

shankari commented Oct 6, 2023

The "equivalent" is in www/js//onboarding/SaveQrPage.tsx

  function login(token) {
    const CommHelper = getAngularService('CommHelper');
    const KVStore = getAngularService('KVStore');
    const EXPECTED_METHOD = "prompted-auth";
    const dbStorageObject = {"token": token};
    return KVStore.set(EXPECTED_METHOD, dbStorageObject).then((r) => {

I would add some logs there and to KVStore

@Abby-Wheelis
Copy link
Member Author

Abby-Wheelis commented Oct 6, 2023

Looking at adding those log statements, I think the issue may be that the user is never getting logged in - the login should be called by this useEffect

  useEffect(() => {
    if (overallStatus == true && !registerUserDone) {
      logDebug('permissions done, going to log in');
      login(onboardingState.opcode).then((response) => {
        logDebug('login done, refreshing onboarding state');
        setRegisterUserDone(true);
        preloadDemoSurveyResponse();
        refreshOnboardingState();
      });
    } else {
      logDebug('permissions not done, waiting');
    }
  }, [overallStatus]);

But when I search the log outputs I got, I have several instances of "permission not done, waiting" but none of "permission done, going to log in"

If they're not logged in, I'm not sure how the app continues to advance, so I've added another log statement in onboarding state, to see what's happening there and if that can provide any insight.

Abby-Wheelis pushed a commit to Abby-Wheelis/e-mission-phone that referenced this issue Oct 6, 2023
in the logs for the bug runs: e-mission/e-mission-docs#1002 I'm not seeing log statements indicating that the user is logged in (which I should see) and so I'm wondering how the onboarding state is moving on in that case. Adding this log statement to investigate.
@JGreenlee
Copy link

Still reproducible on 1.5.3 for me. Will investigate tomorrow.

@JGreenlee
Copy link

Looking at adding those log statements, I think the issue may be that the user is never getting logged in - the login should be called by this useEffect
...
But when I search the log outputs I got, I have several instances of "permission not done, waiting" but none of "permission done, going to log in"

If they're not logged in, I'm not sure how the app continues to advance, so I've added another log statement in onboarding state, to see what's happening there and if that can provide any insight.

I think this is spot on. I don't see "permissions done, going to log in" or any of the new log statements like "about to login with token" or "registered user in CommHelper result".

I actually was able to reproduce the issue on my second time through the onboarding process by breaking the location permission, logging out, and trying to log back in.
This suggests something is causing overallStatus to not get updated and recognized as true, as the useEffect evidently never runs while overallStatus is true.

@JGreenlee
Copy link

After some trial and error, I can reproduce this in the devapp on a real phone and can do some more hands-on debugging

@JGreenlee
Copy link

The issue results from using our custom hook, usePermissionStatus in multiple places, while updates are only being triggered for one of these instances.

When a permission is fixed via PermissionsControls, its instance of usePermissionStatus gets its overallStatus updated. However, other instances of usePermissionStatus did not receive this update.

So when SaveQrPage hooks into usePermissionStatus and watches overallStatus for changes in the useEffect, we never received changes, causing the login function to never be triggered.

The path forward seems to be:

  • Hoist the permissions state higher in the component tree so it is stored only in one place and the same instance is shared throughout the app
  • Ensure that users cannot fill out a survey until after a successful login
    • It seems like we mistakenly queried existing surveys for user 'null' or similar, and obviously did not find it, so we assumed they were a first-time user. We shouldn't proceed in the onboarding flow unless the user is valid

JGreenlee added a commit to JGreenlee/e-mission-phone that referenced this issue Oct 6, 2023
Now that we have an App component, we can think about hoisting state higher in the component tree so it can be shared instead of being redundant.
Rather than hooking into usePermissionStatus from multiple different components, it will be cleaner to hook into it once in the App component and share it downstream via the AppContext.

When there were multiple instances of usePermissionStatus, we ran into issues where only one was recieving updates (e-mission/e-mission-docs#1002)
Hoisting the permission state to the App component resolves these issues because now there is only one instance of usePermissionStatus
@JGreenlee
Copy link

Fix is up at e-mission/e-mission-phone#1059. I hope this is the last one!

@Abby-Wheelis
Copy link
Member Author

I just logged in and out on a test phone 6-8 times in a row and did not experience this error any of those times!

@github-project-automation github-project-automation bot moved this from Showstoppers for the current release to Tasks completed in OpenPATH Tasks Overview Oct 27, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants