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

notifications generated by background checks don't open the app correctly #712

Closed
shankari opened this issue Mar 24, 2022 · 32 comments
Closed

Comments

@shankari
Copy link
Contributor

Google finally started enforcing background restrictions on its apps
The background check was not re-entrant, so we ran into
#710

After fixing that, I got a notification that the background restrictions were not set correctly.
On clicking it, however, the app was not launched correctly; instead a separate activity was created

Phone app emulator
bar_instead_of_opening Screenshot_1648078560

After much debugging, it turned out that this was because when we click on the notification, the local notification plugin tries to read the notification config from SharedPreferences.
#710 (comment)

Moving the notification generation into the UI thread did not work
#710 (comment)

So I looked to see if this was also a new regression, and:

  • it happens on API 29 with the older version of the plugin (1.7.0)
  • it happens for other permissions (e.g. motion activity)
  • it hangs most of the time (3/4 times-ish) but not all the time

Note that I had to run this on an emulator which hadn't been upgraded to enforce the background restrictions to avoid hanging. But the fact that it happens for a different permission and without running in the background indicates that there is likely a more substantial issue here.

So tracking it in a separate issue.

This is not a fire drill like the other issue, but it would be good to fix before reaching out to participants to get them to fix the app.
Since this is an issue with the local notification plugin, we may want to fix the crashes around accessing the shared preferences at the same time.

@shankari
Copy link
Contributor Author

