anycable-go: TurboDrive/TurboStream Subscribe/Unsubscribe Race Condition

SUMMARY

I’ve noticed a Subscribe/Unsubscribe race condition with navigating pages using TurboDrive. When leaving a page and going to a new one, an unsubscribe/subscribe event is sent. However, these are sent to the server at the same timestamp in the browser logs.

DETAILS

anycable-go logs sometimes show the following Unsubscribed/Subscribed events:

OK SCENARIO

BROWSER

ANYCABLE-GO

20:13:23.860Z context=node sid=... Incoming message: &{unsubscribe {"channel":"Turbo::StreamsChannel"......"} <nil>}
20:13:23.860Z context=node sid=... Unsubscribed from channel: {"channel":"Turbo::StreamsChannel"......"}
20:13:23.860Z channel={"channel":"Turbo::StreamsChannel"......"} context=hub sid=... Unsubscribed

20:13:23.861Z context=node sid=... Incoming message: &{subscribe {"channel":"Turbo::StreamsChannel"......"} <nil>}
20:13:23.861Z context=turbo identifier={"channel":"Turbo::StreamsChannel"......"} verified stream: my_stream
20:13:23.861Z context=node sid=... Subscribed to channel: {"channel":"Turbo::StreamsChannel"......"}
20:13:23.861Z channel={"channel":"Turbo::StreamsChannel"......"} context=hub sid=... stream=my_stream Subscribed

In the above example, the channel is correctly unsubscribed, and then subscribed (last line).

FAIL SCENARIO

Sometimes all the events show in a different order with “Unsubscribe” as last.

BROWSER

ANYCABLE-GO

20:17:09.463Z context=node sid=... Incoming message: &{unsubscribe {"channel":"Turbo::StreamsChannel"......"} <nil>}
20:17:09.464Z context=node sid=... Unsubscribed from channel: {"channel":"Turbo::StreamsChannel"......"}

20:17:09.464Z context=node sid=... Incoming message: &{subscribe {"channel":"Turbo::StreamsChannel"......"} <nil>}
20:17:09.464Z context=turbo identifier={"channel":"Turbo::StreamsChannel"......"} verified stream: my_stream
20:17:09.464Z context=node sid=... Subscribed to channel: {"channel":"Turbo::StreamsChannel"......"}
20:17:09.465Z channel={"channel":"Turbo::StreamsChannel"......"} context=hub sid=... stream=my_stream Subscribed

20:17:09.466Z channel={"channel":"Turbo::StreamsChannel"......"} context=hub sid=... Unsubscribed

In the first set of logs the Unsubscribed event logged as the 3rd item, but in this last case it comes last. When I see the Unsubscribed last in the log after navigating to a page using TurboDrive, the browser dev tools show the WS still connected, but anycable-go logs indicate “No sessions”:

20:00:01.206Z context=pubsub Incoming pubsub message from Redis: {"stream":"my_stream","data":"\"\\u003cturbo-stream action=\\\"append\\\"   ..."}
20:00:01.206Z context=node Incoming pubsub message: &{my_stream "\u003cturbo-stream action=\"append\"   ..."}
20:00:01.206Z context=hub stream=my_stream Broadcast message: "\u003cturbo-stream action=\"append\"   ..."
20:00:01.206Z context=hub stream=my_stream No sessions

SIMILAR ACTION CABLE CLIENT ISSUE

It might be the same race condition reported/resolved here: ActionCable client ensures subscribe command is confirmed ?

SETUP

About this issue

Original URL
State: closed
Created 2 years ago
Comments: 16 (8 by maintainers)

Commits related to this issue

fix: stop/start stream race conditions Ref #148 — committed to anycable/anycable-go by palkan 2 years ago

Most upvoted comments

The server-side race condition has been fixed and released in 1.2.1. /cc @jwako

Closing this one.

Client-side issue has been moved here: https://github.com/anycable/anycable-client/issues/15 /cc @tleish

palkan on Jun 30, 2022

What is your client code?

I use @rails/actioncable 6.1.4-1 and my client code is below:

      this.badgeChannel = this.consumer.subscriptions.create(this.channelName, {
        connected: () => {
          this.badgeChannel?.perform('follow', {
            channel_id: `${account_id}_${user_id}`
          });
        }
...
      });

Do you perform follow multiple times?

No.

And what is “the problem”?

The problem is the order of Unsubscribed/Subscribed events differs.

When follow calls in my code BadgeNotificationChannel, stop_all_streams should calls Unsubscribe, and stream_from should calls Subscribe. But actually when follow calls, somehow Subscribe calls, and then Unsubscribe calls at last. So I cannot send any badge notification because it is unsubscribed.

anycable-go 1.0 is OK (the order of events is Unsubscribe -> Subscribe). But when I upgraded to 1.1, the order of events is Subscribe -> Unsubscribe even though it is the same code. I could reproduce the different orders 100% with anycable-go 1.1 and 1.2.

jwako on Jun 30, 2022