DBConnection Error(DBConnection.ConnectionError) tcp recv: closed (PGPool)

mcrunix

Hi Everyone, I’m trying to use PGPool in front of a PG database and Ecto’s using it but all commands failed. Here are the logs that I figured out.

$ mix ecto.create
** (Mix) The database for App.Repo couldn't be created: command timed out

Also, I hit PGPool through postgrex directly and more info turned out.

iex(1)> {:ok, pid} = Postgrex.start_link(hostname: "localhost", port: 7432, username: "postgres", password: "adminpassword", database: "postgres", prepare: :unnamed)
{:ok, #PID<0.594.0>}
iex(2)> Postgrex.query!(pid, "SELECT 1;", [], [timeout: 20000])
** (DBConnection.ConnectionError) tcp recv: closed (the connection was closed by the pool, possibly due to a timeout or because the pool has been terminated)
    (postgrex 0.15.7) lib/postgrex.ex:249: Postgrex.query!/4
{"msg":"Postgrex.Protocol (#PID<0.596.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.592.0> timed out because it queued and checked out the connection for longer than 20000ms\n\n#PID<0.592.0> was at location:\n\n    :prim_inet.recv0/3\n    (postgrex 0.15.7) lib/postgrex/protocol.ex:2838: Postgrex.Protocol.msg_recv/4\n    (postgrex 0.15.7) lib/postgrex/protocol.ex:1241: Postgrex.Protocol.recv_parse/3\n    (postgrex 0.15.7) lib/postgrex/protocol.ex:1208: Postgrex.Protocol.recv_parse_describe/4\n    (postgrex 0.15.7) lib/postgrex/protocol.ex:1028: Postgrex.Protocol.parse_describe_flush/3\n    (db_connection 2.3.1) lib/db_connection/holder.ex:316: DBConnection.Holder.holder_apply/4\n    (db_connection 2.3.1) lib/db_connection.ex:1257: DBConnection.prepare/4\n    (db_connection 2.3.1) lib/db_connection.ex:1250: DBConnection.run_prepare/4\n    (db_connection 2.3.1) lib/db_connection.ex:1262: DBConnection.run_prepare_execute/5\n    (db_connection 2.3.1) lib/db_connection.ex:1359: DBConnection.run/6\n    (db_connection 2.3.1) lib/db_connection.ex:557: DBConnection.parsed_prepare_execute/5\n    (db_connection 2.3.1) lib/db_connection.ex:550: DBConnection.prepare_execute/4\n    (postgrex 0.15.7) lib/postgrex.ex:235: Postgrex.query_prepare_execute/4\n    (postgrex 0.15.7) lib/postgrex.ex:247: Postgrex.query!/4\n    (stdlib 3.14) erl_eval.erl:680: :erl_eval.do_apply/6\n    (elixir 1.11.3) src/elixir.erl:280: :elixir.recur_eval/3\n    (elixir 1.11.3) src/elixir.erl:265: :elixir.eval_forms/3\n    (iex 1.11.3) lib/iex/evaluator.ex:261: IEx.Evaluator.handle_eval/5\n    (iex 1.11.3) lib/iex/evaluator.ex:242: IEx.Evaluator.do_eval/3\n    (iex 1.11.3) lib/iex/evaluator.ex:220: IEx.Evaluator.eval/3\n","level":"error","datetime":"2021-02-24T17:16:11.000088Z","function":"disconnect/2","file":"lib/db_connection/connection.ex"}
iex(2)>

PGPool Logs:

2021-02-24 17:15:51: pid 166: LOG:  DB node id: 0 backend pid: 9337 statement: Parse: SELECT 1;
2021-02-24 17:15:51: pid 166: LOG:  DB node id: 0 backend pid: 9337 statement: D message
2021-02-24 17:16:11: pid 166: ERROR:  unable to read data from frontend
2021-02-24 17:16:11: pid 166: DETAIL:  EOF encountered with frontend

Ecto Config:

config :app, App.Repo,
  URL: databaseUrl,
  show_sensitive_data_on_connection_error: true,
  pool_size: 20,
  timeout: 60_000

My suspect is on the incompatibility DB Connection module with PSQL protocol, Should be noted I tried psql 11 and 13 versions, all had same issue.

did you experience same issue?

7 comments

#ecto #postgres #postgrex #db_connection #pgpool

0 3898 7

2021-02-25 17:31:24 UTC

Showing Posts 1 to 7

Show Best Posts
Show All (oldest first)
Show All (newest first)

minhajuddin

I would try connecting to pgpool from your server using psql. That should root out any issues because of IPs and what not.

Post #1

mcrunix

@minhajuddin psql works well with pgpool

Post #2

minhajuddin

The next thing I would try would be to look at the logs on the pgpool side of things and see why it is closing the Postgrex connections. If that doesn’t work spin up Wireshark and look at the TCP stream and see who is sending the FIN packet (it’s most probably pgpool), if you know that pgpool is closing the connection you’ll have to figure out why it is doing that

Post #3

mcrunix

Hmm. interesting, the last matched record(blue one) has FIN packet, and it’s from PGPool side. Could be related to pool mode(sessions, transactional, statements)?

Post #4

minhajuddin

It looks like your elixir process initiated the FIN, packet 1066. Try connecting directly to the postgres database first and see if you can recreate it. Try using a library from another language e.g. pg gem from ruby to rule out any misconfigurations.

Post #5

mcrunix

I tried to test pgpool instance with ruby and node.js both worked and returned the desired result.

Post #6

mcrunix

I’d like to put few other references which might be related.

Quote from Medium:

The migration was smooth, and the pgbouncer is the mandatory layer for the large scale Elixir deployment to handle the connections in a better way. We tried pgpool as well(to leverage the features like caching and the read/write split), but seems there is no official support from Elixir for pgpool. It gave some issues in our tests. So we went live with pgbouncer.

Post #7

— All posts loaded —