psql connection timeout issues

All we need is an easy explanation of the problem, so here it is.

I am trying to establish a (logical) replica of a database on a remote site. Therefore we established a permanent VPN connection to that site where we are running two machines. One is an Ubuntu 18.10 box we use for maintenance and client operations. The other one is a Debian 9.11 which is actually running the replica Postgres 11.5 DB Host.

I wasn’t able to connect the master node via the SUBSCRIPTION, therefore I tried to connect via psql from the replica node to my master node. I get asked to type in the password and then the connection timesout after about a minute.

When I try to connect from our maintenance box everything works fine. We double checked Firewall rules of the tunnel, pg_hba.coonf and deactivated all local firwalls, without success. Hosts are pingable and ports are open and listening.

I don’t have any further ideas what else could cause the client to not connect to a postgres server instance.

The database is postgres 10.7, the client is 11.5.

What else could cause a client connection timeout like this?

EDIT: the exact error message on the client side is

psql: could not connect to server: Connection refused Is the server
running on host "" and accepting TCP/IP connections on port 5432?

On the serverside the log contains nothing.

The server is configured to listen on ‘*’ and accept connections as host from 0.0.0.0/0 md5 on all databases from all users. As said, the connection from another box on the remote site is working.

The working client is psql (PostgreSQL) 10.9 (Ubuntu 10.9-0ubuntu0.18.10.1)

The non-working client is psql (PostgreSQL) 11.5 (Debian 11.5-3.pgdg90+1)

EDIT2: I reconfigured log verbosity of our postgres db server to DEBUG5…this is what I get

2020-06-18 11:32:14.310 CEST [4860] DEBUG:  find_in_dynamic_libpath: trying "C:/Program Files/PostgreSQL/11/lib/pg_stat_statements"
2020-06-18 11:32:14.310 CEST [4860] DEBUG:  find_in_dynamic_libpath: trying "C:/Program Files/PostgreSQL/11/lib/pg_stat_statements.dll"
2020-06-18 11:32:14.310 CEST [4860] DEBUG:  loaded library "pg_stat_statements"
2020-06-18 11:32:14.310 CEST [4860] LOG:  connection received: host=192.168.110.124 port=47246
2020-06-18 11:32:14.321 CEST [4860] DEBUG:  postgres child[4860]: starting with (
2020-06-18 11:32:14.321 CEST [4860] DEBUG:      postgres
2020-06-18 11:32:14.321 CEST [4860] DEBUG:  )
2020-06-18 11:32:14.321 CEST [4860] DEBUG:  InitPostgres
2020-06-18 11:32:14.321 CEST [4860] DEBUG:  my backend ID is 3
2020-06-18 11:32:14.322 CEST [4860] DEBUG:  mapped win32 error code 2 to 2
2020-06-18 11:32:14.322 CEST [4860] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2020-06-18 11:32:14.334 CEST [4860] DEBUG:  shmem_exit(0): 1 before_shmem_exit callbacks to make
2020-06-18 11:32:14.334 CEST [4860] DEBUG:  shmem_exit(0): 6 on_shmem_exit callbacks to make
2020-06-18 11:32:14.334 CEST [4860] DEBUG:  proc_exit(0): 3 callbacks to make
2020-06-18 11:32:14.334 CEST [4860] DEBUG:  exit(0)
2020-06-18 11:32:14.334 CEST [4860] DEBUG:  shmem_exit(-1): 0 before_shmem_exit callbacks to make
2020-06-18 11:32:14.334 CEST [4860] DEBUG:  shmem_exit(-1): 0 on_shmem_exit callbacks to make
2020-06-18 11:32:14.334 CEST [4860] DEBUG:  proc_exit(-1): 0 callbacks to make
2020-06-18 11:32:14.337 CEST [3892] DEBUG:  reaping dead processes
2020-06-18 11:32:14.337 CEST [3892] DEBUG:  server process (PID 4860) exited with exit code 0

A working connection from the same subnet (other machine) looks like this in the logs

2020-06-18 11:41:16.373 CEST [3892] DEBUG:  forked new backend, pid=576 socket=4932
2020-06-18 11:41:16.392 CEST [576] DEBUG:  find_in_dynamic_libpath: trying "C:/Program Files/PostgreSQL/11/lib/pg_stat_statements"
2020-06-18 11:41:16.392 CEST [576] DEBUG:  find_in_dynamic_libpath: trying "C:/Program Files/PostgreSQL/11/lib/pg_stat_statements.dll"
2020-06-18 11:41:16.392 CEST [576] DEBUG:  loaded library "pg_stat_statements"
2020-06-18 11:41:16.392 CEST [576] LOG:  connection received: host=192.168.110.111 port=44920
2020-06-18 11:41:16.403 CEST [576] DEBUG:  postgres child[576]: starting with (
2020-06-18 11:41:16.403 CEST [576] DEBUG:   postgres
2020-06-18 11:41:16.403 CEST [576] DEBUG:  )
2020-06-18 11:41:16.403 CEST [576] DEBUG:  InitPostgres
2020-06-18 11:41:16.403 CEST [576] DEBUG:  my backend ID is 5
2020-06-18 11:41:16.403 CEST [576] DEBUG:  StartTransaction(1) name: unnamed; blockState: DEFAULT; state: INPROGRESS, xid/subid/cid: 0/1/0
2020-06-18 11:41:16.415 CEST [576] DEBUG:  received password packet
2020-06-18 11:41:16.415 CEST [576] LOG:  connection authorized: user=swwat database=swwat
2020-06-18 11:41:16.417 CEST [576] DEBUG:  CommitTransaction(1) name: unnamed; blockState: STARTED; state: INPROGRESS, xid/subid/cid: 0/1/0

How to solve :

I know you bored from this bug, So we are here to help you! Take a deep breath and look at the explanation of your problem. We have many solutions to this problem, But we recommend you to use the first method because it is tested & true method that will 100% work for you.

Method 1

That is a networking problem. The message and the lack of server log entries prove that you didn’t reach the database server.

You’ll have to use standard network debugging techniques to solve this problem.

Method 2

Finally solved it!

Our IPS (Ubiqity Firewall) identified this particular connection as a threat and disconnected it every time. Why it identified one client as a threat and not also the other one too, we don’t actually know.

Accepting Laurenz Answer as his first intention was oviously right.

Note: Use and implement method 1 because this method fully tested our system.
Thank you 🙂

All methods was sourced from stackoverflow.com or stackexchange.com, is licensed under cc by-sa 2.5, cc by-sa 3.0 and cc by-sa 4.0

Leave a Reply