Apparently hung connection

Question

Apparently hung connection

Closed this issue 7 months ago · 7 comments

I've been working through an issue where we sometimes, generally on the first request to the database lock up at the level of exec_params. These hang indefinitely (tens of hours) and the ruby backtrace stops where the clib begins and I'm trying to ascertain how the code is supposed to timeout but I cannot figure it out. It looks like we end up in an infinite loop here which calls wait_socket_readable without a timeout.

It looks like the code is then reliant on libpq to return a timeout. However, at the very least, connect_timeout does not apply here and from my testing tcp_user_timeout does not seem to correct this behavior. I'd expect that after some time the connection should timeout if I've configured timeouts so for it to not is a little concerning.

System in use:
Server is postgres 15
We currently use a pgbouncer cluster to proxy requests to postgres
The query that we block on is not in a transaction.
connect_timeout: 15
tcp_user_timeout: 100k
idle_timeout: 0 (however, the connection is checked out of the pool at the time)
checkout_timeout: 60

Answer 1 · 2023-03-21T14:49:08.000Z

Did you try out the libpq keepalive settings? https://www.postgresql.org/docs/15/libpq-connect.html#LIBPQ-KEEPALIVES

Answer 2 · 2023-03-21T14:56:52.000Z

We rely on the system settings which are the following:

$ sysctl net.ipv4 | grep keepalive
net.ipv4.tcp_keepalive_intvl = 60
net.ipv4.tcp_keepalive_probes = 5
net.ipv4.tcp_keepalive_time = 300

My understanding is that this should result in a disconnect after ~10 minutes but that's not happening. The tcp_user_timeout should limit this to 100 seconds, but that's also not happening.

Answer 3 · 2023-03-28T12:49:17.000Z

Related to this, I am experiencing the gem not discovering a dead connection despite the use of keepalives parameters.

Reproduction using version 1.4.6 and Ruby 2.7:

Click to unfold

$ docker run --rm -it debian:bullseye-slim bash
root@2a1ffed1753a:/# apt update
[...]
root@2a1ffed1753a:/# apt install -y --no-install-recommends postgresql ruby-dev bundler postgresql-server-dev-all gcc
[...]
root@2a1ffed1753a:/# service postgresql start
Starting PostgreSQL 13 database server: main.
root@2a1ffed1753a:/# su - postgres
postgres@2a1ffed1753a:~$ psql -c "CREATE USER myuser WITH SUPERUSER PASSWORD 'mypassword';"
CREATE ROLE
postgres@2a1ffed1753a:~$ psql -c "CREATE DATABASE mydb;"
CREATE DATABASE
postgres@2a1ffed1753a:~$ exit
logout
root@2a1ffed1753a:/# gem install pg
[...]
root@2a1ffed1753a:/# gem list | grep pg
pg (1.4.6)
root@2a1ffed1753a:/# irb -r pg
irb(main):001:0> c = PG.connect('postgres://myuser:mypassword@127.0.0.1/mydb')
=> #<PG::Connection:0x000055b82dc48048 host=127.0.0.1 port=5432 user=myuser>
irb(main):002:0> c.status
=> 0

# Exec into the Docker container and restart the PostgreSQL service.

$ docker exec -it name_of_container bash
root@2a1ffed1753a:/# service postgresql restart
Restarting PostgreSQL 13 database server: main.

# Go back to the IRB.

irb(main):003:0> c.status
=> 0
irb(main):004:0> c.exec('SELECT 1') { |result| puts result.to_a }; nil
Traceback (most recent call last):
        5: from /usr/bin/irb:23:in `<main>'
        4: from /usr/bin/irb:23:in `load'
        3: from /usr/lib/ruby/gems/2.7.0/gems/irb-1.2.6/exe/irb:11:in `<top (required)>'
        2: from (irb):4
        1: from (irb):4:in `exec'
PG::ConnectionBad (PQconsumeInput() server closed the connection unexpectedly)
	This probably means the server terminated abnormally
	before or while processing the request.
irb(main):005:0> c.status
=> 1

