Client side `failed with reason: {"reason":"unmatched topic"}` errors (WebSocket)

[rhcarvalho]

Environment

• Elixir version (elixir -v):

Erlang/OTP 28 [erts-16.1.2] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:1] [jit:ns]

Elixir 1.19.3 (compiled with Erlang/OTP 28)

• Phoenix version (mix deps) & Phoenix LiveView version (mix deps):

mix deps | grep -E 'phoenix([^_]|_live_view)'
* phoenix 1.8.2 (Hex package) (mix)
  locked at 1.8.2 (phoenix) 19ea65b4
* phoenix_live_view 1.1.18 (Hex package) (mix)
  locked at 1.1.18 (phoenix_live_view) f189b759

• Operating system: Linux / N/A
• Browsers you attempted to reproduce this bug on (the more the merrier):

Chrome Mobile 142.0.0
Samsung Internet 29.0
Edge 143.0.0
Chrome Mobile WebView 142.0.7444
Chrome 142.0.0

• Does the problem persist after removing "assets/node_modules" and trying again? Yes/no: N/A

Actual behavior

tl;dr: I'm seeing failed with reason: {"reason":"unmatched topic"} JavaScript errors and trying to determine what causes them, what's the perceived user experience when they happen and whether they can be ignored.

This is related to https://elixirforum.com/t/handling-channels-liveview-longpoll-fallback-unmatched-topic/72378 and phoenixframework/phoenix#6538 (which landed in Phoenix 1.8.2 and attempted to fix the issue I was investigating and related in the Elixir Forum).

Originally I associated the bulk of our failed with reason: {"reason":"unmatched topic"} JavaScript errors to clients connected via LongPoll.

I've since been tracking the current transport explicitly and reporting it along with client-side errors. This is done by reading window.liveSocket.socket.transport.name and tagging the error event before it is sent out.

I've collected numerous errors events from different browsers in the last few weeks, desktop and mobile, all of which are tagged with the WebSocket transport.

I don't have a fully readable stacktrace to share, but working through the data that I have I see pointers to:

• Object.callback (maybe refers to ViewHook.callback? Or one of the Push.recHooks values as in Push.matchReceive below)
• .matchReceive (~ Push.matchReceive in Phoenix)
• .trigger (maybe Channel.trigger in Phoenix)
• Object.decode
• .onConnMessage
• conn.onmessage

So while I observe the problem in LiveView, it is quite possible the issue/fix lies in Phoenix. Perhaps we need a similar error handling that was added for the LongPoll in the WebSocket transport as well?

Expected behavior

Either no such client side errors or a better understanding why they happen and their consequence.

[SteffenDE]

The big question is if you actually observe any wrong behavior in the app when that happens. You can get an "unmatched topic" if events race while navigating with latency:

1. Client does something that triggers an event
2. LiveView's handle_event sends a push_navigate
3. Before receiving the navigate response, the client does something that triggers a different event
4. Server receives event, but the previous channel is gone -> unmatched topic

In that case, the client could just silently ignore the error instead of letting it bubble up to whatever monitoring you use, as there's nothing to do anyway. The problem is we cannot really know if it's a problem or not on the client, so we log it. Do you get notified for console.error or for a unhandled exception?

[rhcarvalho]

Do you get notified for console.error or for a unhandled exception?

It's an unhandled Promise rejection (so the "async equivalent" of the latter).

[SteffenDE]

There are only a couple of places we don't catch at the moment:

phoenix_live_view/assets/js/phoenix_live_view/view.js

Lines 1512 to 1517 in 8a50f0a

	return this.pushWithReply(refGenerator, "event", {
	type: "hook",
	event: event,
	value: payload,
	cid: this.closestComponentID(targetCtx),
	}).then(({ resp: _resp, reply, ref }) => ({ reply, ref }));

phoenix_live_view/assets/js/phoenix_live_view/view.js

Lines 2115 to 2130 in 8a50f0a

	this.pushWithReply(refGen, "live_patch", { url }).then(
	({ resp }) => {
	this.liveSocket.requestDOMUpdate(() => {
	if (resp.link_redirect) {
	this.liveSocket.replaceMain(href, null, callback, linkRef);
	} else {
	if (this.liveSocket.commitPendingLink(linkRef)) {
	this.href = href;
	}
	this.applyPendingUpdates();
	callback && callback(linkRef);
	}
	});
	},
	({ error: _error, timeout: _timeout }) => fallback(),
	);

