Node-postgres: ECONNRESET with unpooled connection / close

[aahoughton]

We're in the process of bringing up our (normally AWS-based) stack on azure with a hosted PG instance. Azure apparently requires SSL (which may or may not be important, but it's in the stack trace, so..)

We're running into issues with unpooled connections (used to verify DB availability) in our periodic DB status tests. node version is 6.9.0; node-postgres version is 6.4. Code looks like this (w/o longjohn):

require('longjohn');
const pg = require('pg');

const DSN = 'postgres://uid:pwd@azure_db:5432/imp?ssl=true';

function status(cb) {
    var start = Date.now();
    var client = new pg.Client(DSN);
    client.connect(function(err) {
        if (err) {
            return cb(err);
        }

        client.query("select 1 as pong", function(err, results) {
            client.end();

            if (err) {
                return cb(err);
            }

            if (!results.rows || results.rows.length !== 1 || results.rows[0].pong !== 1) {
                return cb(new Error("expected pong of 1"));
            }

            return cb(null, Date.now() - start);
        });
    });
}

setInterval(function() {
    console.log(new Date().toISOString());
    status(function(err, latency) {
        if (err) {
            console.error(err);
        }
    })
}, 5000);

.. errors (after 5s) with this:

Error: read ECONNRESET
    at exports._errnoException (util.js:1022:11)
    at TLSWrap.onread (net.js:569:26)
---------------------------------------------
    at Client.connect (/home/andrew/tmp/node_modules/pg/lib/client.js:184:7)
    at status (/home/andrew/tmp/test-unpooled-pg.js:9:12)
    at Timeout.<anonymous> (/home/andrew/tmp/test-unpooled-pg.js:32:5)
    at ontimeout (timers.js:365:14)
    at tryOnTimeout (timers.js:237:5)
    at Timer.listOnTimeout (timers.js:207:5)

.. seems like it may be related to https://github.com/brianc/node-postgres/issues/314 but unclear.

[brianc]

Looks like something is killing your connection attempt. Can you connect at _all_ to the postgres server from node-postgres? Is it just in this particular scenario? If you do console.log(client.connectionParameters) after you connect the client what do you see there? If you can connect with those same parameters via the pooled connections or psql then it might be an issue w/ node-postgres, but sounds more like a networking issue or postgres not being accessible from your server?

[wadik12]

Hello,

I have same problem with node-postgres and azure. I'm getting Error: read ECONNRESET after receiving response from database. My connectionParameteres:

{
  user: 'username',
  database: 'database',
  port: 5432,
  host: 'service_name.database.windows.net',
  password: 'password',
  binary: false,
  ssl: true,
  client_encoding: '',
  replication: undefined,
  isDomainSocket: false,
  application_name: undefined,
  fallback_application_name: undefined
}

Here is how I'm making query:

const { Pool } = require('pg')

const pool = new Pool({
  user: user,
  password: password,
  host: host,
  database: database,
  ssl: true,
  min: 4,
  max: 10,
  idleTimeoutMillis: 1000
})

function query (...args) {
  return pool.connect().then(client => {
    return client.query(...args)
      .then(res => {
        client.release()
        return res
      })
      .catch(err => {
        client.release()
        console.log(err.stack)
      })
  })
}

Same when I'm doing query this way:

function query (...args) {
  return pool.query(...args)
}

Also it's worth to add that after I disabled ssl on postgres and set ssl: false everything was ok.

[wadik12]

Your suggestion from #314 worked for me (adding this.stream.end();).
If it also works for @aahoughton I can create PR with fix.

[jeffreyplusplus]

I have a use case similar to @aahoughton and @wadik12. Modifying connection.js with the edit from #314 cleared the error for me as well.

[paoliniluis]

Same issue with Node and Azure hosted Postgres, been debugging this all day long. And yes, the problem is when you use SSL: true.
@brianc I can help you debug this if needed

[brianc]

@paoliniluis - I can't reproduce this locally or in any CI environment. Do you have an environment I can use to reproduce the issue? Without a reliable way to reproduce this or PR with test + fix I'm afraid there isn't a lot i can do to help fix the issue from where I sit.

