grpc-js: waitForReady called multiple times

[badsyntax]

Problem description

When using client.waitForReady, the ready callback is called multiple times (3 times in this case). Is this is the expected behaviour? I expected it to be called only once. Perhaps I'm misunderstanding the API.

Reproduction steps

I'm constructing the gRPC client (which extends from Client.ts).

import * as grpc from '@grpc/grpc-js';
import { GradleTasksClient as GrpcClient } from './java-gradle-tasks-grpc/src/main/proto/gradle_tasks_grpc_pb';

const grpcClient = new GrpcClient(
  'localhost:8887',
  grpc.credentials.createInsecure()
);
const deadline = new Date();
deadline.setSeconds(deadline.getSeconds() + 1);
grpcClient.waitForReady(deadline, (err: Error | undefined) => {
  console.log('is ready');
});

Environment

• OS name, version and architecture: macos Catalina 10.15.3 x86_64
• Node version: v12.16.1
• Node installation method: nvm
• Package name and version: @grpc/[email protected]

Screencast

[murgatroid99]

That does look like a bug, but I don't know what could be causing that to happen.

[murgatroid99]

In your screencast, you are running that code in a function connectToServer. Are you sure you're not just calling that function multiple times?

[badsyntax]

Hi. Yes i've checked, that method is called only once, and the ready callback is called 3 times.

I'm using a pretty standard gRPC Java server on the backend.

I've done some digging and it looks like there's some recursion happening which results in multiple watcherObjects being queued which results in the waitForReady callback being called multiple times.

It starts here: (note the callback (checkState) will re-run this code when the state changes - this is the recursion):

within client.waitForReady:

grpc-node/packages/grpc-js/src/client.ts

Lines 179 to 183 in 03fdeed

	this[CHANNEL_SYMBOL].watchConnectivityState(
	newState,
	deadline,
	checkState
	);

channel.watchConnectivityState will queue the first watcher:

grpc-node/packages/grpc-js/src/channel.ts

Lines 451 to 461 in 03fdeed

	const watcherObject = {
	currentState,
	callback,
	timer: setTimeout(() => {
	this.removeConnectivityStateWatcher(watcherObject);
	callback(
	new Error('Deadline passed without connectivity state change')
	);
	}, deadlineDate.getTime() - now.getTime()),
	};
	this.connectivityStateWatchers.push(watcherObject);

Now when channel.updateState is called, the watcher callback method is called, see:

grpc-node/packages/grpc-js/src/channel.ts

Lines 404 to 410 in 03fdeed

	for (const watcherObject of watchersCopy) {
	if (newState !== watcherObject.currentState) {
	watcherObject.callback();
	clearTimeout(watcherObject.timer);
	this.removeConnectivityStateWatcher(watcherObject);
	}
	}

watcherObject.callback is the original checkState callback defined in client.waitForReady, so now we're back to the beginning, and another watcher object is queued.

So I think the fix is to remove the watcher before calling the callback.

So change this code:

grpc-node/packages/grpc-js/src/channel.ts

Lines 406 to 408 in 03fdeed

	watcherObject.callback();
	clearTimeout(watcherObject.timer);
	this.removeConnectivityStateWatcher(watcherObject);

To this:

        clearTimeout(watcherObject.timer);
        this.removeConnectivityStateWatcher(watcherObject);
        watcherObject.callback();

I've tested this change and seems to work, the waitForReady callback is only called once, but I'm really not familiar with this code and I could be completely misunderstanding all of this. Also not sure the side-effects of making this change.

[murgatroid99]

I think I do see a situation that could cause what you're seeing: if the state transition that triggers the updateState call is a transition to the IDLE state, the getConnectivity state in the callback will synchronously kick the channel out of the idle state, calling updateState to be called again, so the watcherObject's callback will be called again before it is removed, increasing the number of eventual watchConnectivityState callbacks.

I'd be happy to make the change you described, or to accept a PR that makes that change.

[badsyntax]

Cool yes I think that makes sense. Am happy to make a PR for this, but will only get to doing it sometime tomorrow (BST).

[badsyntax]

I've added a PR with #1368 but it doesn't look like the builds are running. Should I close the PR and re-open?