Fix: Anonymous Login request not cleared if app is forced close within 5 seconds on a new install #2251

jinliu9508 · 2025-01-31T21:24:15Z

Description

One Line Summary

This PR fixes an issue where subscriptions do not update correctly and results in a 400 error when calling Login. It also handles this bad state when migrating from any previous version.

Details

Motivation

There is an edge case where the app successfully creates a user for the first time, but the request remains in the queue due to the PostCreateDelay. When this happens, all future Login calls return a 400 error, and any subscription updates fail. This PR prevents this scenario by correctly updating the operation queue and handling the bad state during migration.

Scope

OperationRepo: No longer holds up operation processing before the PostCreateDelay. Instead, the waiting time for PostCreateDelay is now integrated into delayBeforeNextExecution at the end of execution.
LoginUserOperationExecutor: Now detects if an anonymous Login request is made without other operations. When this happens, it returns a FAIL_NORETRY and drops the duplicated Login request.

Testing

Manual testing

###Steps to reproduce
This bug can happen strictly after CreateUser is successful for the first time but the app is force-closed before the 5 seconds PostCreateDelay has reached. One way to reproduce this issue is:

Fresh install the app.
Right after the subscription is created or receiving a 200 code from the Create User request, quickly force close the app within 5 seconds.
Re-open the app, observe that a 400 error code is received and any updates like subscribing is not updated in the dashboard.

###New Install
Step 1-2 same as above
3. Re-open the app, wait for the server response and observe that Login with the external ID is successful. Confirmed that no error is logged and the fix works.

###Update From the Broken Version
Step 1-2 same as above
3. upgrade to this version without uninstalling the previous version or clearing the storage, observe that Login with the externalID is successful without error.

Affected code checklist

Checklist

Overview

I have filled out all REQUIRED sections above
PR does one thing
- If it is hard to explain how any codes changes are related to each other then it most likely needs to be more than one PR
Any Public API changes are explained in the PR details and conform to existing APIs

Testing

I have included test coverage for these changes, or explained why they are not needed
All automated tests pass, or I explained why that is not possible
I have personally tested this on my device, or explained why that is not possible

Final pass

Code is as readable as possible.
- Simplify with less code, followed by splitting up code into well named functions and variables, followed by adding comments to the code.
I have reviewed this PR myself, ensuring it meets each checklist item
- WIP (Work In Progress) is ok, but explain what is still in progress and what you would like feedback on. Start the PR title with "WIP" to indicate this.

This change is

jkasten2

Let's add a test too

jkasten2 · 2025-01-31T22:30:35Z

...ain/java/com/onesignal/user/internal/operations/impl/executors/LoginUserOperationExecutor.kt

