sticky "pgbouncer cannot connect to server" error

[strk]

I'm experimenting with shutting down / resurrecting PostgreSQL backends while mapnik renders tiles trough pgbouncer and I'm getting a "sticky" pgbouncer error which could be revealing some issue in mapnik itself.

In particular I don't understand if mapnik is taking the "bad" connection out of the pool and trying to reconnect OR if it is reusing the same bad connection from the pool.

Connecting to the database using psql(1) and the same connection string as the one reported by mapnik in the log succeeds.

This is the error I keep getting:

Error: Postgis Plugin: ERROR:  pgbouncer cannot connect to server

Connection string: 'host=localhost port=6432 dbname=cartodb_dev_user_2_db user=publicuser connect_timeout=4'
  encountered during parsing of layer 'layer0' in Layer at line 12

And this is is the success when connecting with psql:

[strk@cdb:~] psql 'host=localhost port=6432 dbname=cartodb_dev_user_2_db user=publicuser connect_timeout=4'
psql (9.3.1)
Type "help" for help.

cartodb_dev_user_2_db=> 

[strk]

This is with the current tip of the 2.3.x branch ( f202197 ).
I'm now rebuilding with DEBUG=1 to see if I can get more info.

[strk]

NOTE: I'm using mapnik via node-mapnik / tilelive-manik / windshaft, so the "stickiness" could also be in any of the other places. Hopefully more debugging will tell me.

[strk]

There's indeed no more attempt to construct a Connection object during the continuous responses of "failure". This is the last trace from the mapnik log (related to connection):

Mapnik LOG> 2014-03-07 14:48:46: postgis_connection: postgresql connection create - 0x21e87e0
Mapnik LOG> 2014-03-07 14:48:46: postgis_connection: creation failed, closing connection - 0x21e87e0
Mapnik LOG> 2014-03-07 14:48:46: postgis_connection: closing connection (close)- 0x21e87e0

And this is the last trace in absolute from the log (19 minutes later!):

Mapnik LOG> 2014-03-07 15:06:49: agg_renderer: Start processing layer=layer0
Mapnik LOG> 2014-03-07 15:06:49: agg_renderer: -- datasource=0x21ef450
Mapnik LOG> 2014-03-07 15:06:49: agg_renderer: -- query_extent=box2d(-20037508.3000000007450581,-20037508.3000000007450
581,20037508.3000000007450581,20037508.3000000007450581)
Mapnik LOG> 2014-03-07 15:06:49: agg_renderer: Start processing style
Mapnik LOG> 2014-03-07 15:06:49: agg_renderer: End processing style
Mapnik LOG> 2014-03-07 15:06:49: agg_renderer: End layer processing
Mapnik LOG> 2014-03-07 15:06:49: agg_renderer: End map processing

After that, there's no more log coming out, and we're right now at (8 more minutes later):

[2014-03-07 15:11:50.256] [INFO] console - [TILE RENDER ERROR] -- 400: Error: Postgis Plugin: ERROR:  pgbouncer cannot connect to server

Connection string: 'host=localhost port=6432 dbname=cartodb_dev_user_2_db user=publicuser connect_timeout=4'
  encountered during parsing of layer 'layer0' in Layer at line 12

Can it be that the renderer operation fails to be advertised as failing ?
Or the caller (node-mapnik ? tilelive-mapnik ? windshaft ?) fails to check it

[strk]

NOTE: those 19 minutes between the connection failure and the agg_renderer traces contain NO other mapnik traces

[strk]

For the record, I'm using (node.js) tilelive-mapnik@0.6.7, mapnik@0.7.26 and tilelive@4.4.3

[strk]

Waiting 1 minute for the expiration of a "RendererCache" in windshaft@0.19.4 and thus re-creating such cache, finally triggers re-trying to connect and gets a complete rendering. A "RendererCache" is basically what's returned by tilelive.load. In any case this is definitely NOT related to mapnik but rather to higher levels. I'll file it in tilelive.