error stack traces are not displaying the original line when used with async/await

[capaj]

Environment

Knex version: 0.14.4
Database + version: I think that any, I used pg
OS: any
node.js: 9.4.0

given this code:

global.Promise = require('bluebird')
Promise.longStackTraces()
const knex = require('knex')

const db = knex({
  client: 'pg',
  connection: {
    host: 'localhost',
    user: 'my_user',
    password: 'supersecret',
    database: 'my_db'
  }
})

const test = async () => {
  db('userss')
    .select()
    .then(() => {})
}

test()

and the fact that I don't have a userss table in my_db
I get this error:

capaj@capaj-i7-4771:~/git_projects/tests$ node knex.js
Unhandled rejection error: relation "userss" does not exist
    at Connection.parseE (/home/capaj/git_projects/tests/node_modules/pg/lib/connection.js:545:11)
    at Connection.parseMessage (/home/capaj/git_projects/tests/node_modules/pg/lib/connection.js:370:19)
    at Socket.<anonymous> (/home/capaj/git_projects/tests/node_modules/pg/lib/connection.js:113:22)
    at emitOne (events.js:116:13)
    at Socket.emit (events.js:211:7)
    at addChunk (_stream_readable.js:263:12)
    at readableAddChunk (_stream_readable.js:250:11)
    at Socket.Readable.push (_stream_readable.js:208:10)
    at TCP.onread (net.js:594:20)
From previous event:
    at Client_PG._query (/home/capaj/git_projects/tests/node_modules/knex/lib/dialects/postgres/index.js:287:12)
    at Client_PG.query (/home/capaj/git_projects/tests/node_modules/knex/lib/client.js:199:17)
    at Runner.<anonymous> (/home/capaj/git_projects/tests/node_modules/knex/lib/runner.js:149:36)
From previous event:
    at /home/capaj/git_projects/tests/node_modules/knex/lib/runner.js:61:21
    at runCallback (timers.js:789:20)
    at tryOnImmediate (timers.js:751:5)
    at processImmediate [as _immediateCallback] (timers.js:722:5)
From previous event:
    at Runner.run (/home/capaj/git_projects/tests/node_modules/knex/lib/runner.js:47:31)
    at Builder.Target.then (/home/capaj/git_projects/tests/node_modules/knex/lib/interface.js:35:43)
    at test (/home/capaj/git_projects/tests/knex.js:18:6)
    at Object.<anonymous> (/home/capaj/git_projects/tests/knex.js:21:1)
    at Module._compile (module.js:635:30)
    at Object.Module._extensions..js (module.js:646:10)
    at Module.load (module.js:554:32)
    at tryModuleLoad (module.js:497:12)
    at Function.Module._load (module.js:489:3)
    at Function.Module.runMain (module.js:676:10)
    at startup (bootstrap_node.js:187:16)
    at bootstrap_node.js:608:3

now let's change only the body of test function into something like this:

await db('userss').select()

now I get this error thrown:

(node:30763) UnhandledPromiseRejectionWarning: error: relation "userss" does not exist
    at Connection.parseE (/home/capaj/git_projects/tests/node_modules/pg/lib/connection.js:545:11)
    at Connection.parseMessage (/home/capaj/git_projects/tests/node_modules/pg/lib/connection.js:370:19)
    at Socket.<anonymous> (/home/capaj/git_projects/tests/node_modules/pg/lib/connection.js:113:22)
    at Socket.emit (events.js:160:13)
    at addChunk (_stream_readable.js:269:12)
    at readableAddChunk (_stream_readable.js:256:11)
    at Socket.Readable.push (_stream_readable.js:213:10)
    at TCP.onread (net.js:599:20)
From previous event:
    at Client_PG._query (/home/capaj/git_projects/tests/node_modules/knex/lib/dialects/postgres/index.js:287:12)
    at Client_PG.query (/home/capaj/git_projects/tests/node_modules/knex/lib/client.js:199:17)
    at Runner.<anonymous> (/home/capaj/git_projects/tests/node_modules/knex/lib/runner.js:149:36)
From previous event:
    at /home/capaj/git_projects/tests/node_modules/knex/lib/runner.js:61:21
    at runCallback (timers.js:756:18)
    at tryOnImmediate (timers.js:717:5)
    at processImmediate [as _immediateCallback] (timers.js:697:5)
From previous event:
    at Runner.run (/home/capaj/git_projects/tests/node_modules/knex/lib/runner.js:47:31)
    at Builder.Target.then (/home/capaj/git_projects/tests/node_modules/knex/lib/interface.js:35:43)
    at process._tickCallback (internal/process/next_tick.js:160:7)
    at Function.Module.runMain (module.js:703:11)
    at startup (bootstrap_node.js:193:16)
    at bootstrap_node.js:617:3

My original file with test function:

at Object.<anonymous> (/home/capaj/git_projects/tests/knex.js:21:1)

is nowhere in the stacktrace when called with await and that should be fixed IMHO.
I did a little bit of googling and found out this issue: nodejs/node#11865
Which is still opened to this day. IMHO it should be possible to hack it even without the support in node.js. In NODE_ENV=development knex could remember the stacktrace to the last called querybuilder and put that in the thrown error. It is far from ideal solution, but it would certainly help me a ton.
In this discussion someone else proposed similar solution for pupeteer: puppeteer/puppeteer#979 (comment)

In the current state it's quite hard to debug any async/await code because developer simply always have to guess where the exception might have been thrown.

[tgriesser]

I agree, there could be a better developer experience here. I'll take a look into what it'd take to capture the stack trace at the time of execution to give a better trace.

[elhigu]

I have also been thinking of storing information already since the last time when this issue was reported last year.

To me the solution where one would store stacktrace of the place where query builder was initially created (or even every place where it was modified) to the query builder when in debug mode could be enough.

Would definitely make debugging easier.

[wubzz]

I don't like the idea that that useful stacktraces would be dependant upon debug: true tbh. Would expect useful stacks in production logs where debug is never enabled.

Not sure on the performance impact of Error.captureStackTrace but adding it to the knex constructors allows that stack to be used where the error is actually thrown via runner.builder.stack.

At the end of the day I feel it boils down to a Node issue..

[elhigu]

Of course if it doesn't cause big performance / memory consumption hit it could be enabled as default. Maybe separate configuration parameter for this one could be used instead of relaying on debug: true.

[capaj]

@elhigu I'd opt in for a separate config param as well. Something like: asyncStackTraces. I'd default it to true if the performance penalty of making a query would be under 20% to current version. If more, I'd default to false

[repl-raymond-bolander]

We've run into this issue of snipped / incomplete stack traces when using async.

This seems to rear its head periodically during development; Devs end up having to fiddle around to get to the bottom of why a particular knex-dependent section of code is failing, wasting time in the process. So this does have impact, at least for our team.

Has anyone tried using asyncStackTraces under load who maybe has stats to show the impact?

2 Cents worth of thoughts:

• Don't we need need another issue for this, or to re-open? Seems as though our best-effort asyncStackTraces is only suitable for debugging - so in my mind, this is still an outstanding issue, is it not?

• I understand asyncStackTraces can be enabled. Docs allude to a performance impact though, and suggests using it only in debug. If this is a firm recommendation, it would be nice for this to be more absolute and clear, and provide an example use case or something.

• If we are saying collectively that this issue is out of our hands, do we want to add it to list of 'known issues'? Closed github issues make it hard to tell where things have been left off if they don't have a reason supplied.

Happy to assist if/when the knex team decides what the next steps are.