search

anycable / anycable-client

AnyCable / Action Cable JavaScript client for web, Node.js & React Native
MIT License
96 stars 15 forks source link

Stale turbo-stream from turbo-cache preview #18

Closed tleish closed 2 years ago

tleish commented 2 years ago

In testing this latest release @anycable/web-0.4.0 and @anycable/core-0.4.1 with anycable-go-1.2.1 (from changes in https://github.com/anycable/anycable-client/issues/17), I found that a turbo-stream connection on cached turbo drive page no longer processes websocket messages.

Steps to reproduce:

  1. Load page with turbo drive and a turbo-stream element
  2. Navigate to a 2nd page (with same elements)
  3. Navigate back to first (turbo-cached) page
  4. Broadcast a turbo-stream message from the server

Results: browser logs show message received, but the javascript does not process the stream and there's no change in the current DOM.

Server Client Logs

### PAGE 1
D 2022-07-13T23:43:20.550Z context=node sid=Xyr0A-oFV6UX-7AOOu31Z Websocket closed: websocket: close 1001 (going away)
D 2022-07-13T23:43:20.550Z sid=Xyr0A-oFV6UX-7AOOu31Z WebSocket session completed
D 2022-07-13T23:43:20.550Z channel={"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} context=hub sid=Xyr0A-oFV6UX-7AOOu31Z Unsubscribed
D 2022-07-13T23:43:20.550Z context=node sid=Xyr0A-oFV6UX-7AOOu31Z Disconnect {"user":"..."} http://localhost/cable?jid=.... &map[REMOTE_ADDR:127.0.0.1 cookie:....] [{"channel":"Turbo::StreamsChannel","signed_stream_name":"..."}]
D 2022-07-13T23:43:20.550Z context=hub sid=Xyr0A-oFV6UX-7AOOu31Z Unregistered
E 2022-07-13T23:43:20.550Z context=node sid=Xyr0A-oFV6UX-7AOOu31Z Disconnect error: grpc connection is not ready
D 2022-07-13T23:43:20.742Z sid=rbAW2Y9stR1SyQHsN7h6P WebSocket session established
D 2022-07-13T23:43:20.742Z context=hub sid=rbAW2Y9stR1SyQHsN7h6P Registered with identifiers: {"user":"..."}
D 2022-07-13T23:43:20.748Z context=node sid=rbAW2Y9stR1SyQHsN7h6P Incoming message: &{subscribe {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} <nil>}
D 2022-07-13T23:43:20.748Z context=turbo identifier={"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} verified stream: user:abc123
D 2022-07-13T23:43:20.748Z context=node sid=rbAW2Y9stR1SyQHsN7h6P Subscribed to channel: {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."}
D 2022-07-13T23:43:20.748Z channel={"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} context=hub sid=rbAW2Y9stR1SyQHsN7h6P stream=user:abc123 Subscribed

### PAGE 2
D 2022-07-13T23:43:49.619Z context=node sid=rbAW2Y9stR1SyQHsN7h6P Incoming message: &{unsubscribe {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} <nil>}
D 2022-07-13T23:43:49.619Z context=node sid=rbAW2Y9stR1SyQHsN7h6P Unsubscribed from channel: {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."}
D 2022-07-13T23:43:49.619Z channel={"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} context=hub sid=rbAW2Y9stR1SyQHsN7h6P Unsubscribed
D 2022-07-13T23:43:50.125Z context=node sid=rbAW2Y9stR1SyQHsN7h6P Incoming message: &{subscribe {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} <nil>}
D 2022-07-13T23:43:50.125Z context=turbo identifier={"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} verified stream: user:abc123
D 2022-07-13T23:43:50.125Z context=node sid=rbAW2Y9stR1SyQHsN7h6P Subscribed to channel: {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."}
D 2022-07-13T23:43:50.125Z channel={"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} context=hub sid=rbAW2Y9stR1SyQHsN7h6P stream=user:abc123 Subscribed

### BACK TO PAGE 1 (TURBO PREVIEW)
D 2022-07-13T23:44:03.211Z context=node sid=rbAW2Y9stR1SyQHsN7h6P Incoming message: &{unsubscribe {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} <nil>}
D 2022-07-13T23:44:03.211Z context=node sid=rbAW2Y9stR1SyQHsN7h6P Unsubscribed from channel: {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."}
D 2022-07-13T23:44:03.211Z channel={"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} context=hub sid=rbAW2Y9stR1SyQHsN7h6P Unsubscribed     
D 2022-07-13T23:44:03.711Z context=node sid=rbAW2Y9stR1SyQHsN7h6P Incoming message: &{subscribe {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} <nil>}
D 2022-07-13T23:44:03.712Z context=turbo identifier={"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} verified stream: user:abc123
D 2022-07-13T23:44:03.712Z context=node sid=rbAW2Y9stR1SyQHsN7h6P Subscribed to channel: {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."}
D 2022-07-13T23:44:03.712Z channel={"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} context=hub sid=rbAW2Y9stR1SyQHsN7h6P stream=user:abc123 Subscribed
### BACK TO PAGE 1 (TURBO FETCH)               
D 2022-07-13T23:44:04.089Z context=node sid=rbAW2Y9stR1SyQHsN7h6P Incoming message: &{subscribe {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} <nil>}
W 2022-07-13T23:44:04.089Z context=node sid=rbAW2Y9stR1SyQHsN7h6P Failed to handle incoming message '{"command":"subscribe","identifier":"{\"channel\":\"Turbo::StreamsChannel\",\"signed_stream_name\":\"...\"}"}' with error: Already subscribed to {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."}
D 2022-07-13T23:44:08.716Z context=node sid=rbAW2Y9stR1SyQHsN7h6P Incoming message: &{subscribe {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} <nil>}
W 2022-07-13T23:44:08.716Z context=node sid=rbAW2Y9stR1SyQHsN7h6P Failed to handle incoming message '{"command":"subscribe","identifier":"{\"channel\":\"Turbo::StreamsChannel\",\"signed_stream_name\":\"...\"}"}' with error: Already subscribed to {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."}
D 2022-07-13T23:44:09.090Z context=node sid=rbAW2Y9stR1SyQHsN7h6P Incoming message: &{subscribe {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} <nil>}
W 2022-07-13T23:44:09.090Z context=node sid=rbAW2Y9stR1SyQHsN7h6P Failed to handle incoming message '{"command":"subscribe","identifier":"{\"channel\":\"Turbo::StreamsChannel\",\"signed_stream_name\":\"...\"}"}' with error: Already subscribed to {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."}

### BROADCAST MESSAGE
D 2022-07-14T00:12:05.289Z context=pubsub Incoming pubsub message from Redis: {"stream":"user:abc123","data":"\"\\u003cturbo-stream action=\\\"append\\\" target=\\\"turbo-alerts\\\"....\\u003c/turbo-stream\\u003e\""}
D 2022-07-14T00:12:05.289Z context=node Incoming pubsub message: &{user:abc123 "\u003cturbo-stream action=\"append\" target=\"turbo-alerts\"...\u003c/turbo-stream\u003e"}
D 2022-07-14T00:12:05.289Z context=hub stream=user:abc123 Broadcast message: "\u003cturbo-stream action=\"append\" target=\"turbo-alerts\"...\u003c/turbo-stream\u003e"

Client Logs

image

On visiting a turbo cached page, turbo loads the cached version (as a preview) and replaces it with the fetched version when loaded. To met it appears that

  1. The cached/preview DOM connects from the turbo-stream element in the cache.
  2. When turbo swaps the preview page with the fetched page, the new turbo-stream attempts to make the connection, but fails (the server logs the failure and never responds with a success).
  3. When the server broadcasts a turbo-stream message, since logic linked the stream to the cached/preview turbo-stream element (which is no longer in the DOM) it does not update the DOM.

I confirmed that disabling turbo-cache-control temporarily resolves the issue.

<meta name="turbo-cache-control" content="no-cache">

Not a permanent solution, just narrowing down where the problem exists.

FYI, I tested @anycable/web-0.3.2 and @anycable/core-0.3.3 with anycable-go-1.2.1 and don't see this issue, so this was introduced in the latest changes.

palkan commented 2 years ago

Could you please reproduce it with the anycable-client debug logs (createCable({logLevel: 'debug', ...})) and show the console output?

tleish commented 2 years ago

Console output with logLevel: 'debug'.

### PAGE 1
index.js:9 [debug] connecting
index.js:7 [debug] incoming data {type: 'welcome'}
index.js:9 [info] connected
index.js:7 [debug] subscribing {identifier: 'Turbo::StreamsChannel', params: {…}}
index.js:7 [debug] outgoing message {command: 'subscribe', identifier: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}'}
index.js:7 [debug] incoming data {type: 'confirm_subscription', identifier: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}'}
index.js:7 [debug] subscribed {id: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}', identifier: 'Turbo::StreamsChannel', params: {…}}
index.js:7 [debug] incoming data {type: 'ping', message: 1657762965}
index.js:7 [debug] incoming data {type: 'ping', message: 1657762968}
index.js:7 [debug] incoming data {type: 'ping', message: 1657762971}

### PAGE 2
index.js:7 [debug] unsubscribing... {id: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}'}
index.js:7 [debug] outgoing message {command: 'unsubscribe', identifier: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}'}
index.js:7 [debug] subscribing {identifier: 'Turbo::StreamsChannel', params: {…}}
index.js:7 [debug] unsubscribed remotely {id: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}'}
index.js:7 [debug] outgoing message {command: 'subscribe', identifier: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}'}
index.js:7 [debug] incoming data {type: 'confirm_subscription', identifier: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}'}
index.js:7 [debug] subscribed {id: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}', identifier: 'Turbo::StreamsChannel', params: {…}}
index.js:7 [debug] incoming data {type: 'ping', message: 1657762974}
index.js:7 [debug] incoming data {type: 'ping', message: 1657762977}
index.js:7 [debug] incoming data {type: 'ping', message: 1657762980}

### BACK TO PAGE 1 (TURBO PREVIEW)
index.js:7 [debug] unsubscribing... {id: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}'}
index.js:7 [debug] outgoing message {command: 'unsubscribe', identifier: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}'}
index.js:7 [debug] subscribing {identifier: 'Turbo::StreamsChannel', params: {…}}
index.js:7 [debug] unsubscribed remotely {id: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}'}
index.js:7 [debug] subscribing {identifier: 'Turbo::StreamsChannel', params: {…}}
index.js:7 [debug] outgoing message {command: 'subscribe', identifier: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}'}
index.js:7 [debug] incoming data {type: 'confirm_subscription', identifier: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}'}
index.js:7 [debug] subscribed {id: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}', identifier: 'Turbo::StreamsChannel', params: {…}}
### BACK TO PAGE 1 (TURBO FETCH)
index.js:7 [debug] outgoing message {command: 'subscribe', identifier: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}'}
index.js:7 [debug] incoming data {type: 'ping', message: 1657762983}
index.js:7 [debug] incoming data {type: 'ping', message: 1657762986}
index.js:7 [debug] outgoing message {command: 'subscribe', identifier: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}'}
index.js:7 [debug] outgoing message {command: 'subscribe', identifier: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}'}
index.js:7 [debug] incoming data {type: 'ping', message: 1657762989}
index.js:7 [debug] incoming data {type: 'ping', message: 1657762992}
index.js:7 [debug] incoming data {type: 'ping', message: 1657762995}

### BROADCAST MESSAGE
index.js:7 [debug] incoming data {identifier: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}', message: '<turbo-stream action="append" target="turbo-alerts…vg>\n  </button>\n</div>\n</template></turbo-stream>'}
index.js:7 [debug] processed incoming message {identifier: '{"channel":"Turbo::StreamsChannel","signed_stream_..."}', message: '<turbo-stream action="append" target="turbo-alerts…vg>\n  </button>\n</div>\n</template></turbo-stream>'}
index.js:7 [debug] incoming data {type: 'ping', message: 1657762998}
index.js:7 [debug] incoming data {type: 'ping', message: 1657763001}
index.js:7 [debug] incoming data {type: 'ping', message: 1657763004}
palkan commented 2 years ago

So, here we had the following issues:

1) await subscribeTo could still be pending (due to unsubscribe/subscribe race conditions and the way we handle them) when disconnectedCallback is called, resulting in never invoked subscription.disconnect 2) The subscribe retry mechanism has another race condition (when we retry if no ack has been received), which could result in a subscribe command called for the stale/disconnected channel instance.

I released a new version of @anycable/turbo-stream, which resolves the first problem and also reduces the number of potential race conditions (or even eliminates—I wasn't able to reproduce them) by ignore Turbo cached pages (because we don't really need to react on them).

This version is actually a complete rewrite (planned a long time ago), which brings more flexibility and extensibility to the Turbo Streams integration. See https://github.com/anycable/anycable-client/tree/master/packages/turbo-stream

Re: 2. I plan to spend more time, revert a quick fix I pushed before and provide more robust implementation. I have to admit, that my initial idea of having async/await API for subscriptions doesn't play well with the asynchronous nature of WebSockets. And Turbo Streams revealed all the pain points 🙂 Thus, some minor API breaking changes (and significant internal rewrites) are required.

Please, check the updated version of @anycable/turbo-stream and let me know, if it solves the issue.

tleish commented 2 years ago

Just tested it out and the turbo-stream now works.

Note that the logs still seem a little odd.

### BACK TO PAGE 1
index.js:7 [debug] subscribing {identifier: 'Turbo::StreamsChannel', params: {…}}
index.js:7 [debug] outgoing message {command: 'subscribe', identifier: '{"channel":"Turbo::StreamsChannel","signed_stream_…0eee98b502ed69ac53dce55054526f950487debca56a47b"}'}
index.js:7 [debug] incoming data {type: 'ping', message: 1657832674}
index.js:7 [debug] incoming data {type: 'ping', message: 1657832677}
index.js:7 [debug] outgoing message {command: 'subscribe', identifier: '{"channel":"Turbo::StreamsChannel","signed_stream_…0eee98b502ed69ac53dce55054526f950487debca56a47b"}'}
index.js:7 [debug] incoming data {type: 'ping', message: 1657832680}
index.js:7 [debug] incoming data {type: 'ping', message: 1657832683}
index.js:7 [debug] incoming data {type: 'ping', message: 1657832686}

The client attempts to subscribe twice when visiting a prior page, but it doesn't appear to receive and confirmation back from the server that it's subscribed.

anycable-go logs failures of "Already Subscribed":

### BACK TO PAGE 1
D 2022-07-14T21:04:32.794Z context=node sid=16ocsA8akFjnbSrZ5ekdG Incoming message: &{subscribe {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} <nil>}
W 2022-07-14T21:04:32.794Z context=node sid=16ocsA8akFjnbSrZ5ekdG Failed to handle incoming message '{"command":"subscribe","identifier":"{\"channel\":\"Turbo::StreamsChannel\",\"signed_stream_name\":\"...\"}"}' with error: Already subscribed to {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."}
D 2022-07-14T21:04:37.796Z context=node sid=16ocsA8akFjnbSrZ5ekdG Incoming message: &{subscribe {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."} <nil>}
W 2022-07-14T21:04:37.796Z context=node sid=16ocsA8akFjnbSrZ5ekdG Failed to handle incoming message '{"command":"subscribe","identifier":"{\"channel\":\"Turbo::StreamsChannel\",\"signed_stream_name\":\"...\"}"}' with error: Already subscribed to {"channel":"Turbo::StreamsChannel","signed_stream_name":"..."}

Is this expected?

palkan commented 2 years ago

That relates to the second problem, so, it's an expected behavior for now 😕

tleish commented 2 years ago

It looks like with the latest client our system tests now fail with a bunch of the following errors:

Failure/Error: RACK_HIJACK       => lambda { raise NotImplementedError, "only partial hijack is supported."},
NotImplementedError:
   only partial hijack is supported.

Not sure if users will experience the same issues.

palkan commented 2 years ago

Hm, it's not related to the client library; it's the exception from the Ruby web server. Which one do you use in your system tests? Looks like Webrick (it doesn't support full hijack).

tleish commented 2 years ago

False alarm. I saw ActionCable in the callstack and assumed it was related to these changes. Thanks.

palkan commented 2 years ago

Released @anycable/core and @anecable/web 0.5.0, and @anycable/turbo-stream 0.2.0. The number 2 from the above is fixed; now everything should be smooth. Some warnings could still appear if you navigating too fast, for example:

[warn] ReasonError: Channel was disconnected before subscribing
[warn] ignore subscription confirmation, unsubscribed Object

They indicate that we caught some race conditions: attempting to unsubscribe right after sending subscribe and receiving confirmation, when it's not longer needed.