+        // Login operation being processed alone will surely be rejected, so we need to add an existing
+        // external ID to this legacy operation and have it picked up by SetAlias.
+        if (operations.isEmpty() && _identityModelStore.model.externalId != null) {
+            loginUserOp.externalId = _identityModelStore.model.externalId


Could there be an issue with properties being set on the wrong user?
Example:

Login(A)

setTag(A)

Login(B)

setTag(B)

Could this cause User B to get both tag A and B, when it was intended for User A to get tag A and User B to get Tag B?

I just tested this scenario and this is how the manual test is setup:

Fresh install on main branch, right after the anonymous user is created but before the post create delay, programmatically call Login(A), setTag(A), Login(B), setTag(B) altogether and close the app.

Switch to this branch and update the app.

Run the app and observe in the dashboard that both users are created successfully and each with the correct tag.

After analyzing the log closely, the code in this if statement will actually never hit for the scenario. OperationRepo will process the operations in this order:

Create subscription

Login anonymously

Refresh user (anonymous)

Login A AND transfer subscription

Set Alias for A but got 409

Refresh user (A)

Set Tag for A

Login B AND transfer subscription

Set Tag for B

Since operations like setting tags does not go with the Login call in one request and the handler for 409 conflict will take care of the IDs, this will not cause the user to be assigned with the wrong tag.

Further more, I tested out that this bug only happen when Login is interrupted with no other operations like set tag or another Login within a few seconds after app starts up.

jkasten2 · 2025-02-04T00:17:02Z

...ain/java/com/onesignal/user/internal/operations/impl/executors/LoginUserOperationExecutor.kt

+        // Login operation being processed alone will surely be rejected, so we need to drop the request
+        if (operations.isEmpty()) {
+            return ExecutionResponse(ExecutionResult.FAIL_NORETRY)
+        }


If loginUserOp.externalId is set then the operation is still valid, we probably shouldn't drop that.

I have updated the PR description, code, and test cases so that Login with external ID is no long be dropped. Only anonymous Login that is not grouped with any other operations will be dropped.

nan-li · 2025-02-04T06:34:39Z

...DK/onesignal/core/src/main/java/com/onesignal/core/internal/operations/impl/OperationRepo.kt

-        val delayFor = max(delayForOnRetries, retryAfterSecondsNonNull * 1_000)
+        val delayFor = max(delayForOnRetries, max(retryAfterSecondsNonNull * 1_000, postCreateDelay))
        if (delayFor < 1) return
        Logging.error("Operations being delay for: $delayFor ms")


Logging.error("Operations being delay for: $delayFor ms")

Following up from above, especially since we also log this delay as an error, since it represents a "failure response" fundamentally.

The log will not be related to the postCreateDelay anymore since it is moved to a separate logic.

nan-li · 2025-02-04T07:44:30Z

...ain/java/com/onesignal/user/internal/operations/impl/executors/LoginUserOperationExecutor.kt

+        // Handle a bad state that can happen in User Model 5.1.27 or earlier versions that old Login
+        // request is not removed after processing if app is force-closed within the PostCreateDelay.
+        // Anonymous Login being processed alone will surely be rejected, so we need to drop the request
+        if (operations.isEmpty() && loginUserOp.externalId == null) {


We should log an error.

The isEmpty() is probably sufficient for this edge case. Technically this should be a check for the existence of a create/transfer subscription operation, as another user update operation, for example, is not sufficient.

I was thinking to prevent dropping the login request with an externalId. However, even login with an externalId will usually require a transfer subscription so theoretically these will have the same result. Do you think we should allow login operation with an externalId that has no other operations to be processed?

Yeah we should keep login with external ID regardless of subscriptions, since generally the SDK can recover in that state.
I meant for the check itself: operations.isEmpty() && loginUserOp.externalId == null vs something like operations.doesNotContainSub() && loginUserOp.externalId == null

I agree, with operations.doesNotContainSub() && loginUserOp.externalId == null. This way the validation matches what the backend does.

I made a change that checks if there exists any CreateSubscription or TransferSubscription operation. Will this be sufficient?

nan-li · 2025-02-04T07:54:20Z

...core/src/test/java/com/onesignal/user/internal/operations/LoginUserOperationExecutorTests.kt

        }
    }