# Let's try with TCP keepalive.

root@2a1ffed1753a:/# irb -r pg
irb(main):001:0> c = PG.connect('postgres://myuser:mypassword@127.0.0.1/mydb?keepalives=1&keepalives_idle=2&keepalives_interval=2&keepalives_count=2')
=> #<PG::Connection:0x00005600bc0474d8 host=127.0.0.1 port=5432 user=myuser>
irb(main):002:0> c.status
=> 0
irb(main):003:0> c.exec('SELECT 1') { |result| puts result.to_a }; nil
{"?column?"=>"1"}
=> nil

# Restart of PostgreSQL service.

root@2a1ffed1753a:/# service postgresql restart
Restarting PostgreSQL 13 database server: main.

# Back to IRB. Wait 20 seconds before moving on.

irb(main):004:0> sleep 20
=> 20
irb(main):005:0> c.status
=> 0
irb(main):006:0> c.exec('SELECT 1') { |result| puts result.to_a }; nil
Traceback (most recent call last):
        5: from /usr/bin/irb:23:in `<main>'
        4: from /usr/bin/irb:23:in `load'
        3: from /usr/lib/ruby/gems/2.7.0/gems/irb-1.2.6/exe/irb:11:in `<top (required)>'
        2: from (irb):6
        1: from (irb):6:in `exec'
PG::ConnectionBad (PQconsumeInput() SSL connection has been closed unexpectedly)
irb(main):007:0> c.status
=> 1

# As far as I can tell, the keepalives parameters are picked up:

root@2a1ffed1753a:/# irb -r pg -r pry
irb(main):001:0> c = PG.connect('postgres://myuser:mypassword@127.0.0.1/mydb?keepalives=1&keepalives_idle=2&keepalives_interval=2&keepalives_count=2')

From: /var/lib/gems/2.7.0/gems/pg-1.4.6/lib/pg/connection.rb:756 PG::Connection.connect_to_hosts:

    751: 					host: dests.map{|d| d[1] }.join(","),
    752: 					port: dests.map{|d| d[2] }.join(","))
    753: 			else
    754: 				# No host given
    755: 			end
 => 756: 			require 'pry'; binding.pry
    757: 			conn = self.connect_start(iopts) or
    758: 										raise(PG::Error, "Unable to create a new connection")
    759:
    760: 			raise PG::ConnectionBad, conn.error_message if conn.status == PG::CONNECTION_BAD
    761:

[1] pry(PG::Connection)> iopts
=> {:authtype=>"",
 :user=>"myuser",
 :channel_binding=>"prefer",
 :port=>"5432",
 :tty=>"",
 :options=>"",
 :sslmode=>"prefer",
 :sslcompression=>"0",
 :ssl_min_protocol_version=>"TLSv1.2",
 :gssencmode=>"prefer",
 :krbsrvname=>"postgres",
 :target_session_attrs=>"any",
 :password=>"mypassword",
 :dbname=>"mydb",
 :host=>"127.0.0.1",
 :fallback_application_name=>"irb",
 :keepalives=>"1",
 :keepalives_idle=>"2",
 :keepalives_interval=>"2",
 :keepalives_count=>"2",
 :hostaddr=>"127.0.0.1"}

TCP keepalive is definitely turned on:

Click to unfold

root@2a1ffed1753a:/# irb -r pg
irb(main):001:0> c = PG.connect('postgres://myuser:mypassword@127.0.0.1/mydb?keepalives=1&keepalives_idle=2&keepalives_interval=2&keepalives_count=2')
=> #<PG::Connection:0x000055755bb23ec0 host=127.0.0.1 port=5432 user=myuser>
irb(main):002:0> c.close
=> nil