[aahoughton]

OOC, have you tested against an azure-hosted instance (maybe you have, it's not clear)? Azure apparently provides $200 of free usage; barring that, I'm happy to set up a PG instance in their cloud using my account -- which I'll need to create -- and give you permissions. Note that I'm not familiar with their admin console, so it may take a few.

[paoliniluis]

@aahoughton are you able to set up an environment to @brianc? I can set up a video call and help you set up a postgre in Azure if needed. Send me an email directly

[aahoughton]

I just set one up (thank you for the offer, though). @brianc email incoming.

[paoliniluis]

hey @aahoughton, were you able to find any solution to this? thanks!

[cryptcoin-junkey]

@wadik12 Why did you close your PR by yourself?
I got a similar issue on AzureDB with SSL option.
It looks be resolved by your patch.

[charmander]

@cryptcoin-junkey If there is a problem, the patch might only hide it (rather than solve it). It’s important to find out exactly what’s going wrong first.

[cryptcoin-junkey]

@charmander I see.

I've additional info. This may depend on runtimes.

Just in my case.
At the first, I run my app on AzureVM on Japan East region. It worked fine.
Next, I move the app to AzureVM on Southeast Asia. I got this issue.
Both cases, AzureDB is same located on Southesast Asia.

[wadik12]

@cryptcoin-junkey I closed it because there was to many changes in the meantime, and I thought it's already been solved.

[jonathanneve]

I'm getting the same error as soon as I call end. I'm running on a Windows 10 dev machine against a PG server hosted in Azure, so perhaps that's part of the problem. I'd be glad to give you access to my machine for testing if you want.

[cryptcoin-junkey]

@wadik12 Thanks for your reply. Actually your patch is still effective as can be seen by reading comments...

[mitulgolakiya]

worked for me. by disabling ssl on Azure with the above fix #1386

[CocaColaBear]

Not worked for me. I disable SSL on Azure, but I steel get an error: "SSL connection is required. Please specify SSL options and retry"
And I can not connect to postgre azure database without "ssl=true" option :(((

[pasieronen]

I'm having a very similar issue with Azure PostgreSQL, and spent a while debugging this. I think I figured out what's happening.

I tried aahoughton's code snippet (the first in this issue) first against a local Postgresql server first, and inspected traffic with Wireshark. When Connection.prototype.end() is called (and the "0x58" command is sent), the server replies with TLS "close_notify" alert, and the client then cleanly closes the TCP connection. (And the code snipped works just fine)

When I run the same code against Azure Postgresql, the server immediately replies with a TCP RST (=ECONNRESET).

In Connection.prototype.connect, there's code handling this for the non-SSL case:

this.stream.on('error', function (error) {
  // don't raise ECONNRESET errors - they can & should be ignored                                                     
  // during disconnect                                                                                                
  if (self._ending && error.code === 'ECONNRESET') {
    return
  }  
  self.emit('error', error)
})

And about 30 lines later, we have the code for TLS:

self.stream.on('error', function (error) {
  self.emit('error', error)
})

...which is missing the test for self._ending! If I add the same test to the TLS error handler as well, things start working.

@brianc, I can't think of any easy way to trigger this situation on CI, would you accept a PR without tests?

[wadik12]

@brianc any update about this problem? Because it's still occur.

[CombatCode]

Seems to be solved by @pasieronen but still not implemented in node-postgres code and the sheeet numer of devs still wasting time on debugging it , as me now ;)

[FrostBergs]

Any idea on when the above PR will be merged? Would love to remove the workarounds in our code base written to avoid this issue.

[DonMartin76]

Also just ran into this...

[charmander]

Fixed in pg 7.4.1 by #1537.

[DonMartin76]

Yes, fixed with 7.4.1, thanks! (Wherever the question went)

[charmander]

@Elexy It’s happening when you call .end() on an unpooled connection?

[Elexy]

@charmander Sorry I deleted my comment again, because with the code stripped to the minimum I don't see the error. So I am expecting it is in another part of the code.

When I turn on logging I see:

connecting new client
connecting new client
new client connected
dispatching query
query dispatched
pulse queue
no queued requests
remove idle client
{ Error: read ECONNRESET
    at _errnoException (util.js:1031:13)
    at TCP.onread (net.js:619:25) errno: 'ECONNRESET', code: 'ECONNRESET', syscall: 'read' }

Sometimes the remove idle client appears after the ECONNRESET.
We are using pooled connections.

[Elexy]

@aahoughton how did you get the second part of your error, below the `---------------------':

Error: read ECONNRESET
    at exports._errnoException (util.js:1022:11)
    at TLSWrap.onread (net.js:569:26)
---------------------------------------------
    at Client.connect (/home/andrew/tmp/node_modules/pg/lib/client.js:184:7)
    at status (/home/andrew/tmp/test-unpooled-pg.js:9:12)
    at Timeout.<anonymous> (/home/andrew/tmp/test-unpooled-pg.js:32:5)
    at ontimeout (timers.js:365:14)
    at tryOnTimeout (timers.js:237:5)
    at Timer.listOnTimeout (timers.js:207:5)

[Elexy]

I can confirm that another part of my code caused the ECONNRESET.

[Magellol]

It seems that 7.4.1 didn't fix the issue on our end. We've also tried the undocumented option keepAlive on pool creation and it seems it reduced the amount of time it happened (almost thinking it was fixed) but this morning it happened twice.

const databaseConfig: PoolConfig & { keepAlive: boolean } = {
  keepAlive: true,
  connectionTimeoutMillis: 10000, // 10 seconds
  max: 10,
};

I can't seem to figure out where the issue is coming from, to be honest.

[Elexy]

@Magellol are you on Azure with SSL as well?
My config looks like this, on 7.4.1 and Azure with SSL:

conf.pg = {
  host: SERVICE_DB_HOST || 'localhost',
  port: SERVICE_DB_PORT || 5432, // optionally provide port
  database: SERVICE_DB_DATABASE || 'helloworld',
  user: SERVICE_DB_USER || 'postgres',
  password: SERVICE_DB_PASSWORD || 'postgres',
  max: SERVICE_DB_MAX_CLIENTS || 10, // max number of clients in the pool
  idleTimeoutMillis: SERVICE_DB_IDLE_TIMEOUT || 3000, // how long a client is allowed to remain idle before being closed
  // log: console.log,
  ssl : {
    rejectUnauthorized : false
  }
}

[Magellol]

@Elexy Ah sorry no we're not on Azure. Didn't notice this thread was mostly about it, my bad. Thanks for the snippet though!

We're on Kubernetes so I'm not sure it's an environment issue or not. Seems like you guys have some troubles as well on your environment. I can't figure out where the problem might come from, node-pg or actually pg itself.

[Elexy]

@charmander

@Elexy It’s happening when you call .end() on an unpooled connection?

Yes, I now found out that migrating the DB with postgrator it's using an unpooled connection and it never makes it past connection.end.

When I change

Connection.prototype.end = function () {
  // 0x58 = 'X'
  this.writer.add(emptyBuffer)
  this._ending = true
  return this.stream.write(END_BUFFER)
}

to

Connection.prototype.end = function () {
  // 0x58 = 'X'
  this.writer.add(emptyBuffer)
  this._ending = true
  this.stream.write(END_BUFFER)
  return this.stream.end()
}

It all begins to work again.

* update *
I tried to PR this change and found out that the tests fail with this error:

outbound-sending-tests.js...............Message: this.stream.end is not a function

So it's probably not correct :-)

[charmander]

@Elexy And you’re sure postgrator is using 7.4.1 as well?

[Elexy]

@charmander sorry for hijacking the issue, but yes, it's using 7.4.1
https://github.com/rickbergfalk/postgrator/blob/v3.4.0/package.json
Crazy thing is, that when I downgrade postgrator to 2.10.3 (with pg 7.4.1) it's able to pass the connection.end(). I just have to clean up the socket at the end of the migratons or the process never exits.

let handles = process._getActiveHandles()
    for (let i = 0; i < handles.length; i++) {
      if (handles[i]._host && handles[i]._host.indexOf('postgres')) {
        handles[i].end()
        console.log('Closed the postgres socket')
      }
    }

[Elexy]

@charmander I had several go's at a PR fixing this, but no luck. The tests are not passing:
https://travis-ci.org/brianc/node-postgres/jobs/362160405

I lack in depth knowledge of the PG protocol.

[Jackclarify]

I've been stuck in the follow error after runing request, which querying from localhost pg db.
query code:

const dbPool = new Pool({
        user: auth[0],
        password: auth[1],
        host: params.hostname,
        port: params.port,
        database: params.pathname.split('/')[1],
        ssl: databaseUrl.includes('ssl=true')
    });
const sql =` select ...`;
(async () => {
    const results = await dbPool.query(sql);
    dbPool.end();
    console.log(results);
  }
)()

Error details:

events.js:298
 throw er; // Unhandled 'error' event
      ^
Error: read ECONNRESET
    at TLSWrap.onStreamRead (internal/stream_base_commons.js:205:27)
Emitted 'error' event on  instance at:
    at module.exports.<anonymous> (D:\workspace\clarify-platform\node_modules\pg-pool\index.js:93:10)
    at Client.emit (events.js:321:20)
    at Connection.<anonymous> (D:\workspace\clarify-platform\node_modules\pg\lib\client.js:174:19)
    at Connection.emit (events.js:321:20)
    at TLSSocket.<anonymous> (D:\workspace\clarify-platform\node_modules\pg\lib\connection.js:94:12)
    at TLSSocket.emit (events.js:321:20)
    at emitErrorNT (internal/streams/destroy.js:92:8)
    at emitErrorAndCloseNT (internal/streams/destroy.js:60:3)
    at processTicksAndRejections (internal/process/task_queues.js:84:21) {
  errno: 'ECONNRESET',
  code: 'ECONNRESET',
  syscall: 'read',
  client: Client {
    _events: [Object: null prototype] { error: [Function: bound ] },
    _eventsCount: 1,
    _maxListeners: undefined,
    connectionParameters: ConnectionParameters {
      user: 'cxcxcx',
      database: 'cxcxcxcxc',
      port: 5432,
      host: '192.168.1.54',
      password: 'xdcxc',
      binary: false,
      ssl: true,
      client_encoding: '',
      isDomainSocket: false,
      application_name: undefined,
      fallback_application_name: undefined
    },
    user: 'xxxx',
    database: 'xxxxx',
    port: 5432,
    host: '192.168.1.54',
    password: 'xxx',
    _types: TypeOverrides { _types: [Object], text: {}, binary: {} },
    connection: Connection {
      _events: [Object: null prototype],
      _eventsCount: 18,
      _maxListeners: undefined,
      stream: [TLSSocket],
      lastBuffer: false,
      lastOffset: 0,
      buffer: null,
      offset: 1,
      encoding: 'utf8',
      parsedStatements: {},
      writer: [Object],
      ssl: true,
      _ending: true,
      _mode: 0,
      _emitMessage: false,
      _reader: [Object],
      checkSslResponse: true,
      [Symbol(kCapture)]: false
    },
    queryQueue: [],
    binary: false,
    encoding: 'utf8',
    processID: 14624,
    secretKey: -1950471986,
    ssl: true,
    activeQuery: null,
    readyForQuery: true,
    hasExecuted: true,
    _destroying: true,
    [Symbol(kCapture)]: false
  }
}

Error in project:

2020-05-21 18:02:31.84 - error: uncaughtException: read ECONNRESET date=Thu May 21 2020 18:02:31 GMT+0800 (China Standard Time), pid=29368, uid=null, gid=null, cwd=D:\workspace\clarify-platform, execPath=C:\Program Files\nodejs\node.exe, version=v12.16.0, argv=[C:\Program Files\nodejs\node.exe, D:\workspace\clarify-platform\server\server.js], rss=212840448, heapTotal=152281088, heapUsed=142320984, external=2908202, loadavg=[0, 0, 0], uptime=427041, trace=[column=27, file=internal/stream_base_commons.js, function=TLSWrap.onStreamRead, line=205, method=onStreamRead, native=false, column=null, file=---------------------------------------------, function=null, line=null, method=null, native=null, column=10, file=D:\workspace\clarify-platform\node_modules\pg-pool\index.js, function=module.exports.Pool._create, line=89, method=_create, native=false, column=17, file=D:\workspace\clarify-platform\node_modules\pg-pool\node_modules\generic-pool\lib\generic-pool.js, function=Pool._createResource, line=325, method=_createResource, native=false, column=12, file=D:\workspace\clarify-platform\node_modules\pg-pool\node_modules\generic-pool\lib\generic-pool.js, function=Pool.dispense [as _dispense], line=313, method=dispense [as _dispense], native=false, column=8, file=D:\workspace\clarify-platform\node_modules\pg-pool\node_modules\generic-pool\lib\generic-pool.js, function=Pool.acquire, line=391, method=acquire, native=false, column=15, file=D:\workspace\clarify-platform\node_modules\pg-pool\index.js, function=null, line=111, method=null, native=false, column=7, file=D:\workspace\clarify-platform\node_modules\pg-pool\index.js, function=module.exports.Pool._promiseNoCallback, line=75, method=_promiseNoCallback, native=false, column=15, ...
2020-05-21 18:02:31.85 - error: [{"errno":"1","code":"1","syscall":"2","client":"3","domainEmitter":"4","domainThrown":false},"ECONNRESET","read",{"_events":"5","_eventsCount":1,"connectionParameters":"6","user":"7","database":"8","port":5432,"host":"9","password":"10","_types":"11","connection":"12","queryQueue":"13","binary":false,"encoding":"14","processID":6000,"secretKey":1908159699,"ssl":true,"activeQuery":null,"readyForQuery":true,"hasExecuted":true,"_destroying":true},{"_events":"15","_eventsCount":0,"options":"16","pool":"17"},{},{"user":"7","database":"8","port":5432,"host":"9","password":"10","binary":false,"ssl":true,"client_encoding":"18","isDomainSocket":false},"clarify","circle_test","192.168.1.54","IaCA61RaFsA74GeR",{"_types":"19","text":"20","binary":"21"},[88,0,0,0,4,87,73,84,72,32,70,69,32,65,83,32,40,10,32,32,32,32,83,69,76,69,67,84,32,74,46,104,111,115,...,0,0,0,5,73],[],{},{"head":null,"tail":null,"length":0},[null,null],[null,null],[null,null],{"next":null,"entry":null}]

The database log is "could not receive data from client an existing connection was forcibly closed by the remote host"
I tracked that it was emitted from pg-pool index.js, but I don't know the root cause.

Here is the pg-pool index.js(version 1.8.0) section:

Pool.prototype._create = function (cb) {
  this.log('connecting new client')
  var client = new this.Client(this.options)

  client.on('error', function (e) {
    this.log('connected client error:', e)
    this.pool.destroy(client)
    e.client = client
    this.emit('error', e, client)   //  throw error here
  }.bind(this))

  client.connect(function (err) {
    if (err) {
      this.log('client connection error:', err)
      cb(err, null)
    } else {
      this.log('client connected')
      this.emit('connect', client)
      cb(null, client)
    }
  }.bind(this))
}

Connect parameters:

auth:"yyyyy:xxxx"
hash:null
host:"192.168.1.54:5432"
hostname:"192.168.1.54"
href:"postgres://yyyyy:[email protected]:5432/circle_test?ssl=true"
path:"/circle_test?ssl=true"
pathname:"/circle_test"
port:"5432"
protocol:"postgres:"
query:"ssl=true"
search:"?ssl=true"
slashes:true

Envrionment:

OS: windows10 
pg db container from postgres:10.6 image
package: 
       pg: 4.5.7
       pg-pool: 1.8.0

Finally I find if I change the container's export port, which is different from localhost enterprisedb instance(it's status is exit, not up) port, the error message disappeared.

For anyone who might suffer same pain here.

[ndastur]

I'm only recently seeing this too. Wonder if it's a regression?