Many consecutive short operations cause high chance of lazyCloseTimeout triggering close

[Momics]

Screenshot

(Schematic timeline of what's happening, the blocks are operations and the arrows are the lazyCloseTimeout's set by the release fn)

Expected Behaviour
I expected lazyCloseTimeout to be 're-scheduled' every time a subscription releases it's lock, so that the connection is left open until lazyCloseTimeout ms of inactivity.

Actual Behaviour
Instead, each completed subscription schedules it's own timeout. With many short successive subscriptions (completing fast) and some network irregularity chances are high there are 0 locks when the timeout triggers. In the image, just before the last subscription is about to trigger, the connection is closed abruptly.

Especially in the case of short lived subscriptions (e.g. when you are doing mutations over ws only), it adds a lot of unnecessary websocket handshakes.

Debug Information
What I did myself to fix it, is to clear any open lazyCloseTimer(s) before scheduling a new one, essentially 'debouncing' the operation until there is no further activity left:

See this code for reference: https://github.com/enisdenjo/graphql-ws/blob/master/src/client.ts#L790-L797

I declared a lazyCloseTimer before the connect function in the client and then changed above code to:

// Clear any other lazy close timers
clearTimeout(lazyCloseTimer);
// Then set a new one, essentially debouncing the complete check
lazyCloseTimer = setTimeout(() => {
  // (With the old code, there is a high chance locks = 0 here)
  if (!locks && socket.readyState === WebSocketImpl.OPEN)
    complete();
}, lazyCloseTimeout);

Further Information
It could be that I am interpreting the intended behaviour of lazyCloseTimeout in the wrong way.

[enisdenjo]

Interesting, you might be onto something here, thanks for investigating!

Thinking how to write a test for this behaviour. 🤔

[Momics]

I don't really know how to write a test for this either. I discovered the behaviour using the following setup on the client side. I adapted it to work with the example server from the README:

import { createClient } from 'graphql-ws';

const client = createClient({
  url: 'ws://localhost:4000/graphql',
  lazyCloseTimeout: 1000,
});

const totalQueries = 100;
let currentCount = 0;
let t = setInterval(async () => {
  if (currentCount > totalQueries) {
    clearInterval(t);
    return;
  }

  client.subscribe(
    { query: `{ hello }` },
    {
      next: (data) => {
        //
      },
      complete: () => {
        currentCount++;
        console.log("Done", currentCount);
      },
      error: (err) => {
        console.log(err);
      },
    }
  );
}, 100);

Running this on a client in the browser allows you to at least easily spot/experiment with the behaviour:

As you can see from the 'time' column, sometimes the close happens exactly after 1 second (no locks). Sometimes it misses the opening and it then triggers just 100ms or 200ms later.

[enisdenjo]

Awesome stuff, your example inspired my test case:

graphql-ws/src/__tests__/client.ts

Lines 1396 to 1429 in c332837

	it('should debounce close by lazyCloseTimeout', async () => {
	const { url, ...server } = await startTServer();
	const client = createClient({
	url,
	lazy: true, // default
	lazyCloseTimeout: 10,
	retryAttempts: 0,
	onNonLazyError: noop,
	});
	// loop subscriptions and delay them by 5ms (while lazy close is 10ms)
	for (let i = 0; i < 5; i++) {
	await new Promise((resolve) => setTimeout(resolve, 5));
	await new Promise<void>((resolve, reject) => {
	client.subscribe(
	{ query: '{ getValue }' },
	{
	next: () => {
	// noop
	},
	error: reject,
	complete: resolve,
	},
	);
	});
	}
	// if the debounce is set up incorrectly, a leftover timeout might close the connection earlier
	await server.waitForClientClose(() => {
	fail("Client shouldn't have closed");
	}, 5);
	});

It was indeed failing before the fix in c332837.

Thank you @Momics for this great discovery!

[enisdenjo]

🎉 This issue has been resolved in version 5.10.1 🎉

The release is available on:

• npm package (@latest dist-tag)
• GitHub release

Your semantic-release bot 📦🚀