Do you know which one it is? Although I think we could just catch and log in both cases.

[rhcarvalho]

You can get an "unmatched topic" if events race while navigating with latency

I looked at a small sample of the reports, in all of the them there seems to be no navigation involved. In some cases there were live patches several minutes before the error. The particular LiveView where I see the errors is embedded via iframe, and there is no natural/expected navigation other than live patches.

What other data/state would be useful to track for better reports?

I'm thinking I could tag also the number of mounts and mount attempts (perhaps binned: 0, 1-5, 5+), as I suspect it might have something to do with socket disconnection-reconnection.

[rhcarvalho]

Do you know which one it is?

The rejection starts at View.pushWithReply:

phoenix_live_view/assets/js/phoenix_live_view/view.js

Line 1275 in 8a50f0a

reject(new Error(`failed with reason: ${JSON.stringify(reason)}`)),

Of the lines you brought up, only the first is not handling the rejection, the second one handles it using a different syntax Promise.then(okCb, errorCb), so it would be:

phoenix_live_view/assets/js/phoenix_live_view/view.js

Lines 1512 to 1517 in 8a50f0a

	return this.pushWithReply(refGenerator, "event", {
	type: "hook",
	event: event,
	value: payload,
	cid: this.closestComponentID(targetCtx),
	}).then(({ resp: _resp, reply, ref }) => ({ reply, ref }));

But I don't see a sign of pushHookEvent in the stacktrace 😕

I think what I see in a minified stacktrace is

phoenix_live_view/assets/js/phoenix_live_view/view.js

Lines 1197 to 1214 in 8a50f0a

	wrapPush(callerPush, receives) {
	const latency = this.liveSocket.getLatencySim();
	const withLatency = latency
	? (cb) => setTimeout(() => !this.isDestroyed() && cb(), latency)
	: (cb) => !this.isDestroyed() && cb();
	withLatency(() => {
	callerPush()
	.receive("ok", (resp) =>
	withLatency(() => receives.ok && receives.ok(resp)),
	)
	.receive("error", (reason) =>
	withLatency(() => receives.error && receives.error(reason)),
	)
	.receive("timeout", () =>
	withLatency(() => receives.timeout && receives.timeout()),
	);
	});

And then we're in recHooks land which is in the Phoenix code base (push.js).

[SteffenDE]

the second one handles it using a different syntax

Good call!

It makes sense that you see wrapPush, since pushWithReply calls that. The interesting part would be finding out who called pushWithReply, as we'd want to catch it further up. I'll try to look into it a bit more later :)

[rhcarvalho]

The interesting part would be finding out who called pushWithReply, as we'd want to catch it further up.

Yeah! I'm after that! Will try to bring more assertive details once I collect more data.

I'll try to look into it a bit more later :)

Thanks 💜

I'm going to capture a bit more of the View state along with error reports:

        // Fit numeric values into buckets to reduce tag cardinality.
        const classify = v => {
          if (typeof v === "number" && !isNaN(v)) {
            if (v === 0) return "0";
            if (v > 0 && v <= 5) return "1-5";
            if (v > 5) return ">5";
          }
          return v;
        }
        // ...
        // tags:
        tags["liveview_transport"] = window.liveSocket.socket.transport.name;
        tags["liveview_main_is_dead"] = window.liveSocket.main?.isDead;
        tags["liveview_main_join_count"] = classify(window.liveSocket.main?.joinCount);
        tags["liveview_main_join_attempts"] = classify(window.liveSocket.main?.joinAttempts);
        tags["liveview_main_join_pending"] = window.liveSocket.main?.joinPending;
        tags["liveview_main_destroyed"] = window.liveSocket.main?.destroyed;

And I added --keep-names to the Esbuild config temporarily to see if it sheds light on the call stack without disabling minification altogether or requiring a more complex setup.

[SteffenDE]

What I sometimes do is just drop in a <script src="https://cdn.jsdelivr.net/npm/phoenix_live_view@1.1.18/priv/static/phoenix_live_view.js"></script> (or copy that to priv) into the root template and replace the new LiveSocket with a new window.LiveView.LiveSocket. Working with non-minified code does help a lot :D