+
+    test("ensure anonymous login with no other operations will fail with FAIL_NORETRY to release the queue from a bad state") {


I think explanations like "to release the queue from a bad state" should not be part of the test name, it should simply state behavior.
This tests the upgrade fix only, we should have a test that repros the original problematic behavior of not removing successful operations from the repo.

Good point! I have fixed the explanation and created a new test case in OperationRepoTests to test this behavior.

...DK/onesignal/core/src/main/java/com/onesignal/core/internal/operations/impl/OperationRepo.kt

nan-li · 2025-02-04T08:01:34Z

...DK/onesignal/core/src/main/java/com/onesignal/core/internal/operations/impl/OperationRepo.kt


    /**
-     * Wait which ever is longer, retryAfterSeconds returned by the server,
+     * Wait which ever is longer, post create delay, retryAfterSeconds returned by the server,


The PostCreateDelay should probably be a separate delay from the original intention of this method, which is to generate a delay in failure scenarios, since it is operating on the retryWaiter.

I think the delays should be interceptable because if both postCreateDelay and retryDelay are set to 5 seconds, the total wait time should just be 5 seconds instead of 10 seconds if wait for them separately.

We shouldn't confound the waiter with the retryWaiter just because in this particular scenario, the result feels the same. The retryWaiter is meant for retryable errors and can be forced when consent changes.

Both are not going to run: (1) The postCreateDelay is after a create call is successful and the response has ID translations, (2) The retries count and retryAfterSeconds that is original to this method is for failures. Either the operations are successful and contain translation IDs or it is not and is retryable.

I see, the waiters are different. I separated the logic in the fixup commit. Both waiters can be waiting together for different duration, but operations processing will be resumed as soon as both waiter are awake. In this case the stall time is the same as the maximum wait time among them.

...DK/onesignal/core/src/main/java/com/onesignal/core/internal/operations/impl/OperationRepo.kt

nan-li · 2025-02-04T20:34:53Z

...DK/onesignal/core/src/main/java/com/onesignal/core/internal/operations/impl/OperationRepo.kt

+     * however other parts of the system don't currently account
+     * for this so this is not safe to do.
+     */
+    suspend fun delayForPostCreate(hasIDTranslation: Boolean) {


Nit: I think this method should be conditionally called, instead of letting this method check if it should delay using the passed in argument.

Good point, I have made that change in the fixup commit.

nan-li

Can clean up commit history, and reword the PR title?

fix

…d fix some other test cases

jinliu9508 · 2025-02-04T23:23:32Z

Title is updated and commits are cleaned up.

jinliu9508 requested review from jkasten2 and nan-li January 31, 2025 21:27

jinliu9508 assigned jkasten2 Jan 31, 2025

jkasten2 requested changes Jan 31, 2025

View reviewed changes

jinliu9508 force-pushed the subscription-not-updated-due-to-400-error branch 4 times, most recently from 8c75690 to ea56a21 Compare February 3, 2025 23:43

jkasten2 requested changes Feb 4, 2025

View reviewed changes

jinliu9508 force-pushed the subscription-not-updated-due-to-400-error branch from ea56a21 to efa596f Compare February 4, 2025 00:45

jinliu9508 requested a review from jkasten2 February 4, 2025 00:55

jinliu9508 force-pushed the subscription-not-updated-due-to-400-error branch 3 times, most recently from ddafc37 to 20951a6 Compare February 4, 2025 04:38

nan-li requested changes Feb 4, 2025

View reviewed changes

jinliu9508 force-pushed the subscription-not-updated-due-to-400-error branch 3 times, most recently from 2c04789 to e5b8eb3 Compare February 4, 2025 20:06

jinliu9508 requested a review from nan-li February 4, 2025 20:08

jkasten2 reviewed Feb 4, 2025

View reviewed changes

...DK/onesignal/core/src/main/java/com/onesignal/core/internal/operations/impl/OperationRepo.kt Outdated Show resolved Hide resolved

...DK/onesignal/core/src/main/java/com/onesignal/core/internal/operations/impl/OperationRepo.kt Outdated Show resolved Hide resolved

jinliu9508 requested a review from jkasten2 February 4, 2025 20:32

nan-li reviewed Feb 4, 2025

View reviewed changes

jinliu9508 force-pushed the subscription-not-updated-due-to-400-error branch from 4f1368d to 5272900 Compare February 4, 2025 20:57

jinliu9508 requested a review from nan-li February 4, 2025 21:17

jkasten2 approved these changes Feb 4, 2025

View reviewed changes

nan-li approved these changes Feb 4, 2025

View reviewed changes

jinliu9508 changed the title ~~Fix: bug causes the subscription not updated correctly with a 400 error~~ Fix: Anonymous Login request not cleared if app is forced close within 5 seconds on a new install Feb 4, 2025

jinliu9508 added 3 commits February 4, 2025 18:07

fix: login operation not removed from queue within postCreateDelay

3ad85b2

fix: Login request without subscription now returns FAIL_NORETRY

28e1e24

fix

Add: new test case for anonymous login with no create subscription an…

47afee3

…d fix some other test cases

jinliu9508 force-pushed the subscription-not-updated-due-to-400-error branch from 5272900 to 47afee3 Compare February 4, 2025 23:11

jinliu9508 merged commit 9d1d91c into main Feb 4, 2025
2 checks passed

jinliu9508 deleted the subscription-not-updated-due-to-400-error branch February 4, 2025 23:23

jinliu9508 mentioned this pull request Feb 4, 2025

Release 5.1.28 #2256

Merged

Fix: Anonymous Login request not cleared if app is forced close within 5 seconds on a new install #2251

Fix: Anonymous Login request not cleared if app is forced close within 5 seconds on a new install #2251

Uh oh!

Conversation

jinliu9508 commented Jan 31, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Description

One Line Summary

Details

Motivation

Scope

Testing

Manual testing

Affected code checklist

Checklist

Overview

Testing

Final pass

Uh oh!

jkasten2 left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jinliu9508 Feb 3, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

nan-li Feb 4, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

nan-li left a comment

Choose a reason for hiding this comment

Uh oh!

jinliu9508 commented Feb 4, 2025

Uh oh!

Uh oh!

Uh oh!

jinliu9508 commented Jan 31, 2025 •

edited

Loading

jinliu9508 Feb 3, 2025 •

edited

Loading

nan-li Feb 4, 2025 •

edited

Loading