[CRITICAL BUG] onSharedPreferenceChanged() does not fire reliably when multiple processes are writing at the same time

[teqtic]

I was seeing some occasional weirdness in my app after migrating over to Harmony. It looks like onSharedPreferenceChanged() does not fire in another process if that process happens to be committing at the same time.

Steps to reproduce:

1) In an activity, run this at the tap of a button:

sharedPrefsEditor.putBoolean("testKey1", false).commit();
sharedPrefsEditor.putBoolean("testKey2", false).commit();

2) In another process (in my case a foreground service):

@Override
            public void onSharedPreferenceChanged(@NotNull SharedPreferences sharedPreferences, @org.jetbrains.annotations.Nullable String prefKey) {

                if (prefKey == null) {
                    Utils.logWarn(TAG, "null key!");
                    return;
                }

                Utils.logDebug(TAG, "onSharedPreferenceChanged() prefKey: " + prefKey);

                if (prefKey.equals("testKey1") || prefKey.equals("testKey2")) {
                    sharedPrefsEditor.putBoolean("testKey3", false).commit();
                }
            }

The expected output is:

onSharedPreferenceChanged() prefKey: testKey1
onSharedPreferenceChanged() prefKey: testKey3
onSharedPreferenceChanged() prefKey: testKey2
onSharedPreferenceChanged() prefKey: testKey3

The actual output is USUALLY:

onSharedPreferenceChanged() prefKey: testKey1
onSharedPreferenceChanged() prefKey: testKey3

onSharedPreferenceChanged() does not fire for testKey2 changing at all!

I have also rarely seen:

onSharedPreferenceChanged() prefKey: 2
onSharedPreferenceChanged() prefKey: 1
onSharedPreferenceChanged() prefKey: 3
onSharedPreferenceChanged() prefKey: 3

... which would be fine, but this is not usually the case.

This does NOT happen to a listener in the same activity making the testKey1 and testKey2 commits.

This does NOT happen if you commit both keys at the same time:

sharedPrefsEditor.putBoolean("testKey1", false);
sharedPrefsEditor.putBoolean("testKey2", false);
sharedPrefsEditor.commit();

This does NOT happen if using sharedPrefsEditor.apply() in the activity instead of commit(), but I have a feeling that's just because the write in the service is being called after the commit is already persisted to disk, so it's not really happening at the same time in this test.

P.S. apply() seems to be preferred since it is asynchronous and leaves the writing to the background. Does onSharedPreferenceChanged() only fire once it's persisted to disk? In that case, when is using commit() necessary or preferred over apply()?

P.S. Super minor but the regular SharedPreferences listener is named OnSharedPreferenceChangeListener. The Harmony version is named OnHarmonySharedPreferenceChange**d**Listener. Is this on purpose?

[pablobaxter]

I'm curious if this also happens in the Android SharedPreference as well. I believe it may be a deadlock of the main thread, as the call to commit() blocks the thread until it completes, and the callback of OnSharedPreferenceChangeListener occurs on the main thread.

apply() seems to be preferred since it is asynchronous and leaves the writing to the background. Does onSharedPreferenceChanged() only fire once it's persisted to disk? In that case, when is using commit() necessary or preferred over apply()?

If it's listened on the same process, it'll fire once it's committed to memory. If it's on a different process, the preference change will trigger once it's committed to disk.

Super minor but the regular SharedPreferences listener is named OnSharedPreferenceChangeListener. The Harmony version is named OnHarmonySharedPreferenceChangedListener. Is this on purpose?

That is totally a typo. I can make a new class with the correct name, and deprecate this class in the next version. Great catch!

[teqtic]

Hard to say whether this happens with the Android SharedPreferences since that doesn't work correctly with multiple processes, which why we're here in the first place.

I'm not sure what thread deadlocking is, but if it's similar to a thread sleeping or busy doing work, shouldn't the listener still fire after the commit is done? It never ends up firing. Can this be fixed?

Is it safe to use apply() instead or could this issue manifest with apply() as well if the timing is just right?

[teqtic]

Unfortunately after some more testing it looks like using apply() does not fix the issue. Steps to reproduce:

1) In the first process (in my case onStartCommand() of a foreground service), run a loop that will write every 10ms for 10s:

Utils.logDebug(TAG, "Starting loop in service!");
        i = 0;
        handler = new Handler();
        runnable = new Runnable() {
            @Override
            public void run() {
                sharedPrefsEditor.putBoolean("testKey1", true).apply();
                if (i < 1000) {
                    handler.postDelayed(runnable, 10);
                    i++;
                    //Utils.logDebug(TAG, "i: " + i);
                } else {
                    Utils.logDebug(TAG, "Ended loop in service!");
                }
            }
        };
        runnable.run();

2) Also set up a listener in this process:

@Override
            public void onSharedPreferenceChanged(@NotNull SharedPreferences sharedPreferences, @org.jetbrains.annotations.Nullable String prefKey) {

                Utils.logDebug(TAG, "onSharedPreferenceChanged() prefKey: " + prefKey);
            }

3) In a second process (in my case activity onStart()), run a loop that will run for 5 seconds, writing 10 times every 500ms:

Utils.logDebug(TAG, "Starting loop in activity!");
        i = 0;
        handler = new Handler();
        runnable = new Runnable() {
            @Override
            public void run() {
                sharedPrefsEditor.putBoolean("testKey2", false).apply();
                if (i < 10) {
                    handler.postDelayed(runnable, 500);
                    i++;
                    //Utils.logDebug(TAG, "i: " + i);
                } else {
                    Utils.logDebug(TAG, "Ended loop in activity!");
                }
            }
        };
        runnable.run();