Continuing the tracking to see how often it happens (from #710)

  • 7:17: Installed with all permissions
  • 7:18: Turned off motion activity; got prompt; worked
  • 7:19: Did not fix motion activity; waiting for next background check
  • 7:29: Notification; did not work; dismiss; wait
  • 7:40: Notification; did not work; dismiss
  • 8:50: Notification; worked
  • 9:02: Notification; did not work
  • 9:21: Notification; did not work
  • 10:08: Notification, did not work
  • 10:21: Notification, did not work
  • 10:31: Notification, did not work
  • 10:41: Notification, did not work
  • 10:58: Notification, did not work

So it does not work for the majority of the time.

@shankari
Copy link
Contributor Author

shankari commented Mar 24, 2022

Let's try and generate the notification from a UI thread to confirm that it does work reliably in that case.
Trial involves:

  • force sync
  • ignore "trigger" popup
  • send app to background
  • click on notification

Tried ~ 10 trials, all of them worked

@shankari
Copy link
Contributor Author

the entries are saved into the SharedPreferences in Notification.persist

        editor = getPrefs(PREF_KEY_ID).edit();
        editor.putString(id, options.toString());
        editor.apply();

I also use SharedPreferences to store the current state machine state, and I remember switching from apply() to commit() e-mission/e-mission-data-collection@ec63703

commit() saves data synchronously
https://developer.android.com/reference/android/content/SharedPreferences.Editor#commit()

apply() does so asynchronously and the android lifecycle events make sure to write in-flight events. But it is not clear that they are written for background operation. The documentation says:

If you don't care about the return value and you're using this from your application's main thread, consider using apply() instead.

That's why I moved from apply() to commit(). Let's try changing this in the local notification code and see if that fixes it.

Then, we need to figure out how to incorporate it into the plugin...

@shankari
Copy link
Contributor Author

FYI, there are multiple locations where we use commit()

platforms/android//app/src/main/java/edu/berkeley/eecs/emission/cordova/tracker/location/TripDiaryStateMachineService.java:        prefsEditor.commit();
platforms/android//app/src/main/java/edu/berkeley/eecs/emission/cordova/tracker/location/TripDiaryStateMachineServiceOngoing.java:        prefsEditor.commit();
platforms/android//app/src/main/java/edu/berkeley/eecs/emission/cordova/tracker/location/TripDiaryStateMachineReceiver.java:            prefsEditor.commit();
platforms/android//app/src/main/java/edu/berkeley/eecs/emission/cordova/jwtauth/OpenIDAuthStateManager.java:            if (!editor.commit()) {
platforms/android//app/src/main/java/de/appplant/cordova/plugin/notification/Notification.java:        editor.commit();
platforms/android//app/src/main/java/de/appplant/cordova/plugin/notification/Notification.java:        editor.commit();
platforms/android//app/src/main/java/com/adobe/phonegap/push/PushPlugin.java:            editor.commit();
platforms/android//app/src/main/java/com/adobe/phonegap/push/PushPlugin.java:              editor.commit();
platforms/android//app/src/main/java/com/ionicframework/common/IonicCordovaCommon.java:    editor.commit();
platforms/android//app/src/main/java/com/ionicframework/common/IonicCordovaCommon.java:    editor.commit();

There are also multiple other places where we use apply() need to see whether we need to change them as well

platforms/android//app/src/main/java/edu/berkeley/eecs/emission/cordova/tracker/location/TripDiaryStateMachineReceiver.java:        editor.apply();
platforms/android//app/src/main/java/de/appplant/cordova/plugin/notification/Notification.java:            editor.apply();
platforms/android//app/src/main/java/de/appplant/cordova/plugin/badge/BadgeImpl.java:        editor.apply();
platforms/android//app/src/main/java/de/appplant/cordova/plugin/badge/BadgeImpl.java:        editor.apply();
platforms/android//app/src/main/java/com/adobe/phonegap/push/PushPlugin.java:    editor.apply();
platforms/android//app/src/main/java/com/ionicframework/cordova/webview/IonicWebViewEngine.java:      editor.apply();
platforms/android//app/src/main/java/com/ionicframework/cordova/webview/IonicWebView.java:      editor.apply();
platforms/android//app/src/main/java/com/ionicframework/common/IonicCordovaCommon.java:    prefs.edit().putString("uuid", this.uuid).apply();

@shankari
Copy link
Contributor Author

Testing with commit from the background:

  • 4:43: launched app
  • 4:49: notification, worked
  • 5:08: notification, did not work. ARGH!
  • 5:23: notification, worked
    -..... missing notifications for a while....
  • 8pm: notification, did not work. ARGH!

Let's briefly see if the toast is visible right after it is created. Otherwise, we may want to store in local storage instead.

@shankari
Copy link
Contributor Author

notification was saved on create

2022-03-24 20:25:04.319 13272-13272/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: all checks = false but location permission status  true should be true  so one of the non-location checks must be false: loc permission, motion permission, notification, unused apps[true, false, true, true]
2022-03-24 20:25:04.324 13272-13272/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: a non-local check failed, generating only user visible notification
2022-03-24 20:25:04.406 13272-13272/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: Retrieved just created notification {"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data":{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}}

worked

2022-03-24 20:34:46.392 13272-13272/edu.berkeley.eecs.emission I/AbstractClickReceiver: onClick complete, finishing...

@shankari
Copy link
Contributor Author

ok, hit the failure case again, we are able to retrieve the notification right after creation

2022-03-24 21:06:26.040 6235-6277/edu.berkeley.eecs.emission I/SensorControlChecks: About to check location settings
2022-03-24 21:06:26.057 6235-6277/edu.berkeley.eecs.emission D/SensorControlChecks: Checking location settings for request Request[PRIORITY_HIGH_ACCURACY requested=30000ms fastest=5000ms]
2022-03-24 21:06:26.144 6235-6235/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: Current location settings are com.google.android.gms.location.LocationSettingsResponse@b996107
2022-03-24 21:06:26.167 6235-6235/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: all checks = false but location permission status  true should be true  so one of the non-location checks must be false: loc permission, motion permission, notification, unused apps[true, false, true, true]
2022-03-24 21:06:26.172 6235-6235/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: a non-local check failed, generating only user visible notification
2022-03-24 21:06:26.268 6235-6235/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: Retrieved just created notification {"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data":{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}}
...
2022-03-24 21:21:01.962 6235-6235/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: a non-local check failed, generating only user visible notification
2022-03-24 21:21:02.042 6235-6235/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: Retrieved just created notification {"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data":{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}}

but fails when clicked

2022-03-24 21:22:27.587 32701-32701/edu.berkeley.eecs.emission I/AbstractClickReceiver: starting onCreate
2022-03-24 21:22:27.595 32701-32701/edu.berkeley.eecs.emission I/AbstractClickReceiver: starting onStart
2022-03-24 21:22:27.596 32701-32701/edu.berkeley.eecs.emission I/AbstractClickReceiver: starting onResume
2022-03-24 21:22:27.596 32701-32701/edu.berkeley.eecs.emission I/AbstractClickReceiver: checking bundle Bundle[mParcelledData.dataSize=280]
2022-03-24 21:22:27.598 32701-32701/edu.berkeley.eecs.emission I/AbstractClickReceiver: found toast null

notification generated again

2022-03-24 22:02:03.398 29570-29570/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: Retrieved just created notification {"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data":{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}}

clicked again

2022-03-24 22:03:53.983 29108-29108/edu.berkeley.eecs.emission I/AbstractClickReceiver: starting onCreate
2022-03-24 22:03:53.988 29108-29108/edu.berkeley.eecs.emission I/AbstractClickReceiver: starting onStart
2022-03-24 22:03:53.989 29108-29108/edu.berkeley.eecs.emission I/AbstractClickReceiver: starting onResume
2022-03-24 22:03:53.989 29108-29108/edu.berkeley.eecs.emission I/AbstractClickReceiver: checking bundle Bundle[mParcelledData.dataSize=280]
2022-03-24 22:03:53.989 29108-29108/edu.berkeley.eecs.emission I/AbstractClickReceiver: toast id from bundle = 362253744
2022-03-24 22:03:53.990 29108-29108/edu.berkeley.eecs.emission I/AbstractClickReceiver: found toast null

The id from the bundle is correct, but it cannot find any matches. The SharedPreferences are null.
Not sure why this is not an issue with the SharedPreferences for the TripDiaryStateMachine.

@shankari
Copy link
Contributor Author

Now the background sync process is not even running reliably so it is super hard to test.
Stopping this for now, and will pick up tomorrow morning.

A fairly easy workaround is to store the information in the database, similar to e-mission/e-mission-phone@a09385b on iOS.

However, I am concerned that we also store the FSM state in shared preferences, and if there's something funky about it, it could cause us to fail in unpredictable ways.

Let's spend a little more time working on the reason, then just track if the current state is null and move on to storing in the database.

@shankari
Copy link
Contributor Author

Ha right after that, noticed that the sync had run in the adb logcat, just no logs showed up.

During sync, we were able to read the notification

03-24 22:41:49.479 27410 27410 I SensorControlBackgroundChecker: Retrieved just created notification {"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data"
:{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}}

And when we clicked, we were not

2022-03-24 22:48:56.978 21852-21852/edu.berkeley.eecs.emission I/AbstractClickReceiver: starting onResume
2022-03-24 22:48:56.986 21852-21852/edu.berkeley.eecs.emission I/AbstractClickReceiver: Retrieved just created notification null

Although we had the exact same copy pasted code in both locations

      Notification createdNotification = de.appplant.cordova.plugin.notification.Manager.getInstance(ctxt).get(SensorControlConstants.OPEN_APP_STATUS_PAGE);
      Log.i(ctxt, TAG, "Retrieved just created notification "+createdNotification);

        Notification createdNotification = de.appplant.cordova.plugin.notification.Manager.getInstance(context).get(SensorControlConstants.OPEN_APP_STATUS_PAGE);
        edu.berkeley.eecs.emission.cordova.unifiedlogger.Log.i(context, "AbstractClickReceiver", "Retrieved just created notification "+createdNotification);

I do note that the click reciever uses the application context

        Context context    = getApplicationContext();

while the background checker uses the passed in context

      NotificationHelper.schedulePluginCompatibleNotification(ctxt, OPEN_APP_STATUS_PAGE(ctxt), null);
      Notification createdNotification = de.appplant.cordova.plugin.notification.Manager.getInstance(ctxt).get(SensorControlConstants.OPEN_APP_STATUS_PAGE);
      Log.i(ctxt, TAG, "Retrieved just created notification "+createdNotification);

Let's see if that is the difference. If that is the problem, the database may not work either. Let's try changing the context.

@shankari
Copy link
Contributor Author

After restart, the first call works with both contexts, which is not unusual.

2022-03-24 23:12:26.762 5689-5689/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: Retrieved just created notification with app context{"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data":{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}}
2022-03-24 23:12:26.770 5689-5689/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: Retrieved just created notification with service context{"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data":{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}}
2022-03-24 23:13:12.196 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: starting onCreate
2022-03-24 23:13:12.205 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: starting onStart
2022-03-24 23:13:12.205 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: starting onResume
2022-03-24 23:13:12.212 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: Retrieved just created notification {"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data":{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}}
2022-03-24 23:13:12.212 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: checking bundle Bundle[mParcelledData.dataSize=280]
2022-03-24 23:13:12.212 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: toast id from bundle = 362253744
2022-03-24 23:13:12.213 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: found toast {"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data":{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}}

True test is tomorrow morning when the contexts will presumably start differing

@shankari
Copy link
Contributor Author

shankari commented Mar 25, 2022

Next morning:

  • 6am/7:13am: works (both contexts work during creation)
  • 7:15am: fails (both contexts work during creation/application context fails during retrieval)
2022-03-25 07:14:19.509 2535-2575/edu.berkeley.eecs.emission I/TripDiaryStateMachineRcvr: END PERIODIC ACTIVITY
2022-03-25 07:14:19.634 2535-2535/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: Retrieved just created notification with app context{"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data":{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}}
2022-03-25 07:14:19.651 2535-2535/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: Retrieved just created notification with service context{"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data":{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}}

2022-03-25 07:15:27.776 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: starting onCreate
2022-03-25 07:15:27.782 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: starting onStart
2022-03-25 07:15:27.782 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: starting onResume
2022-03-25 07:15:27.796 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: Retrieved just created notification null
2022-03-25 07:15:27.796 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: checking bundle Bundle[mParcelledData.dataSize=280]
2022-03-25 07:15:27.796 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: toast id from bundle = 362253744
2022-03-25 07:15:27.797 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: found toast null

7:31/7:32: again didn't work

2022-03-25 07:31:37.182 2535-12337/edu.berkeley.eecs.emission I/TripDiaryStateMachineRcvr: END PERIODIC ACTIVITY
2022-03-25 07:31:37.199 2535-2535/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: Retrieved just created notification with app context{"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data":{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}}
2022-03-25 07:31:37.210 2535-2535/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: Retrieved just created notification with service context{"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data":{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}}

2022-03-25 07:34:52.851 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: starting onCreate
2022-03-25 07:34:52.857 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: starting onStart
2022-03-25 07:34:52.858 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: starting onResume
2022-03-25 07:34:52.863 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: Retrieved just created notification null
2022-03-25 07:34:52.863 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: checking bundle Bundle[mParcelledData.dataSize=280]
2022-03-25 07:34:52.863 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: toast id from bundle = 362253744
2022-03-25 07:34:52.863 5689-5689/edu.berkeley.eecs.emission I/AbstractClickReceiver: found toast null

Trying the database to store info now

@shankari
Copy link
Contributor Author

shankari commented Mar 25, 2022

Wait, I retrieved the app context but not actually passed it in to the creator

    public static void generateOpenAppSettingsNotification(Context ctxt) {
      Log.i(appContext, TAG, "About to use appContext to create Click notification"+appContext);
      NotificationHelper.schedulePluginCompatibleNotification(appContext, OPEN_APP_STATUS_PAGE(ctxt), null);

Fixed and restarted at 7:38

@shankari
Copy link
Contributor Author

shankari commented Mar 25, 2022

  • 7:44: worked
  • 7:59: worked
  • 8:15: worked (could this be it!)
  • 8:45: worked (optimistic!!)
  • 9:51: worked

Note that I also see that the logs with the application context show up in the e-mission process and the logs with the regular context show up in the emission:sync process.

2022-03-25 08:45:21.235 16247-16247/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: About to use appContext to create Click notificationandroid.app.Application@6ae97e8
2022-03-25 08:45:21.291 16247-16247/edu.berkeley.eecs.emission D/CordovaWebViewImpl: >>> loadUrl(javascript:cordova.plugins.notification.local.fireEvent("trigger",{"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data":{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}},{"event":"trigger","foreground":false,"queued":false,"notification":362253744}))
2022-03-25 08:45:21.314 16247-16247/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: Retrieved just created notification with app context{"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data":{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}}
2022-03-25 08:45:21.366 16247-16247/edu.berkeley.eecs.emission I/SensorControlBackgroundChecker: Retrieved just created notification with service context{"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data":{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}}

Note that this worked (and works) in the transition notifier code (https://github.com/e-mission/e-mission-transition-notify/blob/master/src/android/TransitionNotificationReceiver.java#L79) (`onRecieve -> fireGenericTransition -> postNativeAndNotify), which is why I assumed it would work here.

But that is launched from a receiver, which doesn't create a new process. This is launched from a sync service, which does.

Screen Shot 2022-03-25 at 9 08 11 AM

https://github.com/e-mission/cordova-server-sync/blob/master/plugin.xml#L67

        <service
                android:name="edu.berkeley.eecs.emission.cordova.serversync.SyncService"
                android:exported="true"
                android:process=":sync">
            <intent-filter>
                <action android:name="android.content.SyncAdapter"/>
            </intent-filter>
            <meta-data android:name="android.content.SyncAdapter"
                    android:resource="@xml/syncadapter" />
        </service>

@shankari
Copy link
Contributor Author

shankari commented Mar 25, 2022

Next steps:

  • revert logging changes to the notification plugin
  • change the notification handler plugin to always use the application context for the plugin compatible notification to avoid such confusion in the future.

Open question:

  • ?? should we keep the commit vs. apply change. We definitely felt the need for it in the FSM code, but it didn't turn out to be the real issue here. And if we don't change it, we don't need to fork the plugin.
  • or do we? There is the crash while accessing the shared preferences at the same time..

Decision: Right now, we don't touch the plugin. File a new issue to handle the crash, if we have to change the code around that anyway, we might as well change apply to commit at that time.

@shankari
Copy link
Contributor Author

shankari commented Mar 25, 2022

Reverted changes by reinstalling plugins, starting test...

10:32: turned off motion activity permissions
10:35: notification, worked
10:48: notification (didn't hang), didn't work

@shankari
Copy link
Contributor Author

Made changes to the notification handler, starting test...

10:54: deployed changes
11:00: notification; 11:05 click: worked
11:37: notification; 11:38 click: did not work. What!!

Having issues with the background process, may run on a physical device instead for improved testing.

@shankari
Copy link
Contributor Author

Uninstalled and reinstalled

11:50: worked
12:00: did not work!

This is because the app context is apparently not the same when invoked from the sync code.

Worked

Screen Shot 2022-03-25 at 12 12 25 PM

Did not work

Screen Shot 2022-03-25 at 12 13 02 PM

@shankari
Copy link
Contributor Author

shankari commented Mar 25, 2022

Printing out the application context, we get

  • in e-mission
2022-03-25 12:29:14.953 19147-19192/edu.berkeley.eecs.emission I/NotificationHelper: Using app context to schedule new notificationandroid.app.Application@f304780
2022-03-25 12:29:15.682 12663-19210/edu.berkeley.eecs.emission I/NotificationHelper: Using app context to schedule new notificationandroid.app.Application@e0d736a
2022-03-25 12:29:15.682 12663-19210/edu.berkeley.eecs.emission I/NotificationHelper: Using app context to schedule new notificationandroid.app.Application@e0d736a

in the sync

2022-03-25 12:29:14.953 19147-19192/edu.berkeley.eecs.emission I/NotificationHelper: Using app context to schedule new notificationandroid.app.Application@f304780
2022-03-25 12:29:14.953 19147-19192/edu.berkeley.eecs.emission I/NotificationHelper: Using app context to schedule new notificationandroid.app.Application@f304780

So it looks like the contexts are different, and the log is printed in both?! What the heck are the two contexts?

worked.

@shankari
Copy link
Contributor Author

shankari commented Mar 25, 2022

Looks like we call the background checker twice and each call has a different application context?!

03-25 12:28:14.937 19147 19188 I TripDiaryStateMachineRcvr: END PERIODIC ACTIVITY
03-25 12:28:14.953 19147 19147 I SensorControlBackgroundChecker: All settings are valid, checking current state

03-25 12:28:15.627 12663 12663 I SensorControlBackgroundChecker: All settings are valid, checking current state

03-25 12:29:14.934 19147 19192 I SensorControlBackgroundChecker: all current settings and permissions are probably valid, but could be reset later
03-25 12:29:14.938 19147 19192 I SensorControlBackgroundChecker: don't generate a tracking error right now, but let's ask the user to avoid the reset
03-25 12:29:14.953 19147 19192 I NotificationHelper: Using app context to schedule new notificationandroid.app.Application@f304780

03-25 12:29:15.653 12663 19210 I SensorControlBackgroundChecker: all current settings and permissions are probably valid, but could be reset later
03-25 12:29:15.660 12663 19210 I SensorControlBackgroundChecker: don't generate a tracking error right now, but let's ask the user to avoid the reset
03-25 12:29:15.682 12663 19210 I NotificationHelper: Using app context to schedule new notificationandroid.app.Application@e0d736a

@shankari
Copy link
Contributor Author

shankari commented Mar 25, 2022

The sync process has

2022-03-25 12:44:17.477 19147-27531/edu.berkeley.eecs.emission I/NotificationHelper: Using app context to schedule new notificationandroid.app.Application@f304780

Screen Shot 2022-03-25 at 12 54 29 PM

The emission process has the previous invocation only.

2022-03-25 12:29:15.682 12663-19210/edu.berkeley.eecs.emission I/NotificationHelper: Using app context to schedule new notificationandroid.app.Application@e0d736a

Screen Shot 2022-03-25 at 12 54 51 PM

03-25 12:43:17.425 19147 19147 I SensorControlBackgroundChecker: All settings are valid, checking current state

03-25 12:44:17.451 19147 27531 I SensorControlBackgroundChecker: all current settings and permissions are probably valid, but could be reset later
03-25 12:44:17.456 19147 27531 I SensorControlBackgroundChecker: don't generate a tracking error right now, but let's ask the user to avoid the reset
03-25 12:44:17.477 19147 27531 I NotificationHelper: Using app context to schedule new notificationandroid.app.Application@f304780

Only one call in process ID 19147, which generates the same application context f304780
No call in process ID 12663 as before, so no application context e0d736a

So it shouldn't work? Yup.

@shankari
Copy link
Contributor Author

shankari commented Mar 25, 2022

So the sync process is the same

2022-03-25 13:14:49.042 11143-11185/edu.berkeley.eecs.emission I/NotificationHelper: Using app context to schedule new notificationandroid.app.Application@f304780

The emission process shows up too

2022-03-25 13:14:49.873 5854-11195/edu.berkeley.eecs.emission I/NotificationHelper: Using app context to schedule new notificationandroid.app.Application@e0d736a

So it should work this time. And it did

2022-03-25 13:16:47.651 5854-5854/edu.berkeley.eecs.emission I/AbstractClickReciever: Resumed with application contextandroid.app.Application@e0d736a
2022-03-25 13:16:47.660 5854-5854/edu.berkeley.eecs.emission D/CordovaWebViewImpl: >>> loadUrl(javascript:cordova.plugins.notification.local.fireEvent("click",{"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data":{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}},{"event":"click","foreground":false,"queued":false,"notification":362253744}))

And the application context is indeed the same as emission.

2022-03-25 13:16:47.651 5854-5854/edu.berkeley.eecs.emission I/AbstractClickReciever: Resumed with application contextandroid.app.Application@e0d736a
2022-03-25 13:16:47.660 5854-5854/edu.berkeley.eecs.emission D/CordovaWebViewImpl: >>> loadUrl(javascript:cordova.plugins.notification.local.fireEvent("click",{"id":362253744,"title":"Incorrect app settings","text":"Click to view and fix app status","data":{"redirectTo":"root.main.control","redirectParams":{"launchAppStatusModal":true}},"trigger":{"type":"calendar"},"progressBar":{"enabled":false}},{"event":"click","foreground":false,"queued":false,"notification":362253744}))

Next time, there were no logs in the emission process and it didn't work

2022-03-25 13:34:52.488 5854-5854/edu.berkeley.eecs.emission I/AbstractClickReciever: Resumed with application contextandroid.app.Application@e0d736a

@shankari
Copy link
Contributor Author

Now we have a bunch of options:

  • we can remove the sync name and sync from the same main process
  • we can try to switch to a different mechanism for saving that is hopefully not as process-dependent, namely the local storage. Note that this should also fix the shared preferences crash.

Let's first see if the first option works (to prove to ourselves that we understand the problem).

@shankari
Copy link
Contributor Author

On physical phone (to ensure that the task runs every 10 minutes)

  • 13:37: works
2022-03-25 13:37:44.647 8191-8841/edu.berkeley.eecs.emission I/NotificationHelper: Using app context to schedule new notificationandroid.app.Application@196b35b
  • 13:49: didn't work

Phone disconnected, so no logs, but we know what is going on.

@shankari
Copy link
Contributor Author

shankari commented Mar 25, 2022

Without sync as a separate process (in the emulator):

  • 13:56: works
  • 14:51: works
  • 15:52: works

This works, but it looks like it is only invoked once an hour.
Ah this is because when I reinstalled the plugin, it reset to 1 hour!

Deployed onto physical phone to avoid issue with background operation on emulator

  • 3:05: works
  • 3:06: works
  • 4:29: works
  • 4:30 works

@shankari
Copy link
Contributor Author

Reinstalled at around 4:30 with a 10 min cadence

Emulator:

  • 4:36: works
  • 4:43: works
  • 4:58: works
  • 5:13: works

Physical device:

  • 4:55: works
  • 5:05: works
  • 5:22: works
  • 5:27: works

So it seems pretty clear that this works.

@shankari
Copy link
Contributor Author

Tried with the physical device multiple times over the weekend and they all worked.

@shankari
Copy link
Contributor Author

Has been working in the emulator all morning

2022-03-27 23:15:58.281 15654-5209/edu.berkeley.eecs.emission I/NotificationHelper: Using app context to schedule new notificationandroid.app.Application@2e0a05b
2022-03-28 07:32:14.790 15654-15092/edu.berkeley.eecs.emission I/NotificationHelper: Using app context to schedule new notificationandroid.app.Application@2e0a05b
2022-03-28 07:45:51.431 15654-22549/edu.berkeley.eecs.emission I/NotificationHelper: Using app context to schedule new notificationandroid.app.Application@2e0a05b
2022-03-28 07:59:54.141 15654-30378/edu.berkeley.eecs.emission I/NotificationHelper: Using app context to schedule new notificationandroid.app.Application@2e0a05b
2022-03-28 08:42:24.085 15654-6645/edu.berkeley.eecs.emission I/NotificationHelper: Using app context to schedule new notificationandroid.app.Application@2e0a05b
2022-03-28 09:16:25.185 15654-25396/edu.berkeley.eecs.emission I/NotificationHelper: Using app context to schedule new notificationandroid.app.Application@2e0a05b
2022-03-28 09:27:35.245 15654-32106/edu.berkeley.eecs.emission I/NotificationHelper: Using app context to schedule new notificationandroid.app.Application@2e0a05b

And has also worked consistently in the physical device over the weekend.

This is definitely one solution.

@shankari
Copy link
Contributor Author

Before we decide that this is the solution, let us look at the crashes related to accessing shared preferences while the screen is locked.
Screen Shot 2022-03-28 at 1 47 27 PM

@shankari
Copy link
Contributor Author

shankari commented Apr 4, 2022

This has a fix that is both in the master branch
katzer/cordova-plugin-local-notifications@376871d

and in the timkelleypa fork
timkellypa/cordova-plugin-local-notifications@376871d

We should switch to one of them.

Let's try timkelleypa, which seems to have some more recent updates, although they are still from 2020.
The last updates on master are from 2019.

@shankari
Copy link
Contributor Author

shankari commented Apr 5, 2022

timkelleypa seems to build and not have any regressions.

So we now need to make the final decision on whether:

  • to run the sync in the main process, OR
  • to switch to local storage

Since we don't need to switch to local storage to fix the crash, and we don't have a principled reason for using a separate process for the sync[1], let's go with the first option. The only downside that I can think of is that then a crash in the sync will crash the app process. But the app process can always be killed due to memory issues, and we have to remember to restart it. So this does not appear to significantly impact robustness.

[1] other than "that's what the content provider template used"

@shankari
Copy link
Contributor Author

shankari commented Apr 5, 2022

Testing on physical device before pushing the changes.

@shankari
Copy link
Contributor Author

shankari commented Apr 6, 2022

6:37: notification works on emission, does not open correctly on CanBikeCO
6:40: notification works on emission
8:12: notification works on emission, does not work on CanBikeCO

I claim that this is fixed and will push out the change tonight

shankari added a commit to shankari/cordova-server-sync that referenced this issue Apr 8, 2022
So that notifications generated from sync open the app properly and launch the
status screen.

This implements
e-mission/e-mission-docs#712 (comment)
shankari added a commit to shankari/e-mission-phone that referenced this issue Apr 8, 2022
- Update the sync plugin so that it doesn't run in a separate process
- Update the local notification plugin so that it doesn't crash on startup if the screen is locked

Both of these are tracked in
e-mission/e-mission-docs#712
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

1 participant