@grpc/grpc-js: sendUnaryData callback not working as expected

[nateshmbhat]

Problem description

When i call the sendUnaryData callback function of the request handler as soon as the request comes , the grpc client successfully gets the response.

When i am calling the callback function after awaiting for the result of a promise , the client call is not getting complete and response is not received.

Reproduction steps :

Here's the below code for handling the request that doesn't send the response to the client :

(clientCall: any, callback: grpc.sendUnaryData<any>) => {
        new Promise((res, rej)=>{
          setTimeout(() => {
           res({message : 'my response'}) 
          }, 1000);
        })
          .then(responseInfo => {
            console.log('calling response interceptor on : ', responseInfo);
            return responseInfo
          })
          .then(responseInfo => {
            console.log('sending transformed response : ', responseInfo);
            callback(null,{message : 'its working'} )
          });
      };

Though the callback function gets called after 1 second , the response never reaches the client. Also the same behavior is seen even when i reduce the timeout to just "1 milli second" or even "0" .

Code that works :

The client successfully gets the response , if i resolve the promise outside the set timeout function.

clientCall: any, callback: grpc.sendUnaryData<any>) => {
        new Promise((res, rej)=>{
           res({message : 'my response'});
        })
          .then(responseInfo => {
            console.log('calling response interceptor on : ', responseInfo);
            return responseInfo
          })
          .then(responseInfo => {
            console.log('sending transformed response : ', responseInfo);
            callback(null,{message : 'its working'} )
          });
      };

if i change the code to the above code , then i get a proper response :

{
  "message": "its working"
}

Environment

• Linux pop-os 5.8.0-7625-generic
• Node version v10.19.0
• Package name and version "@grpc/grpc-js": "^1.2.2"

Additional Context :

Here is the full enclosing function code that i am using ( may be helpful ? ) :

function addGrpcServices(server: grpc.Server | null, serviceProtos: ProtoService[]): void {
  serviceProtos.forEach(serviceProto => {
    const serviceImplementation: grpc.UntypedServiceImplementation = {}
    Object.entries(serviceProto.methods).forEach(([methodName, methodRpcInfo]) => {
      serviceImplementation[methodName] = (clientCall: any, callback: grpc.sendUnaryData<any>) => {
        new Promise((res, rej) => {
           setTimeOut( ()=>{
               res({ message: 'my response' })
            } , 1000);
        })
          .then(responseInfo => {
            // i plan to add some console log and other stuff here later.
            return responseInfo
          })
          .then(responseInfo => {
            callback(null, { message: 'its working' })
          });
      };
    })
    server.addService(serviceProto.serviceDefinition, serviceImplementation);
  })
}

export const startMockGrpcServer = (serviceProtos: ProtoService[]): void => {
  const grpcServer = new grpc.Server();

  addGrpcServices(grpcServer, serviceProtos)
  appConfigStore.subscribe(config => {
    grpcServer.bindAsync(config.mockGrpcServerUrl, grpc.ServerCredentials.createInsecure(), (error, port) => {
      if (error) {
        console.error(error)
      }
      else {
        console.log("Started server at port : ", port)
        grpcServer.start();
        appConfigStore.setMockGrpcServer(grpcServer)
      }
    });
  })();
}

[nateshmbhat]

does someone have any idea why this may be happening or what i can do to fix this ? any direction would be of great help here...

[murgatroid99]

So, in your server code that is failing, are you seeing both of the log lines?

I suggest running the server with the environment variables GRPC_TRACE=all and GRPC_VERBOSITY=DEBUG and sharing the output. That may help determine what is happening here.

[nateshmbhat]

Thanks for the reply :)

Here are the logs. please take a look at them.