4) Start the service to run the loop for 10s. You have 5 seconds to start the activity so it can try to write prefKey2 while the service is writing prefKey1 frequently.

5) Make sure the logcat contains "Starting loop in service!" and that it wasn't truncated.

6) Make sure the logcat contains "Ended loop in service!" after "Ended loop in activity!". If it doesn't, you didn't start the loop in the activity in time.

Expected output: "onSharedPreferenceChanged() prefKey: testKey2" should appear in the logcat 10 times.

Actual output: "onSharedPreferenceChanged() prefKey: testKey2" appears in the logcat 7-8 times. Some of the calls to onSharedPreferenceChanged are never received by the service in the other process!

[teqtic]

Found a cleaner way to demonstrate the bug that also fails more often. Have 2 processes write at the same time and listen for changes from both. Here are the steps to reproduce.

1 ) In the first process' onCreate (my case a service) run a loop that will write testKey1 every 2 seconds at the nearest second. We will start the loop when the second process tells it to via a sharedPrefs change (step 2):

@Override
            public void onSharedPreferenceChanged(@NotNull SharedPreferences sharedPreferences, @org.jetbrains.annotations.Nullable String prefKey) {

                Utils.logDebug(TAG, "onSharedPreferenceChanged() prefKey: " + prefKey);

                if (prefKey.equals("startLoopInFirstProcess")) {
                    Utils.logDebug(TAG, "Starting loop in service!");
                    i = 0;
                    handler = new Handler();
                    runnable = new Runnable() {
                        @Override
                        public void run() {
                            //Utils.logDebug(TAG, "---Running at SystemClock.uptimeMillis(): " + SystemClock.uptimeMillis());
                            sharedPrefsEditor.putBoolean("testKey1", true).apply();

                            if (i < 30) {
                                handler.postAtTime(runnable, (SystemClock.uptimeMillis() / 1000 * 1000) + 2000);
                                i++;
                            } else {
                                Utils.logDebug(TAG, "Ended loop in service!");
                            }
                        }
                    };
                    handler.postAtTime(runnable, (SystemClock.uptimeMillis() / 1000 * 1000) + 2000);
                }
            }

2) In the second process' onCreate (my case an activity) run a loop that will write testKey2 every 2 seconds at the nearest second. Trigger the first process to start its loop at the same time so that they are synced:

Utils.logDebug(TAG, "Starting loop in activity!");
        i = 0;
        handler = new Handler();
        runnable = new Runnable() {
            @Override
            public void run() {
                //Utils.logDebug(TAG, "---Running at SystemClock.uptimeMillis(): " + SystemClock.uptimeMillis());
                sharedPrefsEditor.putBoolean("testKey2", true).apply();

                if (i < 30) {
                    handler.postAtTime(runnable, (SystemClock.uptimeMillis() / 1000 * 1000) + 2000);
                    i++;
                } else {
                    Utils.logDebug(TAG, "Ended loop in activity!");
                }
            }
        };
        handler.postAtTime(runnable, (SystemClock.uptimeMillis() / 1000 * 1000) + 2000);
        sharedPrefsEditor.putBoolean("startLoopInFirstProcess", true);

3) Set up a listener in both processes:

@Override
            public void onSharedPreferenceChanged(@NotNull SharedPreferences sharedPreferences, @org.jetbrains.annotations.Nullable String prefKey) {

                Utils.logDebug(TAG, "onSharedPreferenceChanged() prefKey: " + prefKey);
            }

4) Start up the first process, then the second and clear the logcat.

5) Filter the logcat to one process at a time and look at the output every 2 seconds. You can even clear the logcat after seeing the output, before the next output comes in, to make the output more clear.

Expected result: You would expect each listener to fire both for the change made in its own process and the other process:

onSharedPreferenceChanged() prefKey: testKey1
onSharedPreferenceChanged() prefKey: testKey2

Actual result: In my service process I usually only see the self change: onSharedPreferenceChanged() prefKey: testKey1

In my activity process I usually see both, but occasionally only the self change: onSharedPreferenceChanged() prefKey: testKey2

This is a blocking bug for me! I can't use the library like this since I can't guarantee different processes are not writing at the same time. I can try to help look at the code for Harmony but I'm afraid I can't read Kotlin very well.

[pablobaxter]

I think I found the bug, and it has to do with the timing of the changes. Essentially, when you call the following on the first process:

// Primary process
sharedPrefsEditor.putBoolean("testKey1", false).commit();
sharedPrefsEditor.putBoolean("testKey2", false).commit();

You create two transactions in Harmony, each with their own timestamp. This gets stored, which notifies the other processes. So then what you have is this:

// Transactions
-> testKey1 transaction timestamp 1
-> testKey2 transaction timestamp 2

What happens in your scenario is that you create a new transaction by committing the event of testKey3 on the alternate process. This means that when testKey2 transaction comes in, it's considered "old" (since testKey3 is now the "last" transaction), and it's basically ignored for the change listener (but not for storage). To illustrate this situation:

onSharedPrefChange -> emit testKey1
create transaction for testKey3
-> testKey3 transaction timestamp 3
receive testKey2 transaction
testKey2 transaction is old compared to testKey3, do not emit

I do want to make clear your data is stored. It's just that some logic meant to prevent re-emitting changed keys also was preventing the new keys from emitting in this particular circumstance.

[teqtic]

Good work! Whether or not it's saved, I still need the notifications to work reliably, or else one process will continue with old data from local memory and end up updating the shared prefs later without the change from the other process included. i.e. I don't check sharedPrefs every time I need a value. I have a local variable that is updated from shared prefs when there's a change notification. Plus the change may need to trigger certain code when it does change.

Do my second and third ways to reproduce above also cover the same cause you found? Are you able to fix it relatively easily?