Errors are swallowed

[frandiox]

Hi, thanks for this tool!

I've noticed that DB connection errors using https://github.com/porsager/postgres are swallowed. It doesn't show anything at all.

I need to add console.log(err) to this line https://github.com/lukeed/ley/blob/master/index.js#L42 in order to see the actual error.

[lukeed]

Hey, thanks!

Do you mind telling me how to reproduce? Was it a standard SQL syntax error, or something more specific?

Either way, I thought this would be catching & reporting migration errors: https://github.com/lukeed/ley/blob/master/bin.js#L15

[frandiox]

@lukeed Hi! Thanks for your answer.

The issue is about DB connection. porsager/postgres uses process.env.PGPASSWORD for the Postgres password, for example. I'm using multienv-loader to load environment variables but that shouldn't matter (just so you understand the following logs).

If I don't declare PGPASSWORD variable, ley doesn't throw anything in my terminal:

➜  project git:(master) ✗ yarn migrate:staging up
yarn run v1.22.0
$ cross-env NODE_ENV=staging yarn migrate up
$ ley -C ./src/lib/database -r multienv-loader/load up
✨  Done in 0.82s.

If I declare the variable it works:

➜  project git:(master) ✗ yarn migrate:staging up
yarn run v1.22.0
$ cross-env NODE_ENV=staging yarn migrate up
$ ley -C ./src/lib/database -r multienv-loader/load up

[ley] All caught up! 🎉

✨  Done in 0.73s.

When I add a console.error(err) to https://github.com/lukeed/ley/blob/master/index.js#L42 , with the PGPASSWORD variable missing:

➜  project git:(master) ✗ yarn migrate:staging up      
yarn run v1.22.0
$ cross-env NODE_ENV=staging yarn migrate up
$ ley -C ./src/lib/database -r multienv-loader/load up
PostgresError: password authentication failed for user "xxxx"
    at Object.ErrorResponse (/project/node_modules/postgres/lib/backend.js:131:22)
    at Socket.data (/project/node_modules/postgres/lib/connection.js:226:25)
    at Socket.emit (events.js:315:20)
    at addChunk (_stream_readable.js:295:12)
    at readableAddChunk (_stream_readable.js:271:9)
    at Socket.Readable.push (_stream_readable.js:212:10)
    at TCP.onStreamRead (internal/stream_base_commons.js:186:23) {
  severity_local: 'FATAL',
  severity: 'FATAL',
  code: '28P01',
  file: 'auth.c',
  line: '345',
  routine: 'auth_failed'
}
✨  Done in 0.52s.

Therefore, I guess there might be some gotcha with Promise swallowing errors :/

[lukeed]

Hmm... I'm having a hard time reproducing. If you enter other incorrect connection details, is it the same error?

For example, I have this inside a local ley.config.js for the postgres client:

module.exports = {
    host        : '',
  port        : 5432,
  path        : '',
  database    : 'ley_testing',
  username    : 'foobar',
  password    : '',
}

(This is just a way to avoid ENV reliance)

$ node bin -C test/fixtures/postgres status

[ley] Loading configuration

[ley] An error occurred:

      Error: role "foobar" does not exist
        at Object.generic (/.../node_modules/postgres/lib/types.js:200:5)
        at Object.ErrorResponse (/.../node_modules/postgres/lib/backend.js:125:22)
        at Socket.data (/.../node_modules/postgres/lib/connection.js:167:25)
        at Socket.emit (events.js:315:20)
        at addChunk (_stream_readable.js:295:12)
        at readableAddChunk (_stream_readable.js:271:9)
        at Socket.Readable.push (_stream_readable.js:212:10)
        at TCP.onStreamRead (internal/stream_base_commons.js:186:23)
      severity_local: FATAL
      severity: FATAL
      code: 28000
      file: miscinit.c
      line: 607
      routine: InitializeSessionUserId

[frandiox]

Just tried without env variables and using the config you posted but same result:

$ ley -C ./src/lib/database up
[ley] Loading configuration
✨  Done in 0.67s.

When I add the console.error, it shows password authentication failed for user "foobar".

Also, just updated to ley@0.6.0 but doesn't change anything.

--

I've tried creating a new clean project with only ley and the config you posted. It shows errors when the migration folder doesn't exist but not with connection erros:

  _test git:(master) ✗ ./node_modules/.bin/ley up
[ley] Loading configuration

[ley] An error occurred:

      Error: ENOENT: no such file or directory, scandir '/.../_test/migrations'
        errno: -2
        code: ENOENT
        syscall: scandir
        path: /.../_test/migrations

➜  _test git:(master) ✗ mkdir migrations
➜  _test git:(master) ✗ ./node_modules/.bin/ley up
[ley] Loading configuration
➜  _test git:(master) ✗ 

I'm using Node v12.18.4 in Mac Catalina 10.15.6, not sure what else could be affecting this 😓

