Reconnecting hangs when connection is terminated

[Ingramz]

While attempting to produce a connection error, I noticed that pg-listen seems to never recover from termination:

SELECT pg_terminate_backend(pid) FROM pg_stat_activity WHERE pid <> pg_backend_pid() AND usename = 'myusername';

Log:

  pg-listen:connection Creating PostgreSQL client for notification streaming +0ms
  pg-listen:subscription Subscribing to PostgreSQL notification "test-chan" +0ms
  pg-listen:connection DB Client error: { error: terminating connection due to administrator command
    at Connection.parseE (/Users/indrek/test/node_modules/pg/lib/connection.js:601:11)
    at Connection.parseMessage (/Users/indrek/test/node_modules/pg/lib/connection.js:398:19)
    at Socket.<anonymous> (/Users/indrek/test/node_modules/pg/lib/connection.js:120:22)
    at Socket.emit (events.js:189:13)
    at addChunk (_stream_readable.js:284:12)
    at readableAddChunk (_stream_readable.js:265:11)
    at Socket.Readable.push (_stream_readable.js:220:10)
    at TCP.onStreamRead [as onread] (internal/stream_base_commons.js:94:17)
  name: 'error',
  length: 109,
  severity: 'FATAL',
  code: '57P01',
  detail: undefined,
  hint: undefined,
  position: undefined,
  internalPosition: undefined,
  internalQuery: undefined,
  where: undefined,
  schema: undefined,
  table: undefined,
  column: undefined,
  dataType: undefined,
  constraint: undefined,
  file: 'postgres.c',
  line: '2881',
  routine: 'ProcessInterrupts' } +6s
  pg-listen:connection Reconnecting to PostgreSQL for notification streaming +18ms
  pg-listen:connection PostgreSQL reconnection attempt #1... +0ms
  pg-listen:connection DB Client error: Error: Connection terminated unexpectedly
    at Connection.con.once (/Users/indrek/test/node_modules/pg/lib/client.js:223:9)
    at Object.onceWrapper (events.js:277:13)
    at Connection.emit (events.js:189:13)
    at Socket.<anonymous> (/Users/indrek/test/node_modules/pg/lib/connection.js:130:10)
    at Socket.emit (events.js:194:15)
    at endReadableNT (_stream_readable.js:1125:12)
    at process._tickCallback (internal/process/next_tick.js:63:19) +131ms
  pg-listen:connection Reconnecting to PostgreSQL for notification streaming +0ms
  pg-listen:connection PostgreSQL reconnection attempt #1... +1ms
  pg-listen:connection DB Client connection ended +1ms
  pg-listen:connection Reconnecting to PostgreSQL for notification streaming +0ms
  pg-listen:connection PostgreSQL reconnection attempt #1... +0ms

[andywer]

Hey @Ingramz, thanks for reporting!

Sorry for the delayed response. I saw the issue, but didn't have much time and couldn't see what might cause that behavior.

Can you by any chance provide some sample code to reproduce the issue (maybe something unit-test-ish)?

What caught my attention is the repeating PostgreSQL reconnection attempt #1.... It doesn't seem to increment the attempt number.

[Ingramz]

This is pretty much the example code from readme, nothing special about it.

const connectionString = 'YOUR CONNECTION STRING'

const createSubscriber = require('pg-listen')

// Accepts the same connection config object that the "pg" package would take
const subscriber = createSubscriber({ connectionString })

subscriber.notifications.on("my-channel", (payload) => {
  // Payload as passed to subscriber.notify() (see below)
  console.log("Received notification in 'my-channel':", payload)
})

subscriber.events.on("error", (error) => {
  console.error("Fatal database connection error:", error)
  process.exit(1)
})

process.on("exit", () => {
  subscriber.close()
})

async function connect () {
  await subscriber.connect()
  await subscriber.listenTo("my-channel")
}

connect()

Started it up using DEBUG=pg-listen:* node poc.js

First I sent a payload to test if it works: NOTIFY "my-channel", '"my payload"'

Then I terminated the connection using the query I posted earlier.

Finally I waited a little and then tried to send that same payload again.

[andywer]

Memo to myself:
Actionable - Log errors at https://github.com/andywer/pg-listen/blob/master/src/index.ts#L218 with connectionLogger. An error might have happened there that didn't make it into the logs.

[andywer]

Sorry that it took some time, but the issue is fixed now! A regression test has also been added.

Thanks for the detailed report 🙌
Released as v1.2.2 🚀

[Ingramz]

No worries. So far it is working great, thanks!