Websocket connection abruptly closes within a short window of inactivity

[davidkamura]

Overview

I'm building a transaction tracking library which has the ability to subscribe multiple addresses to their log notifications concurrently. The log notifications from the different addresses are merged and streamed to consumeLogs function. The issue arises when the websocket does not receive messages for a variable amount of time - causing abrupt closure of the websocket connection. It throws the following error.

Error Message

SolanaError: WebSocket connection closed
    at [Symbol.asyncIterator] (C:\Users\dkamura\soltransaction_notifier_bot\node_modules\@solana\rpc-subscriptions-transport-websocket\dist\index.node.cjs:134:27)
    at async [Symbol.asyncIterator] (C:\Users\dkamura\soltransaction_notifier_bot\node_modules\@solana\rpc-subscriptions-spec\dist\index.node.cjs:88:28) {
  context: { __code: 8190003 },
  [cause]: CloseEvent {
    [Symbol(kTarget)]: WebSocket {
      _events: [Object: null prototype] {},
      _eventsCount: 0,
      _maxListeners: undefined,
      _binaryType: 'nodebuffer',
      _closeCode: 1006,
      _closeFrameReceived: false,
      _closeFrameSent: false,
      _closeMessage: <Buffer >,
      _closeTimer: null,
      _errorEmitted: false,
      _extensions: {},
      _paused: false,
      _protocol: '',
      _readyState: 3,
      _receiver: [Receiver],
      _sender: [Sender],
      _socket: [TLSSocket],
      _bufferedAmount: 0,
      _isServer: false,
      _redirects: 0,
      _autoPong: true,
      _url: 'rpc-url',
      _req: null,
      [Symbol(kCapture)]: false
    },
    [Symbol(kType)]: 'close',
    [Symbol(kCode)]: 1006,
    [Symbol(kReason)]: '',
    [Symbol(kWasClean)]: false
  }
}

In this case the websocket connection closed within 7 minutes of inactivity

Initializing... [Tue Oct 15 2024 18:31:39 GMT+0300 (East Africa Time)] 
+++++++++++++++++++ 
SolanaError: WebSocket connection closed [Tue Oct 15 2024 18:38:57 GMT+0300 (East Africa Time)] 
+++++++++++++++++++ 

Description of bug

It seems that websocket-connection.ts causes this disconnection as the logic implemented closes the connection when `queuedMessages.length is 0

websocket-connection.ts in handleOpen()

if (queuedMessages.length) {
                state.queuedMessages = [];
                yield* queuedMessages;
              } else {
                try {
                  yield await new Promise((resolve2, reject2) => {
                    iteratorState.set(iteratorKey, {
                      __hasPolled: true,
                      onError: reject2,
                      onMessage: resolve2
                    });
                  });
                } catch (e2) {
                  if (e2 === (EXPLICIT_ABORT_TOKEN ||= createExplicitAbortToken())) {
                    return;
                  } else {
                    throw new errors.SolanaError(
                      errors.SOLANA_ERROR__RPC_SUBSCRIPTIONS__TRANSPORT_CONNECTION_CLOSED,
                      {
                        cause: e2
                      }
                    );
                  }
                }
              }

Steps to reproduce

Below is the applications code:

let walletsToTrack = []; //an array of addresses

try {
        log.info(`\nInitializing...`);
        const logNotifications = establishLogSubscription(walletsToTrack);
        await consumeLogs(logNotifications);
    }
    catch (err) {
        log.error(err);
    }

Create log notification subscriptions for multiple addresses

async function* establishLogSubscription(addresses) {
    // Create an array of async iterators for each address subscription
    const logSubscriptions = addresses.map(async (address) => {
        const logNotifications = await rpcSubscription
            .logsNotifications({ mentions: [address] }, { commitment: "confirmed" })
            .subscribe({ abortSignal: abortController.signal });

        return (async function*() {
            for await (let notification of logNotifications) {
                yield { address, notification }; // Yield notifications with corresponding address
            }
        })(); // Immediately invoke the async generator function
    });

    // Resolve all the async iterators before merging them
    const asyncIterators = await Promise.all(logSubscriptions);

    // Merge multiple async iterators and yield from them concurrently
    yield* mergeAsyncGenerators(asyncIterators);
}

Merge log notificatons of the different addresses and stream them as one

// Helper function to merge multiple async iterators
async function* mergeAsyncGenerators(asyncIterators) {
    while (asyncIterators.length > 0) {
        // Create an array of promises from the iterators
        const results = await Promise.race(
            asyncIterators.map(async (iterator, index) => {
                const { value, done } = await iterator.next();
                return { value, done, index };
            })
        );

        if (results.done) {
            // If the iterator is done, remove it from the array
            asyncIterators.splice(results.index, 1);
        } else {
            // Yield the value and continue
            yield results.value;
        }
    }
}

Consume the merged logs

async function consumeLogs(logNotifications) {
    ...
}

Conclusion

a) Why is the connection closed when queuedMessages.length is zero while in future the websocket connection may receive messages b) How can this be fixed and allow for the websocket connection to be kept alive infinitely?

[steveluscher]

Why is the connection closed when queuedMessages.length is zero while in future the websocket connection may receive messages

This is what actually happens:

1. The websocket publishes messages
2. Messages that your application hasn't consumed yet end up in a queue
3. The websocket errors; the error gets added to the end of that queue
4. Your application pumps the iterator until it reaches the end of the queue, where the error is

So the queue is your red herring. It's neither here nor there; the problem is that your websocket is nuking.

Now, look at the actual error. You received websocket close code 1006. Looking that up:

Indicates that a connection was closed abnormally (that is, with no close frame being sent) when a status code is expected.

So your provider nuked your connection, without warning, without a reason, and without due process.

If you would like to continue this conversation, please do so on Stack Exchange, linked below. Almost certainly what's happening is that walletsToTrack is too large, and your provider is refusing to allow you to make that many subscriptions over a single channel. Related discussion: #3380.

[github-actions[bot]]

Hi @davidkamura,

Thanks for your question!

We want to make sure to keep signal strong in the GitHub issue tracker – to make sure that it remains the best place to track issues that affect the development of the Solana JavaScript SDK itself.

Questions like yours deserve a purpose-built Q&A forum. Unless there exists evidence that this is a bug with the Solana JavaScript SDK itself, please post your question to the Solana Stack Exchange using this link: https://solana.stackexchange.com/questions/ask

---

This automated message is a result of having added the ‘question’ tag.

[davidkamura]

steveluscher thanks for the explanation, it's cleared a lot on this issue. It seems that the walletsToTrack is indeed creating to many subscriptions which can't be supported by the rpc endpoint

[github-actions[bot]]

Because there has been no activity on this issue for 7 days since it was closed, it has been automatically locked. Please open a new issue if it requires a follow up.