Feature Request: Error messages including request table, query parameters and options

marcelcremer commented 6 years ago

Hi@all,

I'd like to suggest better error messages if something bad happens while querying the postgres database.

Current Behaviour

Currently, I often encounter errors like:

{ error: Column »table« doesn't exist
[1]     at Connection.parseE (E:\Development\UnitDesk\server\core\node_modules\pg-promise\node_modules\pg\lib\connection.js:545:11)
[1]     at Connection.parseMessage (E:\Development\UnitDesk\server\core\node_modules\pg-promise\node_modules\pg\lib\connection.js:370:19)
[1]     at Socket.<anonymous> (E:\Development\UnitDesk\server\core\node_modules\pg-promise\node_modules\pg\lib\connection.js:113:22)
[1]     at emitOne (events.js:116:13)
[1]     at Socket.emit (events.js:211:7)
[1]     at addChunk (_stream_readable.js:263:12)
[1]     at readableAddChunk (_stream_readable.js:250:11)
[1]     at Socket.Readable.push (_stream_readable.js:208:10)
[1]     at TCP.onread (net.js:594:20)
[1]   name: 'error',
[1]   length: 102,
[1]   severity: 'ERROR',
[1]   code: '42703',
[1]   detail: undefined,
[1]   hint: undefined,
[1]   position: '41',
[1]   internalPosition: undefined,
[1]   internalQuery: undefined,
[1]   where: undefined,
[1]   schema: undefined,
[1]   table: undefined,
[1]   column: undefined,
[1]   dataType: undefined,
[1]   constraint: undefined,
[1]   file: 'parse_relation.c',
[1]   line: '3090',
[1]   routine: 'errorMissingColumn' } } reason: { error: Column »table« doesn't exist
[1]     at Connection.parseE (E:\Development\UnitDesk\server\core\node_modules\pg-promise\node_modules\pg\lib\connection.js:545:11)
[1]     at Connection.parseMessage (E:\Development\UnitDesk\server\core\node_modules\pg-promise\node_modules\pg\lib\connection.js:370:19)
[1]     at Socket.<anonymous> (E:\Development\UnitDesk\server\core\node_modules\pg-promise\node_modules\pg\lib\connection.js:113:22)
[1]     at emitOne (events.js:116:13)
[1]     at Socket.emit (events.js:211:7)
[1]     at addChunk (_stream_readable.js:263:12)
[1]     at readableAddChunk (_stream_readable.js:250:11)
[1]     at Socket.Readable.push (_stream_readable.js:208:10)
[1]     at TCP.onread (net.js:594:20)
[1]   name: 'error',
[1]   length: 102,
[1]   severity: 'ERROR',
[1]   code: '42703',
[1]   detail: undefined,
[1]   hint: undefined,
[1]   position: '41',
[1]   internalPosition: undefined,
[1]   internalQuery: undefined,
[1]   where: undefined,
[1]   schema: undefined,
[1]   table: undefined,
[1]   column: undefined,
[1]   dataType: undefined,
[1]   constraint: undefined,
[1]   file: 'parse_relation.c',
[1]   line: '3090',
[1]   routine: 'errorMissingColumn' }****

Every time I see one of those, I think to myself: "Wow, useful..." as there's absolutely no context information included.

As I have many many massivejs queries invoked dynamically, I don't know which query was invoked with which parameters causing this error.

Current Debug Options

Currently I have two options to find the context of this error:

