Log additional error properties

[felixfbecker]

Currently, when using SQL mode and a migration contains a syntax error, db-migrate will only print the error message and call stack:

[ERROR] AssertionError [ERR_ASSERTION]: ifError got unwanted exception: syntax error at or near ")"
    at node_modules/db-migrate/lib/commands/on-complete.js:15:14
    at tryCatcher (node_modules/bluebird/js/release/util.js:16:23)
    at Promise.successAdapter (node_modules/bluebird/js/release/nodeify.js:22:30)
    at Promise._settlePromise (node_modules/bluebird/js/release/promise.js:601:21)
    at Promise._settlePromiseCtx (node_modules/bluebird/js/release/promise.js:641:10)
    at _drainQueueStep (node_modules/bluebird/js/release/async.js:97:12)
    at _drainQueue (node_modules/bluebird/js/release/async.js:86:9)
    at Async._drainQueues (node_modules/bluebird/js/release/async.js:102:5)
    at Async.drainQueues [as _onImmediate] (node_modules/bluebird/js/release/async.js:15:14)
    at process.processImmediate (node:internal/timers:476:21)
    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 (node:events:513:28)
    at addChunk (node:internal/streams/readable:324:12)
    at readableAddChunk (node:internal/streams/readable:297:9)
    at Readable.push (node:internal/streams/readable:234:10)
    at TCP.onStreamRead (node:internal/stream_base_commons:190:23)

Even for a medium sized migration SQL file, syntax error at or near ")" can be like finding a needle in a haystack.

When using pg, the Error actually contains additional information with the exact position of the syntax error. But currently, that information is not logged, as explicitly only the stack of the error is logged.

This PR changes it so that the entire error object is logged. Node's behavior when an Error is passed to console.error() (which is used under the hood by log.js) is to log only the stack property if there are no additional properties, meaning there would be no difference in those cases.

But if there are additional properties, Node will log both the stack with message, and any properties after it:

In particular, the position here can be copy-pasted into an editor's "go to position" command to jump exactly to the syntax error in the SQL file. Other properties can be helpful in case e.g. a DB constraints gets violated by the migration, as it can contain the constraint name, offending column values, etc.

One small change is also necessary to make sure the error gets properly logged: Throw the actual error if it's an Error instance instead of wrapping it in an AssertionError, as the AssertionError just adds additional noise to the log and since the Error gets nested under the actual property, it doesn't get expanded in the log but reduced to only [DatabaseError]. There may be a small benefit in wrapping in an error given the error may not be an Error instance, but if it is, it makes more sense to throw the error directly.

[wzrdtales]

removing stack logging can be troublesome, although with promises it anyways has become troublesome since promises just swallow all the information. I can't possibly merge this, as you're breaking the functionality by removing the explicit logging of the stack. Maybe you can adjust it so the stack logging still happens, or at least can be configured.

[felixfbecker]

I'm not sure I understand – isn't the stack still logged in the screenshot above? The information logged now is a strict superset of what was logged before

[wzrdtales]

The stack does not get logged by default on all error objects. That is why.

[felixfbecker]

Are you sure? What's an example of an error object that wouldn't have the stack logged by console.log()?

[felixfbecker]

For reference, here's the code branch in NodeJS that formats errors:

https://github.com/nodejs/node/blob/1e3631f0e392eeac327c33aeb56f590814ba5c39/lib/internal/util/inspect.js#L983-L984

isError() returns true for any Error instance, even from other realms (see https://nodejs.org/api/util.html#utiltypesisnativeerrorvalue).

If for some reason a non-Error instance was to be thrown with a stack property, it would still get logged as a property of a plain object, just not formatted quite as pretty. I think that is an okay trade-off because that's kind of what you have to expect when throwing a non-Error instance, it's not going to get formatted as an Error, but as an object with properties and values. It would actually still print information than currently, because currently no other properties on such object except stack get logged.

Note also that the current code already doesn't support this case well, for example if somebody was to throw null the current code would throw because it's trying to read stack of null. The code in this PR would actually handle this more gracefully.

But if you'd like I could add an extra if that checks for the case of a non-Error object with a stack property and in that case log the stack instead.

[FabianFrank]

I second what @felixfbecker said, if the stack isn't being logged that's most likely an issue with the underlying logging framework, explicitly logging the error but not the stack is definitely not the norm and it removes a lot of useful information.