logging.js:50 2020-12-03T05:35:52.561Z | dns_resolver | Resolver constructed for target dns:localhost:50051
logging.js:50 2020-12-03T05:35:52.562Z | dns_resolver | Resolution update requested for target dns:localhost:50051
logging.js:50 2020-12-03T05:35:52.564Z | dns_resolver | Resolved addresses for target dns:localhost:50051: [::1:50051,127.0.0.1:50051]
logging.js:50 2020-12-03T05:35:52.564Z | server | Attempting to bind ::1:50051
logging.js:50 2020-12-03T05:35:52.565Z | server | Attempting to bind 127.0.0.1:50051
logging.js:50 2020-12-03T05:35:52.566Z | server | Successfully bound ::1:50051
logging.js:50 2020-12-03T05:35:52.566Z | server | Successfully bound 127.0.0.1:50051
grpcServer.ts:57 Started server at port :  50051
logging.js:50 2020-12-03T05:36:06.086Z | server | Received call to method /hello_world.Greeter/SayHello at address ::1:50051
grpcServer.ts:27 calling response interceptor on :  
{message: "my response"}
grpcServer.ts:33 sending transformed response :  
{message: "my response"}
logging.js:50 2020-12-03T05:36:06.107Z | server_call | Request to method /hello_world.Greeter/SayHello ended with status code: OK details: OK
```

I am sending the request from BloomRpc client

[nateshmbhat]

I tried to debug this. here's the behavior for the below code :

(clientCall: any, callback: grpc.sendUnaryData<any>) => {
        new Promise((res, rej) => {
          res({message: 'my response'})
        })
          .then(responseInfo => {
            console.log('calling response interceptor on : ', responseInfo);
            return responseInfo
          }
          )
          .then(responseInfo => {
            console.log('sending transformed response : ', responseInfo);
            callback(null, responseInfo)
          })
          .catch(e => {
            console.log('error in sending response : ', e)
            callback(e, null)
          });
      };
    })

• when i sent the request from the client , i got a successful response and the grpc stream "closed" successfully and i saw the below logs :

logging.js:50 2020-12-03T14:25:28.104Z | server_call | Request to method /hello_world.Greeter/SayHello ended with status code: OK details: OK
logging.js:50 2020-12-03T14:25:28.104Z | server_call | Request to method /hello_world.Greeter/SayHello stream closed with rstCode 0

• when i sent the request and had turned the debugger on with a break point to a line that is executed after the call and before the response , once i hit continue on the breakpoint. it is sending "ok" response but not "closing" the grpc stream. So i'm getting only the "ok response" in the log as shown below :

2020-12-03T14:25:42.207Z | server_call | Request to method /hello_world.Greeter/SayHello ended with status code: OK details: OK

• looks like if server takes some time in processing the request , its not emitting the "stream closed" event.

[murgatroid99]

In the second case where you use a debugger, does the client get the response?

[nateshmbhat]

No, the client keeps loading.

It looks like the close event is not emitted for the stream at all. So the call doesn't get finished and closed at the client.

[murgatroid99]

Can you check if it has the same behavior on Node 14?

[nateshmbhat]

unfortunately, same behavior even when I am using node 14.

Here's the output from process.versions from within the chrome dev tools in electron :

{node: "12.16.3", v8: "8.5.210.26-electron.0", uv: "1.34.2", zlib: "1.2.11", brotli: "1.0.7", …}
ares: "1.16.0"
brotli: "1.0.7"
chrome: "85.0.4183.121"
electron: "10.1.5"
http_parser: "2.9.3"
icu: "67.1"
llhttp: "2.0.4"
modules: "82"
napi: "5"
nghttp2: "1.41.0"
node: "12.16.3"
openssl: "1.1.0"
unicode: "13.0"
uv: "1.34.2"
v8: "8.5.210.26-electron.0"
zlib: "1.2.11"
__proto__: Object

[nateshmbhat]

Here is a more full fledged example to demonstrate the issue :

import * as grpc from '@grpc/grpc-js'
import type { PackageDefinition } from '@grpc/grpc-js/build/src/make-client';

var PROTO_PATH = __dirname + '/../static/sample/greeter-service.proto';

var protoLoader = require('@grpc/proto-loader');
var packageDefinition: PackageDefinition = protoLoader.loadSync(
  PROTO_PATH,
  {
    keepCase: true,
    longs: String,
    enums: String,
    defaults: true,
    oneofs: true
  });
var hello_world_package = grpc.loadPackageDefinition(packageDefinition);

function sayHello(call: any, callback: any) {
  console.log('Request : ', call)
  new Promise((res, rej) => {
    setTimeout(() => {
      res({ message: 'Hello ' + call.request.name })
    } , 100)
  })
    .then(response => {
      callback(null, response);
    })
}


export function startDummyGrpcTargetServer({ port }: { port: number }) {
  var server = new grpc.Server();
  //@ts-ignore
  server.addService(hello_world_package.hello_world.Greeter['service'], { sayHello: sayHello });
  server.bindAsync(`localhost:${port}`, grpc.ServerCredentials.createInsecure(), (error, port) => {
    if (error) {
      console.error(error, port)
    }
    else {
      console.log('Dummy Grpc Test Server started at port : ', port)
      server.start();
    }
  });
}

The proto file being used is :

syntax = "proto3";

option java_multiple_files = true;
option java_package = "com.grpc.myproject.helloworld";
option java_outer_classname = "HelloWorldProto";
option objc_class_prefix = "HLW";
package hello_world;

service Greeter {
    rpc SayHello (HelloRequest) returns (HelloReply) {}
  }

  message HelloRequest {
    string name = 1;
  }
  message HelloReply {
    string message = 1;
  }

[nateshmbhat]

@murgatroid99 anything else that i can try ?

[murgatroid99]

Does any of the promise stuff matter here? If you just call the callback in the setTimeout callback, do you see the same behavior?

[nateshmbhat]

Yes, I see the same behavior.

[murgatroid99]

I tried running your most recent example server code, and I see the response on the client, so I'm not reproducing this failure.

You mentioned the versions in Electron. Are you running this code in Node, or in Electron?

[nateshmbhat]

I'm running it in electron and it's giving this issue.

I tried the above sample server code in just node 14 and node 10. Both are working fine.

What could be the way forward to overcome this?

[nateshmbhat]

I have attached a sample minimal project here : https://github.com/nateshmbhat/grpc-with-electron-sample-project Please run this using npm run dev command which opens the electron window and runs the server at port 50053 in the background.

Use any grpc client to make the call to SayHello rpc . (proto included in the project in the sample/ directory)

[nateshmbhat]

@murgatroid99 anything else that I can do to help you figure out and fix this issue ?

[murgatroid99]

I came back to this issue today to do my own testing and I found that, at least on Windows, if I run the code in your example repository, the server sends the response, and then waits 10 seconds, and then closes the stream. After those 10 seconds, the client sees the response and reports that the request completed successfully. However, if I set the environment variable NODE_DEBUG=http2 on the server (to attempt to debug it), the delay drops to 0.

My recommendation to you is essentially the same as what people said in the Electron issue you opened: don't try to run things like this in the Electron renderer process. It's not made for that.

[PrakashDahal]

@murgatroid99 any update on this issue? I am using @grpc/grpc-js and encountered same issue in sendUnaryData callback. I have handled it with unnecessary async and await for now.

[aspin]

@PrakashDahal how did you handle it? I'm encountering a similar issue. My node GRPC server is making a web request to fetch some data, then return data to client over GRPC. If I return the data immediately, it works, but if I actually make the web request (which successfully some data) it doesn't.

On the client side (Go), I get panic: rpc error: code = Internal desc = Assertion failed.

EDIT: never mind, my issue is elsewhere. In the actual data from my web request I was getting NaN / -Infinity for some fields and putting them into the protobuf definition. Doesn't look like there's an error being surfaced anywhere for this though...