Handle "Connection terminated unexpectedly"

[bajtos]

The spark-api instance running on Fly.io is periodically crashing with the following error:

2023-09-11T06:11:51.893 app[080e126b565608] cdg [info] Error: Connection terminated unexpectedly
2023-09-11T06:11:51.893 app[080e126b565608] cdg [info] at Connection.<anonymous> (/app/node_modules/pg/lib/client.js:132:73)
2023-09-11T06:11:51.893 app[080e126b565608] cdg [info] at Object.onceWrapper (node:events:627:28)
2023-09-11T06:11:51.893 app[080e126b565608] cdg [info] at Connection.emit (node:events:513:28)
2023-09-11T06:11:51.893 app[080e126b565608] cdg [info] at Connection.emit (node:domain:489:12)
2023-09-11T06:11:51.893 app[080e126b565608] cdg [info] at Socket.<anonymous> (/app/node_modules/pg/lib/connection.js:63:12)
2023-09-11T06:11:51.893 app[080e126b565608] cdg [info] at Socket.emit (node:events:513:28)
2023-09-11T06:11:51.893 app[080e126b565608] cdg [info] at Socket.emit (node:domain:489:12)
2023-09-11T06:11:51.893 app[080e126b565608] cdg [info] at TCP.<anonymous> (node:net:301:12)

• The error seems to happen outside of the request handler (in the background).
• The error happens often
  • Sep 11, 2023 06:11 UTC
  • Sep 11, 2023 02:41 UTC
  • Sep 11, 2023 00:11 UTC
  • Sep 10, 2023 22:10 UTC
  • Sep 10, 2023 21:40 UTC
  • Sep 10, 2023 21:10 UTC
  • Sep 10, 2023 20:40 UTC
  • Sep 10, 2023 18:40 UTC
  • Sep 10, 2023 17:40 UTC
  • Sep 10, 2023 17:10 UTC
  • Sep 10, 2023 15:09 UTC
  • (...)
• There is no Sentry record for this error. Instead, Sentry is seeing many unhandled rejections coming from Ethers.js (link)

cc @juliangruber

[juliangruber]

Machine upgraded from 512MB memory to 1GB

[juliangruber]

I don't see anything actionable for me here. @bajtos please close or reassign

[bajtos]

Possibly related discussion:
https://stackoverflow.com/questions/49697082/node-postgres-connection-terminated-unexpectedly

One of the comments suggests the following pg-pool config change:
This may be related to the minimum pool size set to a number greater than 0.
The pool keeps the minimum amount of connections there even if they are terminated. Assigning 0 to the minimum size and also a defining good idle timeout value, maybe 1-5 minutes, can prevent this from happening.

knex/knex#3523 (comment)

Looks like things are happening as I expected so that error is not either happening or registered before it is taken away from pool and data is actually sent over the connection.
One can probably work around this issue by setting minimum pool size to 0 and set idle timeout to be like 5 minutes or so. In that way connections will be discarded from pool before that.

This GH issue seems to be very relevant too. Quoting one of the solutions offered:
brianc/node-postgres#2112 (comment)

Using these values with Knex seems to solve the issue. Specifically setting the pool minimum to 0.

pool: { min: 0, max: 10, acquireTimeoutMillis: 30000, idleTimeoutMillis: 30000 }

Some people are using a different pool implementation:
https://www.npmjs.com/package/postgres-pool

[bajtos]

Bummer. #95 did not fix the problem :(

https://fly.io/apps/spark/monitoring?instance=e286770fe039e8&next_token=1695744986000000000

2023-09-26T16:17:23.139 app[e286770fe039e8] iad [info] Error: Connection terminated unexpectedly
2023-09-26T16:17:23.139 app[e286770fe039e8] iad [info] at Connection.<anonymous> (/app/node_modules/pg/lib/client.js:132:73)
2023-09-26T16:17:23.139 app[e286770fe039e8] iad [info] at Object.onceWrapper (node:events:627:28)
2023-09-26T16:17:23.139 app[e286770fe039e8] iad [info] at Connection.emit (node:events:513:28)
2023-09-26T16:17:23.139 app[e286770fe039e8] iad [info] at Connection.emit (node:domain:489:12)
2023-09-26T16:17:23.139 app[e286770fe039e8] iad [info] at Socket.<anonymous> (/app/node_modules/pg/lib/connection.js:63:12)
2023-09-26T16:17:23.139 app[e286770fe039e8] iad [info] at Socket.emit (node:events:513:28)
2023-09-26T16:17:23.139 app[e286770fe039e8] iad [info] at Socket.emit (node:domain:489:12)
2023-09-26T16:17:23.139 app[e286770fe039e8] iad [info] at TCP.<anonymous> (node:net:301:12)
2023-09-26T16:17:23.270 app[e286770fe039e8] iad [info] POST /retrievals 200 (508ms)
2023-09-26T16:17:23.293 proxy[e286770fe039e8] iad [error] could not complete HTTP request to instance: connection closed before message completed

[bajtos]

We haven't encountered this error in the past week according to Papertrail logs, and I don't remember seeing it for ages.