Subscription List Subscribe/Unsubscribe Bug

[davidhartley]

A bewildering bug regarding the local state of subscriptionLists

What Airship dependencies are you using?

16.7.1 all three libraries urbanairship-fcm, urbanairship-automation, and urbanairship-message-center

Report

What unexpected behavior are you seeing?

Subscribing or unsubscribing to a subscription list doesn't update the subscriptionLists for a contact unless you call get() immediately after apply()

What is the expected behavior?

apply() by itself should work and update the local data

What are the steps to reproduce the unexpected behavior?

Example code

UAirship.shared().contact.editSubscriptionLists().subscribe(subscriptionId, Scope.APP).apply()
// Not sure why we need to call get here again, but the subscribe doesn't stick without it - SDK bug?
UAirship.shared().contact.getSubscriptionLists(true).get()

If I remove the get() after the apply() then the subscribe (or unsubscribe) is not saved and the next time the client calls for getSubscriptionLists(true) the change will not there. However if the get() is there as above it works fine.

I believe it has to do with the local state of the subscriptionList not what is happening on the server. If you relaunch the app, the state was updated successfully, it's just when you later call getSubscriptionLists(true) later on the same instance after subscribing/unsubscribing that the state is incorrect.

[rlepinski]

Could you show me how you are using UAirship.shared().contact.getSubscriptionLists(true) without a get? getSubscriptionLists returns a future so you need to set a callback or get the value or it wont return anything.

[rlepinski]

@davidhartley Trying to figure out how to reproduce an edit now showing, maybe you can help here? I have this so far and its all working as expected:

        Logger.error("Lists: %s", UAirship.shared().contact.getSubscriptionLists().get())
        UAirship.shared().contact.editSubscriptionLists().subscribe("goat", Scope.APP).apply()

        Handler().postDelayed({
            Logger.error("List after 5000: %s", UAirship.shared().contact.getSubscriptionLists().get())
        }, 5000)

As well as this:

        UAirship.shared().contact.getSubscriptionLists().addResultCallback {
            Logger.error("List result callback: %s", it)
        }

[davidhartley]

@rlepinski I am using a get() - it is a bit mysterious overall though. It doesn't make sense what I'm seeing. Checking the list immediately after a subscribe or unsubscribe is fine, it's just later after doing some navigation (fragments) that the list appears incorrect.

Here's my function to check if a user has a subscription by ID:

    fun userHasSubscription(subscriptionId: String): Boolean {
        UAirship.shared().contact.getSubscriptionLists(true).get()?.let { subscriptionLists ->
            return subscriptionLists[subscriptionId]?.contains(Scope.APP) == true
        }
        return false
    }

And then here's my subscribe/unsubscribe functions

    fun subscribeToSubscriptionList(subscriptionId: String) {
        UAirship.shared().contact.editSubscriptionLists().subscribe(subscriptionId, Scope.APP).apply()
        // Not sure why we need to call get here again, but the subscribe doesn't stick without it - SDK bug?
        UAirship.shared().contact.getSubscriptionLists(true).get()
    }

    fun unsubscribeFromSubscriptionList(subscriptionId: String) {
        UAirship.shared().contact.editSubscriptionLists().unsubscribe(subscriptionId, Scope.APP).apply()
        // Not sure why we need to call get here again, but the subscribe doesn't stick without it - SDK bug?
        UAirship.shared().contact.getSubscriptionLists(true).get()
    }

Basically I have a fragment that does some checking and modifying the subscription lists if the user wants. But if I don't have that UAirship.shared().contact.getSubscriptionLists(true).get() immediately after the subscribe or unsubscribe, then back out of the fragment and then go to the fragment again later, and userHasSubscription() is called, the lists that come back are incorrect. I looked a little bit at the source code and it doesn't really seem obvious why this could occur. Very strange.

[davidhartley]

Here's a short video showing the debugger with the list not getting updated during subscribe: https://user-images.githubusercontent.com/4510491/189365447-a6140687-9460-4b93-b34b-7adece0c246f.mov

[rlepinski]

Could you add some log lines to the beginning of your two methods and enable verbose logging on Airship, then capture logs showing that issue? I can provide my email address if you dont want to post the logs here

[davidhartley]

Here you go basically the same thing I showed in the video:

• Go to fragment, check subscription lists (empty)
• Subscribe
• Back out of fragment
• Go back to fragment
• Check subscription lists (empty)