[lukeed]

Hmmm... what version of postgres and what version of PostgreSQL? 😆

[frandiox]

😅 postgres@2.0.0-beta.0 and PostgreSQL 12

[lukeed]

Oh. I imagine the 2.0-beta is the problem – or at least, something changed in the way it handles (connection) errors. I've been using latest for the above samples.

//cc @porsager 👋 hey~! perhaps you can shed some light on this? I don't see anything in the beta's changelog.

[porsager]

@lukeed Yeah, I've got another user telling me the same about connection option errors, so could very well be something in postgres@beta.. I'll just have a look

[porsager]

@lukeed I found 2 cases of errors being swallowed where I hadn't considered errors could be thrown. I've made a new beta release with that fix.

Would you mind trying postgres@2.0.0-beta.1 @frandiox ?

[frandiox]

Unfortunately, I still get the same result. No errors even though the connection is wrong:

➜  microservices git:(master) ✗ rimraf node_modules 
➜  microservices git:(master) ✗ yarn
yarn install v1.22.0
...
➜  microservices git:(master) ✗ yarn why postgres
yarn why v1.22.0
...
=> Found "postgres@2.0.0-beta.1"
info Has been hoisted to "postgres"
...
✨  Done in 0.52s.
➜  microservices git:(master) ✗ yarn migrate:staging up
yarn run v1.22.0
$ cross-env NODE_ENV=staging yarn migrate up
$ ley -C ./src/lib/database -r multienv-loader/load up
✨  Done in 0.73s.

I'm using PGUSER, PGPASSWORD, PGHOST (with IP-like value), and PGDATABASE environment variables if that helps.

I think the error itself is working since I can see it if I add a console.error in a catch right before this finally https://github.com/lukeed/ley/blob/master/index.js#L47 -- PostgresError: password authentication failed for user "xxx".

[frandiox]

@porsager I've tracked the issue to this line: https://github.com/lukeed/ley/blob/master/lib/clients/postgres.js#L13

Maybe sql.unsafe behavior is different in beta and it doesn't throw properly? I've tried to return a manual error (throw new Error('test')) before that line and it works.

[frandiox]

@porsager Ok I think I've found the source of evil: https://github.com/porsager/postgres/blob/master/lib/index.js#L250

That catch statement is trying to throw errors but that seems to be swallowed. It's explained here: http://jamesknelson.com/are-es6-promises-swallowing-your-errors/

After removing that catch, ley shows errors in the terminal normally:

 microservices git:(master) ✗ yarn migrate:staging up
yarn run v1.22.0
$ cross-env NODE_ENV=staging yarn migrate up
$ ley -C ./src/lib/database -r multienv-loader/load up

[ley] An error occurred:

      PostgresError: password authentication failed for user "xxx"
        at Object.ErrorResponse (/.../node_modules/postgres/lib/backend.js:131:22)
        at Socket.data (/.../node_modules/postgres/lib/connection.js:233:25)
        at Socket.emit (events.js:315:20)
        at addChunk (_stream_readable.js:295:12)
        at readableAddChunk (_stream_readable.js:271:9)
        at Socket.Readable.push (_stream_readable.js:212:10)
        at TCP.onStreamRead (internal/stream_base_commons.js:186:23)
      name: PostgresError
      severity_local: FATAL
      severity: FATAL
      code: 28P01
      file: auth.c
      line: 345
      routine: auth_failed

[porsager]

Thanks for debugging @frandiox 🙂

It's very odd though. I don't see why that error shouldn't be re-thrown, and I can't reproduce it with a bare setup of postgres@2.0.0-beta1.

Do you have a setup I can clone where I can repro this?

[frandiox]

@porsager Here you go https://github.com/frandiox/postgres-ley-issue

[porsager]

Thanks a lot! Reproduces here, so I'll take a look later today..

[porsager]

Ok, so I've gotten to the core of the issue now. There was actually two issues in Postgres.js which I've got fixed by investigating this, so thanks a lot for bringing it to my attention @frandiox and @lukeed !

The first was that I was wrongly expecting the socket to be ready before calling end() to try and end it gracefully, but it would never reach the ready state with things like connection errors.

The other was that I was using socket.end(resolve) for the end promise which would result in the promise returned by sql.end() being pending forever if something held the tcp connection open. For this use case it was better to use socket.on('close', resolve); socket.end() instead.

The reason your fix worked for this specific case was not because of rethrowing the error (which didn't make sense to me at first), but because of removing arrayTypesPromise = null. That prevented the error popping up in the sql.end() and thereby hiding the above underlying issues.

I've released fixes for those issues in beta.2 now so I think this issue can also be closed 🙂

Thanks for hosting a Postgres.js issue here @lukeed 😂

[frandiox]

@porsager Can confirm it works now, thank you! Thank you for your time as well @lukeed !

[lukeed]

Very cool! Glad we were able to help/host 😜