root@2a1ffed1753a:/# tcpdump -ni lo port 5432
tcpdump: verbose output suppressed, use -v[v]... for full protocol decode
listening on lo, link-type EN10MB (Ethernet), snapshot length 262144 bytes
12:47:09.177244 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [S], seq 3160257045, win 65495, options [mss 65495,sackOK,TS val 908920482 ecr 0,nop,wscale 7], length 0
12:47:09.177252 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [S.], seq 2127331598, ack 3160257046, win 65483, options [mss 65495,sackOK,TS val 908920482 ecr 908920482,nop,wscale 7], length 0
12:47:09.177260 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [.], ack 1, win 512, options [nop,nop,TS val 908920482 ecr 908920482], length 0
12:47:09.177554 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [P.], seq 1:9, ack 1, win 512, options [nop,nop,TS val 908920483 ecr 908920482], length 8
12:47:09.177557 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [.], ack 9, win 512, options [nop,nop,TS val 908920483 ecr 908920483], length 0
12:47:09.177983 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [P.], seq 1:2, ack 9, win 512, options [nop,nop,TS val 908920483 ecr 908920483], length 1
12:47:09.177987 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [.], ack 2, win 512, options [nop,nop,TS val 908920483 ecr 908920483], length 0
12:47:09.178878 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [P.], seq 9:292, ack 2, win 512, options [nop,nop,TS val 908920484 ecr 908920483], length 283
12:47:09.179020 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [P.], seq 2:101, ack 292, win 512, options [nop,nop,TS val 908920484 ecr 908920484], length 99
12:47:09.179157 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [P.], seq 292:614, ack 101, win 512, options [nop,nop,TS val 908920484 ecr 908920484], length 322
12:47:09.180205 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [P.], seq 101:1426, ack 614, win 512, options [nop,nop,TS val 908920485 ecr 908920484], length 1325
12:47:09.180513 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [P.], seq 614:688, ack 1426, win 512, options [nop,nop,TS val 908920486 ecr 908920485], length 74
12:47:09.180552 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [P.], seq 688:766, ack 1426, win 512, options [nop,nop,TS val 908920486 ecr 908920485], length 78
12:47:09.180580 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [P.], seq 1426:1505, ack 766, win 511, options [nop,nop,TS val 908920486 ecr 908920486], length 79
12:47:09.180589 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [P.], seq 1505:1584, ack 766, win 511, options [nop,nop,TS val 908920486 ecr 908920486], length 79
12:47:09.180598 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [.], ack 1584, win 512, options [nop,nop,TS val 908920486 ecr 908920486], length 0
12:47:09.181267 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [P.], seq 1584:1619, ack 766, win 512, options [nop,nop,TS val 908920486 ecr 908920486], length 35
12:47:09.181464 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [P.], seq 766:829, ack 1619, win 512, options [nop,nop,TS val 908920486 ecr 908920486], length 63
12:47:09.182866 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [P.], seq 1619:1987, ack 829, win 512, options [nop,nop,TS val 908920488 ecr 908920486], length 368
12:47:09.225105 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [.], ack 1987, win 512, options [nop,nop,TS val 908920530 ecr 908920488], length 0
12:47:11.189111 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [.], ack 1987, win 512, options [nop,nop,TS val 908922494 ecr 908920488], length 0
12:47:11.189125 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [.], ack 829, win 512, options [nop,nop,TS val 908922494 ecr 908920530], length 0
12:47:13.205108 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [.], ack 1987, win 512, options [nop,nop,TS val 908924510 ecr 908922494], length 0
12:47:13.205122 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [.], ack 829, win 512, options [nop,nop,TS val 908924510 ecr 908920530], length 0
12:47:15.221094 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [.], ack 1987, win 512, options [nop,nop,TS val 908926526 ecr 908924510], length 0
12:47:15.221107 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [.], ack 829, win 512, options [nop,nop,TS val 908926526 ecr 908920530], length 0
12:47:17.241137 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [.], ack 1987, win 512, options [nop,nop,TS val 908928546 ecr 908926526], length 0
12:47:17.241152 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [.], ack 829, win 512, options [nop,nop,TS val 908928546 ecr 908920530], length 0
12:47:19.253133 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [.], ack 1987, win 512, options [nop,nop,TS val 908930558 ecr 908928546], length 0
12:47:19.253150 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [.], ack 829, win 512, options [nop,nop,TS val 908930558 ecr 908920530], length 0
12:47:21.269101 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [.], ack 1987, win 512, options [nop,nop,TS val 908932574 ecr 908930558], length 0
12:47:21.269118 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [.], ack 829, win 512, options [nop,nop,TS val 908932574 ecr 908920530], length 0
12:47:23.285096 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [.], ack 1987, win 512, options [nop,nop,TS val 908934590 ecr 908932574], length 0
12:47:23.285113 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [.], ack 829, win 512, options [nop,nop,TS val 908934590 ecr 908920530], length 0
12:47:25.301102 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [.], ack 1987, win 512, options [nop,nop,TS val 908936606 ecr 908934590], length 0
12:47:25.301120 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [.], ack 829, win 512, options [nop,nop,TS val 908936606 ecr 908920530], length 0
12:47:27.067389 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [P.], seq 829:856, ack 1987, win 512, options [nop,nop,TS val 908938372 ecr 908936606], length 27
12:47:27.067403 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [P.], seq 856:880, ack 1987, win 512, options [nop,nop,TS val 908938372 ecr 908936606], length 24
12:47:27.067446 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [F.], seq 880, ack 1987, win 512, options [nop,nop,TS val 908938372 ecr 908936606], length 0
12:47:27.067470 IP 127.0.0.1.5432 > 127.0.0.1.52366: Flags [P.], seq 1987:2011, ack 881, win 512, options [nop,nop,TS val 908938373 ecr 908938372], length 24
12:47:27.067488 IP 127.0.0.1.52366 > 127.0.0.1.5432: Flags [R], seq 3160257926, win 0, length 0