I don't see any additional logs for the getSubscriptionLists, just for the subscribe. It's clearly working on the server, which I can tell by the logs and if I kill the app and restart it after a subscribe or unsubscribe. At that point the subscription list is correct.

2022-09-09 11:29:13.665 9241-9311/com.cfahome.esr.dev D/EGL_emulation: app_time_stats: avg=445.33ms min=12.00ms max=7311.33ms count=17
2022-09-09 11:29:13.799 9241-9286/com.cfahome.esr.dev V/AppSyncOfflineMutationInterceptor: Thread:[76]: processing Mutations
2022-09-09 11:29:13.799 9241-9286/com.cfahome.esr.dev V/QueueUpdateHandler: Thread:[76]: Got message to take action on the mutation queue.
2022-09-09 11:29:13.800 9241-9286/com.cfahome.esr.dev V/QueueUpdateHandler: Thread:[76]: Got message to process next mutation if one exists.
2022-09-09 11:29:15.317 9241-9311/com.cfahome.esr.dev D/EGL_emulation: app_time_stats: avg=103.20ms min=14.77ms max=1396.45ms count=16
2022-09-09 11:29:16.594 9241-9311/com.cfahome.esr.dev D/EGL_emulation: app_time_stats: avg=63.18ms min=1.91ms max=1010.90ms count=17
2022-09-09 11:29:16.603 9241-9241/com.cfahome.esr.dev V/ESR Dev - UALib: PreferenceDataStore - Preference updated: com.urbanairship.contacts.OPERATIONS
2022-09-09 11:29:16.604 9241-9499/com.cfahome.esr.dev V/ESR Dev - UALib: PreferenceDataStore - Saving preference: com.urbanairship.contacts.OPERATIONS value: [{"TYPE_KEY":"RESOLVE"}]
2022-09-09 11:29:16.606 9241-9241/com.cfahome.esr.dev V/ESR Dev - UALib: PreferenceDataStore - Preference updated: com.urbanairship.contacts.OPERATIONS
2022-09-09 11:29:16.607 9241-9499/com.cfahome.esr.dev V/ESR Dev - UALib: PreferenceDataStore - Saving preference: com.urbanairship.contacts.OPERATIONS value: [{"TYPE_KEY":"RESOLVE"},{"PAYLOAD_KEY":{"TAG_GROUP_MUTATIONS_KEY":[],"ATTRIBUTE_MUTATIONS_KEY":[],"SUBSCRIPTION_LISTS_MUTATIONS_KEY":[{"action":"subscribe","list_id":"assert_alerts","scope":"app","timestamp":"2022-09-09T15:29:16"}]},"TYPE_KEY":"UPDATE"}]
2022-09-09 11:29:16.608 9241-9241/com.cfahome.esr.dev V/ESR Dev - UALib: PreferenceDataStore - Preference updated: com.urbanairship.contacts.OPERATIONS
2022-09-09 11:29:16.609 9241-9499/com.cfahome.esr.dev V/ESR Dev - UALib: PreferenceDataStore - Saving preference: com.urbanairship.contacts.OPERATIONS value: [{"PAYLOAD_KEY":{"TAG_GROUP_MUTATIONS_KEY":[],"ATTRIBUTE_MUTATIONS_KEY":[],"SUBSCRIPTION_LISTS_MUTATIONS_KEY":[{"action":"subscribe","list_id":"assert_alerts","scope":"app","timestamp":"2022-09-09T15:29:16"}]},"TYPE_KEY":"UPDATE"}]
2022-09-09 11:29:16.650 9241-9241/com.cfahome.esr.dev V/ESR Dev - UALib: AirshipWorker - Running job: JobInfo{action='ACTION_UPDATE_CONTACT', airshipComponentName='com.urbanairship.contacts.Contact', isNetworkAccessRequired=true, minDelayMs=0, conflictStrategy=2, initialBackOffMs=30000, extras={}, rateLimitIds=[Contact.update]}, work Id: 8a0a63a7-dd9a-4732-ba21-c6dd55f917e5 run attempt: 0
2022-09-09 11:29:16.651 9241-9241/com.cfahome.esr.dev V/ESR Dev - UALib: JobDispatcher - Running job: JobInfo{action='ACTION_UPDATE_CONTACT', airshipComponentName='com.urbanairship.contacts.Contact', isNetworkAccessRequired=true, minDelayMs=0, conflictStrategy=2, initialBackOffMs=30000, extras={}, rateLimitIds=[Contact.update]}, run attempt: 0
2022-09-09 11:29:16.761 9241-9501/com.cfahome.esr.dev V/ESR Dev - UALib: ContactApiClient - Update contact response status: 200 body: {"ok":true}
2022-09-09 11:29:16.761 9241-9501/com.cfahome.esr.dev D/ESR Dev - UALib: Contact - Operation ContactOperation{type='UPDATE', payload=UpdatePayload{tagGroupMutations=[], attributeMutations= [], subscriptionListMutations=[ScopedSubscriptionListMutation{action='subscribe', listId='assert_alerts', scope=app, timestamp='2022-09-09T15:29:16'}]}} finished with response Response{responseBody='{"ok":true}
    ', responseHeaders={null=[HTTP/1.1 200 OK], Alt-Svc=[h3=":443"; ma=2592000,h3-29=":443"; ma=2592000], Content-Length=[11], Content-Type=[application/vnd.urbanairship+json;version=3], Date=[Fri, 09 Sep 2022 15:29:17 GMT], Via=[1.1 google], X-Android-Received-Millis=[1662737356760], X-Android-Response-Source=[NETWORK 200], X-Android-Selected-Protocol=[http/1.1], X-Android-Sent-Millis=[1662737356654]}, status=200, lastModified=0}
2022-09-09 11:29:16.761 9241-9501/com.cfahome.esr.dev V/ESR Dev - UALib: PreferenceDataStore - Preference updated: com.urbanairship.contacts.OPERATIONS
2022-09-09 11:29:16.761 9241-9499/com.cfahome.esr.dev V/ESR Dev - UALib: PreferenceDataStore - Saving preference: com.urbanairship.contacts.OPERATIONS value: []
2022-09-09 11:29:16.762 9241-9501/com.cfahome.esr.dev V/ESR Dev - UALib: JobRunner - Finished: JobInfo{action='ACTION_UPDATE_CONTACT', airshipComponentName='com.urbanairship.contacts.Contact', isNetworkAccessRequired=true, minDelayMs=0, conflictStrategy=2, initialBackOffMs=30000, extras={}, rateLimitIds=[Contact.update]} with result: SUCCESS
2022-09-09 11:29:16.762 9241-9501/com.cfahome.esr.dev V/ESR Dev - UALib: JobDispatcher - Job finished. Job info: JobInfo{action='ACTION_UPDATE_CONTACT', airshipComponentName='com.urbanairship.contacts.Contact', isNetworkAccessRequired=true, minDelayMs=0, conflictStrategy=2, initialBackOffMs=30000, extras={}, rateLimitIds=[Contact.update]}, result: SUCCESS
2022-09-09 11:29:16.762 9241-9290/com.cfahome.esr.dev I/WM-WorkerWrapper: Worker result SUCCESS for Work [ id=8a0a63a7-dd9a-4732-ba21-c6dd55f917e5, tags={ airship, com.urbanairship.job.AirshipWorker } ]
2022-09-09 11:29:19.893 9241-9311/com.cfahome.esr.dev D/EGL_emulation: app_time_stats: avg=62.24ms min=11.65ms max=2439.92ms count=53
2022-09-09 11:29:21.514 9241-9311/com.cfahome.esr.dev D/EGL_emulation: app_time_stats: avg=95.36ms min=10.31ms max=1360.80ms count=17
2022-09-09 11:29:23.168 9241-9311/com.cfahome.esr.dev D/EGL_emulation: app_time_stats: avg=97.25ms min=7.86ms max=1396.47ms count=17
2022-09-09 11:29:23.813 9241-9286/com.cfahome.esr.dev V/AppSyncOfflineMutationInterceptor: Thread:[76]: processing Mutations
2022-09-09 11:29:23.813 9241-9286/com.cfahome.esr.dev V/QueueUpdateHandler: Thread:[76]: Got message to take action on the mutation queue.
2022-09-09 11:29:23.813 9241-9286/com.cfahome.esr.dev V/QueueUpdateHandler: Thread:[76]: Got message to process next mutation if one exists.

[rlepinski]

Thanks, nothing obvious is standing out. I will try to recreate your scenario to see if I can reproduce. If not, are you available for a zoom live debug session next week?

[rlepinski]

What threads are you calling subscribe and get on?

[davidhartley]

I'm available, we can work something out.

I had that thought about threads over lunch - the .getSubscriptionLists(true).get() occurs on IO threads via coroutines. The .subscribe(subscriptionId, Scope.APP).apply() is on the main thread since it happens in the background anyways. I can try moving them both to main just to see what happens.

[rlepinski]

I could see a scenario where get does not have the edits you apply if they are called roughly at the same time since they are on two threads. I would expect if you navigate back and forth the next time you do a get you should see them though.

[davidhartley]

Changing threads didn't make a difference. They aren't called at the same time or anything so it's probably not that.

I was looking through the source code in Contact.java and it looks like the in-memory cache (subscriptionListCache) is only set in one place - in the fallback to fetching block here:

 // Get the subscription lists from the in-memory cache, if available.
            Map<String, Set<Scope>> subscriptions = subscriptionListCache.get();
            if (subscriptions == null) {
                // Fallback to fetching
                subscriptions = fetchContactSubscriptionList(contactId);
                if (subscriptions != null) {
                    subscriptionListCache.set(subscriptions, SUBSCRIPTION_CACHE_LIFETIME_MS);
                }
            }

This is inside getSubscriptionLists(). In fact, I put a breakpoint in for CachedValue's set() and it is never called for the modified subscription list after subscribe or unsubscribe. It looks like the in-memory cache is never updated unless getSubscriptionLists() has a cache miss and it has to go back to the network.

[rlepinski]

That is expected, the cache is stored for up to 10 mins then we will fetch again. Pending edits are applied when you pass in true, and any edits that we send up are applied to the cache for up to 10 mins as well.

I think I see a potential race condition going from pending to local history, but it would not always be reproducible like what you are experiencing.

[rlepinski]

If you are debugging the SDK, the thing I am curious about is when fetch is being called what is in the pending vs local history? A snapshot of the state for here might help us figure it out - https://github.com/urbanairship/android-library/blob/main/urbanairship-core/src/main/java/com/urbanairship/contacts/Contact.java#L1197

[davidhartley]

I just stepped through it again and there are no mutation updates that get applied to the cached value, neither pending nor localHistory after subscribe/unsubscribe. Seems like there's an issue where the after the updates have succeeded on the server, the local cache is out of date, but no longer getting the local pending updates applied either.

Looks like in performOperation, the local history is never modified because lastContactIdentity.isAnonymous() returns false. Not sure what this means, but should it be NOT anonymous like below instead?

if (updateResponse.isSuccessful() && !lastContactIdentity.isAnonymous()) {

Here's the original block in full:

if (updateResponse.isSuccessful() && lastContactIdentity.isAnonymous()) {
                    updateAnonData(updatePayload, null);

                    if (!updatePayload.getAttributeMutations().isEmpty()) {
                        for (AttributeListener listener : this.attributeListeners) {
                            listener.onAttributeMutationsUploaded(updatePayload.getAttributeMutations());
                        }
                    }

                    if (!updatePayload.getTagGroupMutations().isEmpty()) {
                        for (TagGroupListener listener : this.tagGroupListeners) {
                            listener.onTagGroupsMutationUploaded(updatePayload.getTagGroupMutations());
                        }
                    }

                    if (!updatePayload.getSubscriptionListMutations().isEmpty()) {
                        cacheInSubscriptionListLocalHistory(updatePayload.getSubscriptionListMutations());
                    }
                }

As for your question, I'm only seeing fetch getting called at the first getSubscriptionList() call, I don't see it called again. There aren't any pending updates at that point. Though I'm not waiting the 10 minutes for the cache to expire either.

[rlepinski]

I added two buttons to a fragment with this binding and its always working.

binding.check.setOnClickListener { v: View? ->
    Toast.makeText(context, "Has \"sub $sub\" subscription: ${userHasSubscription("sub $sub")}", Toast.LENGTH_SHORT).show()
}

binding.subscribe.setOnClickListener { v: View? ->
    sub++
    UAirship.shared().contact.editSubscriptionLists().subscribe("sub $sub", Scope.APP)
        .apply()
    Toast.makeText(context, "Subscribed \"sub $sub\"", Toast.LENGTH_SHORT).show()
}

I did not test actually setting a named user. That code looks like the culprit.

[rlepinski]

YEP! That is the issue, it should be stored for all contacts. Ill try to get a patch out today, but might be Monday. Thanks for helping us figure this out.

[davidhartley]

Thanks a bunch!

[rlepinski]

Fixed in 16.7.3