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

fix: Subscription failed event should be terminal event #74

Merged
merged 1 commit into from
Feb 17, 2022

Conversation

lawmicha
Copy link
Contributor

@lawmicha lawmicha commented Feb 17, 2022

Issue #, if available:

Description of changes:
The caller of a subscription should only receive the .failed event once. A .failed event to the caller indicates that the subscription is in terminal state. In AppSync SDK, this event is propagated back to the caller in the resultHandler. In APIPlugin, this is in the completionListener. Data/Connection events are propagated in a different handler (statusHandler, progressHandler).

The bug is that the subscription will send multiple .failed events in a few scenarios.

  1. Subscription level messages (messages with the exact subscription ID) will be sent to all subscriptions and filtered out by other subscriptions. Errors are handled by sending the .failed event.
  2. Connection level messages will be sent to all subscriptions, the subscription will handle errors by sending the .failed event.
    Multiple .failed events can be caused by a combination of 1 and 2 or multiple instances of 1 or 2. The below scenario describes one scenario where there are multiple instances of 1. The 101st subscription reaches terminal state, and then the 102nd subscription causes subscription 101 to retry and send another .failed event to the caller.

MaxSubscriptionReached failure scenario

When there are 100 subscriptions subscribed to the connection, the 101st subscription will fail with MaxSubscriptionsReached and retry, and eventually the caller will receive the subscription failed to subscribe.

flowchart 
A[101st Subscription receives MaxSubscriptionReached] --> B{Retry Advice - Should retry?};
B -- Yes --> C[Connection.connect];
B -- No --> D[Send Failed event];
D ----> E[Caller];
C --> F[First 100 Subscriptions];
C --> G[101st Subscription];
F --> H[Already subscribed, No-op];
G --> I[Not subscribed, subscribe];
I --> A
Loading

When both 101st and 102nd subscriptions fail with MaxSubscriptionsReached, they both wait for retry to trigger. When retry is triggered, it will call Connection.connect. The connection will inform every subscription to handle the connected status. The first 100 subscriptions will ignore the connection event since they are already subscribed.

flowchart 
Z[Connection.receive] -->|MaxSubscriptionReached Sub 101| A[Sub 101 - .inProgress];
Z[Connection.receive] -->|MaxSubscriptionReached Sub 102| B[Sub 102 - .inProgress];
A --> A2[Sub 101 to .notSubscribed - Waiting for retry];
B --> B2[Sub 102 to .notSubscribed - Waiting for retry];
B2 --> |retry fired| A4[Call connection.connect];
A2 --> |retry fired| A4[Call Connection.connect];
A4 --> |send connected event|A5[Sub id 101 to inProgress];
A4 --> |send connected event|A6[Sub id 102 to inProgress];
A5 -->|send subscribe| Z2[Connection.write message]
A6 -->|send subscribe| Z2[Connection.write message]
Loading

When both subscriptions for waiting to retry, one of them will fire before the other. Say subscription 101 fires slightly before subscription 102, while 102 is still waiting to fire. 101's retry attempt causes both 101 and 102 to retry. Because 102 is attempting earlier than it should, it's retry attempts are exhausted first. One way to see this is to wait for 101 to retry a few times until it reaches a long wait time, then start 102 on its retry path.

