When deadline is set to the current time for a GRPC call, the unary callback is never executed

[CMCDragonkai]

Problem description

If you set the deadline to the current date during a unary call:

const deadline = Date.now();
client.doSomeCall(
  emptyMessage,
  metadata,
  { deadline },
  (error, ...values) => {
    console.log('NEVER CALLED');
  }
);

This is in contrast to if you just create a slightly longer deadline like const deadline = Date.now() + 1000;. The callback will be executed with the deadline exceeded error.

I've used the debugger to trace why this is happening.

At the deadline-filter.js (compiled from TS), you have:

        if (timeout <= 0) {
            process.nextTick(() => {
                callStream.cancelWithStatus(constants_1.Status.DEADLINE_EXCEEDED, 'Deadline exceeded');
            });
        }

The timeout ends up being negative, because the deadline is too close to now.

Following through with the callStream.cancelWithStatus, it eventually leads to the outputStatus method on Http2CallStream.

In the process.nextTick call, the _a or this.listener ends up being null. When it is null, it never is able to execute the _a.onReceiveStatus(filteredStatus).

            const filteredStatus = this.filterStack.receiveTrailers(this.finalStatus);
            /* We delay the actual action of bubbling up the status to insulate the
             * cleanup code in this class from any errors that may be thrown in the
             * upper layers as a result of bubbling up the status. In particular,
             * if the status is not OK, the "error" event may be emitted
             * synchronously at the top level, which will result in a thrown error if
             * the user does not handle that event. */
            process.nextTick(() => {
                var _a;
                (_a = this.listener) === null || _a === void 0 ? void 0 : _a.onReceiveStatus(filteredStatus);
            });

Because the _a.onReceiveStatus(filteredStatus) is never called, it never returns the status back to the unary call callback, and thus the callback is never executed.

Reproduction steps

Clone this:

nix-shell # optional (if you have npm, you can just proceed)
# terminal 1
npm run polykey -- agent start --password-file=<(echo 'abc') --verbose
# terminal 2
npm run polykey -- agent unlock --verbose

You can see that the the console.log here:

https://github.com/MatrixAI/js-polykey/blob/grpcdeadlinebug/src/client/GRPCClientClient.ts#L119-L121

And here:

https://github.com/MatrixAI/js-polykey/blob/grpcdeadlinebug/src/grpc/utils/utils.ts#L215-L224

Are not logged out. If you change the deadline here to plus 1000 ms: https://github.com/MatrixAI/js-polykey/blob/grpcdeadlinebug/src/bin/agent/CommandUnlock.ts#L45

Then the messages will be outputted and the callback will be executed.

Environment

• OS name, version and architecture: Linux matrix-ml-1 5.10.81 Initial import #1-NixOS SMP Sun Nov 21 12:46:37 UTC 2021 x86_64 GNU/Linux
• Node version [e.g. 8.10.0]: v14.17.3
• Package name and version [e.g. gRPC@1.12.0]: "@grpc/grpc-js": "1.3.7"

[murgatroid99]

It looks like this is a consequence of having an async start interceptor, which you show in #1984. #1986 should fix both.

[CMCDragonkai]

Ah it is because that in my session interceptor, I'm also doing an asynchronous read operation.

[murgatroid99]

I have published #1986 in version 1.4.4, so this should be fixed now.