Am I doing something wrong or is there perhaps a bug here?

Thanks 🙇

Answer 4 · 2023-03-28T18:16:36.000Z

OK, that makes sense. The PG::Connection#status is just returning the status from memory. It doesn't do any socket access. It just returns the status from the last command and is not suitable to test the connectivity.

The socket can be read out and checked with PG::Connection#consume_input. It reads a server message at each call and processes the message and stores the result in memory. At the first call in the example above it successfully reads the server closed the connection unexpectedly message from the socket until EOF. At the second call the connection is then already closed and everything is read out, so that it raises PG::ConnectionBad then. There might be more messages to be read until EOF, so consume_input should be called in a loop like so:

while c.socket_io.wait_readable(0)
  c.consume_input
end

I wonder if there should be a PG::Connection#connection_status that checks for TCP connection errors and not just the connection state from memory. Windows has somewhat different closing semantics, which this method could take care in addition.

Answer 5 · 2023-04-06T11:40:37.000Z

I opened #521 as a reaction to the issue described by @mt-clearhaus . Even if it's about only 3 lines of code, I think it's valueable to have some better documentation about what the different methods do.

Unfortunately it doesn't solve the original issue described by @choubacha . I don't use connection proxies, but I know from past issues, that connection proxies (like pgbouncer) can have their own issues and bugs, but sometimes just trigger a situation that doesn't happen with a direct connection. I don't have a good idea about how I or you can reproduce it, so that it can be investigated. But a reproduction would probably be necessary to do more in this regard.

Answer 6 · 2024-03-04T17:44:37.000Z

Has the issue been solved? If so, I'd like to close it.

Answer 7 · 2024-03-05T07:56:11.000Z

At my workplace we ended up working around the by having a separate thread do

while true do
  begin
    DB.select(1).all
  rescue => e
    DB.loggers.first.error("Unable to query trxdb: #{e.message.strip}")
  end
  sleep rand(20..30)
end

in order to provoke reconnect when necessary. We use Unicorn so each Unicorn worker process has such thread. The devil in the detail is that Unicorn only uses the "first" worker for all requests, unless simultaneous requests arrive. So a worker that is rarely used might sit around with a broken connection for hours, days, etc., until it finally receives a request and then sadly fails due to the broken connection. We are avoiding that using the above snippet.

In other words, do not keep this issue open for us.