[LAWMICHA] Connecting Sub 101 (8B930D03-B707-4C1F-A44A-CF867D69047C)
2022-02-17 02:38:27.687731-0500 AppSyncSample[49746:9568800] [AppSyncSubscriptionConnection] Retrying subscription 8B930D03-B707-4C1F-A44A-CF867D69047C after milliseconds(217)
2022-02-17 02:38:28.040812-0500 AppSyncSample[49746:9568534] [AppSyncSubscriptionConnection] Retrying subscription 8B930D03-B707-4C1F-A44A-CF867D69047C after milliseconds(476)
2022-02-17 02:38:28.678885-0500 AppSyncSample[49746:9568532] [AppSyncSubscriptionConnection] Retrying subscription 8B930D03-B707-4C1F-A44A-CF867D69047C after milliseconds(884)
2022-02-17 02:38:29.773876-0500 AppSyncSample[49746:9568534] [AppSyncSubscriptionConnection] Retrying subscription 8B930D03-B707-4C1F-A44A-CF867D69047C after milliseconds(1651)
2022-02-17 02:38:31.718702-0500 AppSyncSample[49746:9568532] [AppSyncSubscriptionConnection] Retrying subscription 8B930D03-B707-4C1F-A44A-CF867D69047C after milliseconds(3284)
2022-02-17 02:38:35.445070-0500 AppSyncSample[49746:9568534] [AppSyncSubscriptionConnection] Retrying subscription 8B930D03-B707-4C1F-A44A-CF867D69047C after milliseconds(6418)
2022-02-17 02:38:42.636133-0500 AppSyncSample[49746:9569644] [AppSyncSubscriptionConnection] Retrying subscription 8B930D03-B707-4C1F-A44A-CF867D69047C after milliseconds(12889)
2022-02-17 02:38:57.037133-0500 AppSyncSample[49746:9569848] [AppSyncSubscriptionConnection] Retrying subscription 8B930D03-B707-4C1F-A44A-CF867D69047C after milliseconds(25600)
[LAWMICHA] Connecting Sub 102 (7C67C248-04BE-4D15-9486-10E51215FAE4)
2022-02-17 02:39:20.798466-0500 AppSyncSample[49746:9570421] [AppSyncSubscriptionConnection] startSubscription(): connection is connected, start subscription 7C67C248-04BE-4D15-9486-10E51215FAE4 notSubscribed.
2022-02-17 02:39:20.798848-0500 AppSyncSample[49746:9570421] [AppSyncSubscriptionConnection] startSubscription(): connection is connected, start subscription 8B930D03-B707-4C1F-A44A-CF867D69047C notSubscribed.
2022-02-17 02:39:21.050572-0500 AppSyncSample[49746:9570419] ConnectionProviderError.limitExceeded; identifier=7C67C248-04BE-4D15-9486-10E51215FAE4;
2022-02-17 02:39:21.051335-0500 AppSyncSample[49746:9570419] [AppSyncSubscriptionConnection] Retrying subscription 7C67C248-04BE-4D15-9486-10E51215FAE4 after milliseconds(204)
2022-02-17 02:39:21.156638-0500 AppSyncSample[49746:9570443] ConnectionProviderError.limitExceeded; identifier=8B930D03-B707-4C1F-A44A-CF867D69047C;
2022-02-17 02:39:21.157873-0500 AppSyncSample[49746:9570443] [AppSyncSubscriptionConnection] Retrying subscription 8B930D03-B707-4C1F-A44A-CF867D69047C after milliseconds(51266)
2022-02-17 02:39:21.276009-0500 AppSyncSample[49746:9570420] [AppSyncSubscriptionConnection] startSubscription(): connection is connected, start subscription 7C67C248-04BE-4D15-9486-10E51215FAE4 notSubscribed.
2022-02-17 02:39:21.276328-0500 AppSyncSample[49746:9570420] [AppSyncSubscriptionConnection] startSubscription(): connection is connected, start subscription 8B930D03-B707-4C1F-A44A-CF867D69047C notSubscribed.
2022-02-17 02:39:21.443558-0500 AppSyncSample[49746:9570420] ConnectionProviderError.limitExceeded; identifier=7C67C248-04BE-4D15-9486-10E51215FAE4;
2022-02-17 02:39:21.450886-0500 AppSyncSample[49746:9570420] [AppSyncSubscriptionConnection] Retrying subscription 7C67C248-04BE-4D15-9486-10E51215FAE4 after milliseconds(487)
2022-02-17 02:39:21.545018-0500 AppSyncSample[49746:9570443] ConnectionProviderError.limitExceeded; identifier=8B930D03-B707-4C1F-A44A-CF867D69047C;
2022-02-17 02:39:21.545262-0500 AppSyncSample[49746:9570443] [AppSyncSubscriptionConnection] Retrying subscription 8B930D03-B707-4C1F-A44A-CF867D69047C after milliseconds(102417)
2022-02-17 02:39:21.986469-0500 AppSyncSample[49746:9570443] [AppSyncSubscriptionConnection] startSubscription(): connection is connected, start subscription 7C67C248-04BE-4D15-9486-10E51215FAE4 notSubscribed.
2022-02-17 02:39:21.986885-0500 AppSyncSample[49746:9570443] [AppSyncSubscriptionConnection] startSubscription(): connection is connected, start subscription 8B930D03-B707-4C1F-A44A-CF867D69047C notSubscribed.
2022-02-17 02:39:22.204983-0500 AppSyncSample[49746:9570443] ConnectionProviderError.limitExceeded; identifier=7C67C248-04BE-4D15-9486-10E51215FAE4;
2022-02-17 02:39:22.205540-0500 AppSyncSample[49746:9570443] [AppSyncSubscriptionConnection] Retrying subscription 7C67C248-04BE-4D15-9486-10E51215FAE4 after milliseconds(864)
2022-02-17 02:39:22.310200-0500 AppSyncSample[49746:9570419] ConnectionProviderError.limitExceeded; identifier=8B930D03-B707-4C1F-A44A-CF867D69047C;
2022-02-17 02:39:22.310760-0500 AppSyncSample[49746:9570419] [AppSyncSubscriptionConnection] Retrying subscription 8B930D03-B707-4C1F-A44A-CF867D69047C after milliseconds(204854)
2022-02-17 02:39:23.155564-0500 AppSyncSample[49746:9570419] [AppSyncSubscriptionConnection] startSubscription(): connection is connected, start subscription 7C67C248-04BE-4D15-9486-10E51215FAE4 notSubscribed.
2022-02-17 02:39:23.156448-0500 AppSyncSample[49746:9570419] [AppSyncSubscriptionConnection] startSubscription(): connection is connected, start subscription 8B930D03-B707-4C1F-A44A-CF867D69047C notSubscribed.
2022-02-17 02:39:23.280223-0500 AppSyncSample[49746:9570419] ConnectionProviderError.limitExceeded; identifier=7C67C248-04BE-4D15-9486-10E51215FAE4;
2022-02-17 02:39:23.280678-0500 AppSyncSample[49746:9570419] [AppSyncSubscriptionConnection] Retrying subscription 7C67C248-04BE-4D15-9486-10E51215FAE4 after milliseconds(1604)
2022-02-17 02:39:23.382805-0500 AppSyncSample[49746:9570443] ConnectionProviderError.limitExceeded; identifier=8B930D03-B707-4C1F-A44A-CF867D69047C;
2022-02-17 02:39:23.383237-0500 AppSyncSample[49746:9570443] 8B930D03-B707-4C1F-A44A-CF867D69047C Should not retry, send failure
[LAWMICHA] AppSync subscription error=limitExceeded(Optional("8B930D03-B707-4C1F-A44A-CF867D69047C"))
2022-02-17 02:39:25.043645-0500 AppSyncSample[49746:9570419] [AppSyncSubscriptionConnection] startSubscription(): connection is connected, start subscription 7C67C248-04BE-4D15-9486-10E51215FAE4 notSubscribed.
2022-02-17 02:39:25.043851-0500 AppSyncSample[49746:9570419] State 7C67C248-04BE-4D15-9486-10E51215FAE4 inProgress.
2022-02-17 02:39:25.044179-0500 AppSyncSample[49746:9570419] [AppSyncSubscriptionConnection] startSubscription(): connection is connected, start subscription 8B930D03-B707-4C1F-A44A-CF867D69047C notSubscribed.
2022-02-17 02:39:25.044271-0500 AppSyncSample[49746:9570419] State 8B930D03-B707-4C1F-A44A-CF867D69047C inProgress.
2022-02-17 02:39:25.155548-0500 AppSyncSample[49746:9570443] [RealtimeConnectionProvider] received error
2022-02-17 02:39:25.156578-0500 AppSyncSample[49746:9570443] ConnectionProviderError.limitExceeded; identifier=7C67C248-04BE-4D15-9486-10E51215FAE4;
2022-02-17 02:39:25.157051-0500 AppSyncSample[49746:9570443] [AppSyncSubscriptionConnection] Retrying subscription 7C67C248-04BE-4D15-9486-10E51215FAE4 after milliseconds(3228)
2022-02-17 02:39:25.291440-0500 AppSyncSample[49746:9570443] [RealtimeConnectionProvider] received error
2022-02-17 02:39:25.292583-0500 AppSyncSample[49746:9570420] ConnectionProviderError.limitExceeded; identifier=8B930D03-B707-4C1F-A44A-CF867D69047C;
2022-02-17 02:39:25.293067-0500 AppSyncSample[49746:9570420] 8B930D03-B707-4C1F-A44A-CF867D69047C Should not retry, send failure
[LAWMICHA] AppSync subscription error=limitExceeded(Optional("8B930D03-B707-4C1F-A44A-CF867D69047C"))
2022-02-17 02:39:28.709346-0500 AppSyncSample[49746:9570420] [AppSyncSubscriptionConnection] startSubscription(): connection is connected, start subscription 7C67C248-04BE-4D15-9486-10E51215FAE4 notSubscribed.
2022-02-17 02:39:28.709565-0500 AppSyncSample[49746:9570420] State 7C67C248-04BE-4D15-9486-10E51215FAE4 inProgress.
2022-02-17 02:39:28.710093-0500 AppSyncSample[49746:9570420] [AppSyncSubscriptionConnection] startSubscription(): connection is connected, start subscription 8B930D03-B707-4C1F-A44A-CF867D69047C notSubscribed.
2022-02-17 02:39:28.710197-0500 AppSyncSample[49746:9570420] State 8B930D03-B707-4C1F-A44A-CF867D69047C inProgress.
2022-02-17 02:39:28.822403-0500 AppSyncSample[49746:9570443] [RealtimeConnectionProvider] received error
2022-02-17 02:39:28.823268-0500 AppSyncSample[49746:9570443] ConnectionProviderError.limitExceeded; identifier=7C67C248-04BE-4D15-9486-10E51215FAE4;
2022-02-17 02:39:28.823797-0500 AppSyncSample[49746:9570443] [AppSyncSubscriptionConnection] Retrying subscription 7C67C248-04BE-4D15-9486-10E51215FAE4 after milliseconds(6469)
2022-02-17 02:39:28.934294-0500 AppSyncSample[49746:9570420] [RealtimeConnectionProvider] received error
2022-02-17 02:39:28.934780-0500 AppSyncSample[49746:9570420] ConnectionProviderError.limitExceeded; identifier=8B930D03-B707-4C1F-A44A-CF867D69047C;
2022-02-17 02:39:28.934991-0500 AppSyncSample[49746:9570420] 8B930D03-B707-4C1F-A44A-CF867D69047C Should not retry, send failure
[LAWMICHA] AppSync subscription error=limitExceeded(Optional("8B930D03-B707-4C1F-A44A-CF867D69047C"))
2022-02-17 02:39:35.939546-0500 AppSyncSample[49746:9570420] [AppSyncSubscriptionConnection] startSubscription(): connection is connected, start subscription 7C67C248-04BE-4D15-9486-10E51215FAE4 notSubscribed.
2022-02-17 02:39:35.939955-0500 AppSyncSample[49746:9570420] State 7C67C248-04BE-4D15-9486-10E51215FAE4 inProgress.
2022-02-17 02:39:35.940592-0500 AppSyncSample[49746:9570420] [AppSyncSubscriptionConnection] startSubscription(): connection is connected, start subscription 8B930D03-B707-4C1F-A44A-CF867D69047C notSubscribed.
2022-02-17 02:39:35.940842-0500 AppSyncSample[49746:9570420] State 8B930D03-B707-4C1F-A44A-CF867D69047C inProgress.
2022-02-17 02:39:36.051072-0500 AppSyncSample[49746:9569849] [RealtimeConnectionProvider] received error
2022-02-17 02:39:36.052907-0500 AppSyncSample[49746:9569849] ConnectionProviderError.limitExceeded; identifier=7C67C248-04BE-4D15-9486-10E51215FAE4;
2022-02-17 02:39:36.053634-0500 AppSyncSample[49746:9569849] [AppSyncSubscriptionConnection] Retrying subscription 7C67C248-04BE-4D15-9486-10E51215FAE4 after milliseconds(12839)
2022-02-17 02:39:36.163584-0500 AppSyncSample[49746:9570868] [RealtimeConnectionProvider] received error
2022-02-17 02:39:36.164590-0500 AppSyncSample[49746:9570868] ConnectionProviderError.limitExceeded; identifier=8B930D03-B707-4C1F-A44A-CF867D69047C;
2022-02-17 02:39:36.164999-0500 AppSyncSample[49746:9570868] 8B930D03-B707-4C1F-A44A-CF867D69047C Should not retry, send failure
[LAWMICHA] AppSync subscription error=limitExceeded(Optional("8B930D03-B707-4C1F-A44A-CF867D69047C"))

Sub 102 causes Sub 101 to retry despite it's retry attempts have been exhausted. The problem is that sub 101 attempted to retry based on another subscriptions retry logic, and that it sent multiple failure events indicating that it failed.

This PR removes the subscription from the connection so that it will no longer handle connection messages after it has sent out a failed event to the caller. This doesn't solve the problem with cross-subscription fired retry attempts, however, it does have the desired behavior for callers to be able to react properly to the .failed event.

By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.

@lawmicha lawmicha marked this pull request as ready for review February 17, 2022 14:41
@lawmicha lawmicha requested a review from a team February 17, 2022 14:41
Copy link
Member

@atierian atierian left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@lawmicha lawmicha merged commit 3cc0603 into main Feb 17, 2022
@lawmicha lawmicha deleted the fix/remove-listener branch February 17, 2022 16:54
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

Successfully merging this pull request may close these issues.

2 participants