Infinite loop in web3.js subscription handling

[yamen]

I have a situation where I have a handful of subscriptions, and my WebSocket temporarily disconnects. This will sometimes cause an infinite loop with 300k errors in the logs of the type:

slotSubscribe error for argument [] WebSocket is not open: readyState 0 (CONNECTING)

Before an eventually out of memory error and process crash.

From looking at the code, there seems to be a potential edge case race condition. Namely:

• _updateSubscriptions() is called when there are no active subscriptions and an active connection.
• This flags _rpcWebSocketConnected = false and starts a 500ms timer to actually disconnect the WebSocket:

solana/web3.js/src/connection.ts

Lines 4543 to 4556 in c4d2c95

	this._rpcWebSocketConnected = false;
	this._rpcWebSocketIdleTimeout = setTimeout(() => {
	this._rpcWebSocketIdleTimeout = null;
	try {
	this._rpcWebSocket.close();
	} catch (err) {
	// swallow error if socket has already been closed.
	if (err instanceof Error) {
	console.log(
	`Error when closing socket connection: ${err.message}`,
	);
	}
	}
	}, 500);

• Before the timer expires, the WebSocket disconnects (network issue), and new subscriptions are made. _updateSubscriptions() is called again. Now there are active subscriptions and no active connection.
• However, as there is an active disconnect timer, the connection is flagged as active _rpcWebSocketConnected = true:

solana/web3.js/src/connection.ts

Lines 4561 to 4565 in c4d2c95

	if (this._rpcWebSocketIdleTimeout !== null) {
	clearTimeout(this._rpcWebSocketIdleTimeout);
	this._rpcWebSocketIdleTimeout = null;
	this._rpcWebSocketConnected = true;
	}

• This leads to an infinite loop in _updateSubscriptions() as the normal guards to stop this from happening have been bypassed:
  • _rpcWebSocketConnected = true even though we're not really connected, which stops the function from returning early
  • _rpcWebSocketGeneration doesn't get updated as there isn't a new close event since entering the function

Now the WebSocket calls fail (hence the error), but the failure leads to an infinite recursion of trying again and again on loop.

I think this is what's happening, very hard to debug. Using a different flag for a 'pending disconnect' scenario will likely fix this.

[steveluscher]

Before the timer expires, the WebSocket disconnects (network issue), and new subscriptions are made. _updateSubscriptions() is called again. Now there are active subscriptions and no active connection.

If _updateSubscriptions() is called because a new subscription is made, the disconnect timer gets cancelled (see clearTimeout(this._rpcWebSocketIdleTimeout)).

I'm almost positive that this is because of corruption in rpc-websockets – the library that we depend on to track the state of the websocket connection.

Tracked in #25578.

[steveluscher]

Oh, I see what you're saying. Yeah, that's a leak. Not sure if it's the one that's causing your problem, but a leak.

[yamen]

FWIW when I changed my code to keep an active subscription (ie never go to -no subscriptions- and hence start the disconnect), I haven’t had the problem. Before it was happening every few hours, and now not at all for a few days.

On Fri, 22 Jul 2022 at 18:16, Steven Luscher ***@***.***> wrote: Oh, I see what you're saying. Yeah, that's a leak. Not sure if it's the one that's causing your problem, but a leak. — Reply to this email directly, view it on GitHub <#26665 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AACVTZ5TJMZYJ63VQZF6FN3VVJKENANCNFSM535Z2YRQ> . You are receiving this because you authored the thread.Message ID: ***@***.***>

-- Sent from Gmail Mobile

[steveluscher]

Can you try out #26734, @yamen?

[steveluscher]

I landed this change. If you have time to update to the version after 1.50.0 and retest your app, @yamen, I'd love to hear if this fixed things for you.

[yamen]

Thanks Steve I will check in a week or so, temporary workaround is stable for now so will wait for regular dependency update chore.

[laterbreh]

We are currently on 1.52 (https://github.com/solana-labs/solana-web3.js/releases/tag/v1.52.0) and we are still experiencing this issue.
(wallet address ommited)
accountSubscribe error for argument [ 'XXXXXXXXXXXXXXXXXXXX', { encoding: 'base64', commitment: 'finalized' }

We never get more than 3 to 5 subscriptions. We actively track and unsubscribe from the wallets every X minutes. When this occurs, we hit 99% cpu usage and our gateway locks up.