attach pg-promise-monitor to see the generated SQL
attach a debugger and try to find the context by including many breakpoints (as the pgp-promise runs async and doesn't have the massive context)

Both of them are a real pain for sporadically occuring runtime errors. In my use case, massive is invoked after calling a REST service, so wrong http parameters might cause database errors.

Suggestion

As Massive invokes PG-Promise and direktly returns the promise to the client which causes this behaviour, I'd suggest to wrap the Promises, catch the error, fill in some context information (e.g. QueryTable "foo", QueryObject: {"table": 'bar', "id >": 20}) and reject another Promise with the additional Information - maybe with a custom Error Type "MassiveError" (I love that Name) or something.

The basic idea is like:

let pgp = require('pg-promise');
...
select => (table, queryParameters) => {
...
return pgp.any(`select * from foo where table='bar' AND id > 20`)
.then(data => Promise.resolve(data)) // bubble up the original data
.catch(error => {
 return Promise.reject({ // Add some context information to the original pgp error
table,
queryParameters,
pgp-error: error
});
};
...
}

I'd try to make a pull request, but I'm not deep enough in the massive code yet. Also, maybe you have some additional suggestions on how we could improve the error handling to get some context to the pgp-error.

Best Regards Marcel

vitaly-t commented 6 years ago

You already have several approaches to diagnosing errors - error event, pg-monitor, and Bluebird long-stack tracing. Using at least one of them is sufficient.

marcelcremer commented 6 years ago

Hi Vitaly,

yes - I do not deny that there are some options. But runtime errors, especially sporadic ones are really hard to debug. The current Options all need a reconfiguration of the server to enable the debugging stuff and waiting for the error to occur again:

the error event doesn't have context information in the stack
pg-monitor needs to be attached to log queries, which will usually occur after the error happened
Bluebird is not an option in my opinion. There are native promises available and a good tool should work and be able to debug without using an external Promise library

On the other side, adding context information to the pgp-error would be always available, doesn't cost performance and is easy to implement - at least when you know, where pgp is called.

I don't see negative impact if that would be implemented tbh. Maybe you could explain your concerns?

Best Regards Marcel

vitaly-t commented 6 years ago

the error event doesn't have context information in the stack

Bluebird stack has all the details.

pg-monitor needs to be attached to log queries, which will usually occur after the error happened

What do you mean after? You attach to events at the app start, and it logs everything.

Bluebird is not an option in my opinion.

It is the best option, better performing and way more flexible, especially when it comes to stack tracing. I don't understand your arguments against it.

In all, you have all the right tools already.

marcelcremer commented 6 years ago

Hi Vitaly,

I hope I catched you on a bad day, so I'll try it once again:

the error event doesn't have context information in the stack

Bluebird stack has all the details.

Of course it has. But I'm trying to tell you, that the light of my bike is flashing and suggest to fix the bulb. You tell me to rent a mercedes instead, because it's more comfortable.

Massive doesn't depend on Bluebird and should work perfectly fine without it. The error handling is just not as good as it could be, and I described, how to give some context information with a small change. I also wrote, that I might be able to give a pull request for it and asked, what concerns you have.

It's like telling people to use jQuery foreach, because they have problems with the native array foreach function, which is not very productive.

pg-monitor needs to be attached to log queries, which will usually occur after the error happened

What do you mean after? You attach to events at the app start, and it logs everything.

I'm talking about runtime errors. They just occur, somewhen, in production. And when they do, they should be somewhat meaningful.

It's not recommended to use pg-monitor in production, and neither it is for bluebird longstack:

Long stack traces imply a substantial performance penalty, around 4-5x for throughput and 0.5x for latency.

http://bluebirdjs.com/docs/api/promise.longstacktraces.html

Adding the table that was called, the query parameter and query options to the error message however, doesn't have any penality as it's already there. It just needs to be added to the error, so it get's printed when the error occurs.

I hope you have a great day and weekend.

Marcel

dmfay commented 6 years ago

I've usually just tailed the Postgres log when I've needed to track down SQL errors -- you do have to restart PG if you don't have it turned on, but if you're already logging then it's quite transparent.

I'm open to improving error messaging on the Massive side (clearer is always better) but just showing SQL seems like a half measure as the developer is still required to work out which call would have generated it. I haven't really gone past the surface level of dealing with JavaScript errors & stack traces & so on but it seems like it should be possible somehow, I just want to make sure it's done elegantly without boilerplate error traps on every API method.

dmfay / massive-js