Error stack traces lack invocation context

[oleg-codaio]

Currently when using grpc-node, any gRPC errors get raised with somewhat unhelpful stack traces (see https://github.com/grpc/grpc-node/issues/1250, https://github.com/grpc/grpc-node/issues/1661, https://github.com/grpc/grpc-node/issues/1808 for some examples):

Error: 14 UNAVAILABLE: Stream refused by server
    at Object.callErrorFromStatus (/usr/src/app/node_modules/@grpc/grpc-js/build/src/call.js:31:26)
    at Object.onReceiveStatus (/usr/src/app/node_modules/@grpc/grpc-js/build/src/client.js:176:52)
    at Object.onReceiveStatus (/usr/src/app/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:336:141)
    at Object.onReceiveStatus (/usr/src/app/node_modules/@grpc/grpc-js/build/src/client-interceptors.js:299:181)
    at /usr/src/app/node_modules/@grpc/grpc-js/build/src/call-stream.js:145:78
    at processTicksAndRejections (internal/process/task_queues.js:75:11)

The original trace is lost and this makes debugging the source of any errors more difficult. Can we splat on the original stack trace onto any thrown errors?

[murgatroid99]

If you have any ideas about how to accomplish that, we'd be happy to accept suggestions or PRs.

[oleg-codaio]

Sure! I'm not familiar with this codebase, but one thing I noticed is the call to callErrorFromStatus:

https://github.com/grpc/grpc-node/blob/bf2e5cb1dd25e43f53605d8de2b8e082072ec23e/packages/grpc-js/src/call.ts#L79-L82

This function is creating the Error inline, which means it's the stack up at this point in the callback. Instead, we'd want to move the creation of the Error object to where the call is made, perhaps right above this line:

https://github.com/grpc/grpc-node/blob/bf2e5cb1dd25e43f53605d8de2b8e082072ec23e/packages/grpc-js/src/client.ts#L315

If we wanted to get verbose and include both of the stacks, we could do something like this:

  const callingStack = new Error().stack;
  // ...
  call.start(callProperties.metadata, {
    // ...
    onReceiveStatus(status: StatusObject) {
      // ...
      if (status.code === Status.OK) {
        // ...
      } else {
        callProperties.callback!(callErrorFromStatus(status, callingStack));
      }
      // ...

and then callErrorFromStatus would combine the two:

export function callErrorFromStatus(status: StatusObject, callingStack: string): ServiceError {
  const message = `${status.code} ${Status[status.code]}: ${status.details}`;
  const err = new Error(message);
  const stack = `${callingStack}\n\ncaused by\n${err.stack}`;
  return Object.assign(err, status, {stack});
}

That's the general idea for unary calls - I haven't used streaming calls as much myself so haven't thought about how to handle those. (This would have a performance impact due to always creating the Error object up front, but I'd imagine it's negligible in the context of gRPC network I/O.)

BTW, a "better" way to do this longer term might be with async hooks, but as of this time that API is still marked experimental.

[murgatroid99]

I admit, I misremembered a bit about where that error was getting constructed. The fact that it's lexically close to where the call starts does make it easier to grab that call stack. I think this looks like a fairly reasonable option.

[jasonmit]

This is also problematic with tools like Sentry as it has no way of deciphering the differences between errors and so erroneously groups all errors originating from callErrorFromStatus together since their call stacks are identical.

The alternative is manually defining really verbose fingerprinting rules within Sentry.

[murgatroid99]

This has been resolved. In current versions of the library, these errors now additionally show the stack trace of the start of the call.