Stack traces are truncated / lack client side stack trace

[bluenote10]

When pg throws an error, I often have trouble finding the place in my code where this is actually coming from. For some reasons the exceptions thrown by pg seem to contain strange stack trace, and in particular, the stack trace doesn't contain any client side code. I'm actually on TypeScript running through ts-node, but I think I can reproduce the behavior with plain JS. Here is a minimal example:

const pg = require("pg");

async function provokeExceptionPg() {
  let client = new pg.Client();
  await client.connect();
}

provokeExceptionPg().catch((err) => console.log(err));

The output of running node index.js is just:

Error: connect ECONNREFUSED 127.0.0.1:5432
    at TCPConnectWrap.afterConnect [as oncomplete] (net.js:1146:16) {
  errno: -111,
  code: 'ECONNREFUSED',
  syscall: 'connect',
  address: '127.0.0.1',
  port: 5432
}

Note that the output is completely lacking any information of client side code, which in this case would just be my index.js. To demonstrate the kind of traceback I'd expect, I can for instance replace new pg.Client() by something broken like new pg.ClientNonexisting(). This results in a stack trace that clearly shows the client side stack leading to the error:

TypeError: pg.ClientNonexisting is not a constructor
    at provokeExceptionPg (/tmp/test_project/index.js:4:16)
    at Object.<anonymous> (/tmp/test_project/index.js:8:1)
    [...]

The lack of client side stack traces makes it very hard to understand where errors are coming from in a more complex code base. Is there any way to get more meaningful stack traces out of pg or would that make sense as a feature request?

[vitaly-t]

Bring your own promise - Bluebird, and enable Long Stack Traces.

const Promise = require('bluebird');

Promise.config({
    longStackTraces: true
});

// creating pool with custom Promise:
const pool = new Pool({Promise});

[bluenote10]

I had the impression that this is no longer necessary now that --async-stack-traces is enabled by default. At least I often get meaningful stack traces from other libraries (presumably using default promises), and e.g. basic examples like this also seem to contain the full trace by default.

Perhaps it is due to remaining bugs around async stack traces in nodejs though.

I still need to figure out the patterns when it works and when it doesn't.

[stiff]

It kind of snapshots trace when Error was created.

For example, this:

function foo() { 
  return new Promise((res, rej) => ... rej(new Error(err))); 
}

will lose it, but this:

function foo() { 
  const error = new Error(err);
  retrun new Promise((res, rej) => ... rej(error)); 
}

will preserve stack trace.

[rightaway]

@bluenote10 In that issue nodejs/node#36126 (comment) it's due to bugs in the library not in Node.

[rightaway]

These are the kind of stack traces I'm getting in Node 14. Not very useful for debugging.

error: invalid byte sequence for encoding "UTF8"
    at Parser.parseErrorMessage (node_modules/pg-protocol/dist/parser.js:287:98)
    at Parser.handlePacket (node_modules/pg-protocol/dist/parser.js:126:29)
    at Parser.parse (node_modules/pg-protocol/dist/parser.js:39:38)
    at Socket.<anonymous> (node_modules/pg-protocol/dist/index.js:11:42)
    at Socket.emit (events.js:400:28)
    at addChunk (internal/streams/readable.js:290:12)
    at readableAddChunk (internal/streams/readable.js:265:9)
    at Socket.Readable.push (internal/streams/readable.js:204:10)
    at TCP.onStreamRead (internal/stream_base_commons.js:188:23)'

[javier-garcia-meteologica]

It seems that using bluebird is not a future-proof solution. Take a look at this warning.

Please use native promises instead if at all possible. Native Promises have been stable in Node.js and browsers for around 6 years now and they have been fast for around 3. Bluebird still offers some useful utility methods and you can use it - but please consider native promises first.
[...]
Currently - it is only recommended to use Bluebird if you need to support old browsers or EoL Node.js or as an intermediate step to use warnings/monitoring to find bugs.

As a workaround, here is this wrapper around native promises to augment stack traces

const PromiseWithAugmentedStackTrace = function PromiseWithAugmentedStackTrace <T> (
  executor: (
    resolve: (value: T | PromiseLike<T>) => void,
    reject: (reason?: unknown) => void
  ) => void
): Promise<T> {
  return new Promise(executor)
    .catch(err => {
      const infoErr = new Error();

      if (infoErr.stack != null && typeof err === 'object' && err != null) {
        if (typeof (err as Error).stack === 'string') {
          (err as Error).stack = [
            (err as Error).stack,
            'From previous event:',
            infoErr.stack.split('\n').slice(1).join('\n') // Remove first line
          ].join('\n');
        } else {
          (err as Error).stack = infoErr.stack;
        }
      }

      throw err;
    });
} as unknown as PromiseConstructor;

PromiseWithAugmentedStackTrace.resolve = <T>(value?: T | PromiseLike<T>) => Promise.resolve(value);
PromiseWithAugmentedStackTrace.reject = (reason: unknown) => Promise.reject(reason);
PromiseWithAugmentedStackTrace.race = <T>(values: Iterable<T | PromiseLike<T>>) => Promise.race(values);
PromiseWithAugmentedStackTrace.all = <T>(values: Iterable<T | PromiseLike<T>>) => Promise.all(values);
PromiseWithAugmentedStackTrace.any = <T>(values: Iterable<T | PromiseLike<T>>) => Promise.any(values);
PromiseWithAugmentedStackTrace.allSettled = <T>(values: Iterable<T | PromiseLike<T>>) => Promise.allSettled(values);

It can be used with node-postgres as follows

const pool = new pg.Pool({
  ...connectionConfig,
  Promise: PromiseWithAugmentedStackTrace
});

[TimUnderhay]

I am getting loads of disconnects with no evident way of directly seeing what's causing them (Node 16.13.0 / node-pg 8.7.1). They almost always happen when firing concurrent queries from multiple clients obtained from a pool. They also happen after a time when firing thousands of independent queries with pool.query(). Postgres server logs show no errors.

Error: This socket has been ended by the other party
    at Socket.writeAfterFIN [as write] (node:net:474:14)
    at Socket.ondata (node:internal/streams/readable:754:22)
    at Socket.emit (node:events:390:28)
    at addChunk (node:internal/streams/readable:315:12)
    at readableAddChunk (node:internal/streams/readable:289:9)
    at Socket.Readable.push (node:internal/streams/readable:228:10)
    at TCP.onStreamRead (node:internal/stream_base_commons:199:23)

What I've also learned is that that particular error is a big, fat, lying lier (at least in my case) :). Tcpdump reveals that it's the client that is ending the connection. Which is interesting because it still attempts to write to the socket after it just ended it. It would be awesome if it would give the reason reason why this is happening in the stack trace.

As it transpires, when this does occur, my exception handler is never triggered -- the program is just 'stuck' at this point, though it doesn't exit.