Subject: Puzzling situation with threads and psycopg2 on RDS

From: Stefan Knecht <[email-masked]>
Date: Mon, 17 Oct 2022 18:25:14 +0700

Hello

I have this situation now, that I can't wrap my head around and I'm hoping
someone can shed some light onto what is going on, before I spend hours
trying to reproduce this by taking the code apart into a test case.

A few facts:

- I've got a piece of code split into several classes.
- It initializes a dynamic number of threads. For the sake of this topic,
I'll stick to just 2 threads to illustrate.
- Each thread creates its own database connection (psycopg2.connect()) when
it's started
- Each thread, for each task it does, prints out its own name and the PID
of the database session.

Running the code, I see this:

Threadcount 2
Starting thread Thread-1
Starting thread Thread-2
Thread-1 CONNECT
Thread-2 CONNECT
Thread-2 Run plan <<'Create basic order'>>
  Thread-2 Processing query block <'Query block 1'>
    Thread-2 File 'select_random_product.sql'
Thread-1 Run plan <<'Create basic order'>>
  Thread-1 Processing query block <'Query block 1'>
    Thread-1 File 'select_random_product.sql'
    Thread-2 PID 31909
    Thread-2 PID 31908
    Thread-2 File 'select_random_customer.sql'
    Thread-2 PID 31908
    Thread-2 File 'create_simple_order.sql'
    Thread-1 File 'select_random_customer.sql'
    Thread-2 PID 31908
    Thread-2 File 'modify_simple_order.sql'
    Thread-2 PID 31908
    Thread-1 File 'create_simple_order.sql'
    Thread-2 PID 31908
    Thread-2 PID 31908
    Thread-1 File 'modify_simple_order.sql'
    Thread-2 PID 31908
All threads exited.

In the database log, with full logging enabled, I see this:

2022-10-17 10:59:03 UTC:10.0.1.17(36350):[unknown]@[unknown]:[31908]:LOG:
 connection received: host=10.0.1.17 port=36350
2022-10-17 10:59:03 UTC:10.0.1.17(36356):[unknown]@[unknown]:[31909]:LOG:
 connection received: host=10.0.1.17 port=36356
2022-10-17 10:59:03 UTC:10.0.1.17(36356):postgres@postgres:[31909]:LOG:
 connection authorized: user=postgres database=postgres SSL enabled
(protocol=TLSv1.2, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256,
compression=off)
2022-10-17 10:59:03 UTC:10.0.1.17(36350):postgres@postgres:[31908]:LOG:
 connection authorized: user=postgres database=postgres SSL enabled
(protocol=TLSv1.2, cipher=ECDHE-RSA-AES256-GCM-SHA384, bits=256,
compression=off)
2022-10-17 10:59:03 UTC:10.0.1.17(36356):postgres@postgres:[31909]:LOG:
 execute <unnamed>: BEGIN
2022-10-17 10:59:03 UTC:10.0.1.17(36350):postgres@postgres:[31908]:LOG:
 execute <unnamed>: BEGIN
2022-10-17 10:59:03 UTC:10.0.1.17(36350):postgres@postgres:[31908]:LOG:
 duration: 0.065 ms
2022-10-17 10:59:03 UTC:10.0.1.17(36356):postgres@postgres:[31909]:LOG:
 statement: select pg_backend_pid();
2022-10-17 10:59:03 UTC:10.0.1.17(36356):postgres@postgres:[31909]:LOG:
 duration: 0.246 ms
2022-10-17 10:59:03 UTC:10.0.1.17(36350):postgres@postgres:[31908]:LOG:
 statement: select pg_backend_pid();
2022-10-17 10:59:03 UTC:10.0.1.17(36350):postgres@postgres:[31908]:LOG:
 duration: 0.237 ms
2022-10-17 10:59:03 UTC:10.0.1.17(36356):postgres@postgres:[31909]:LOG:
 disconnection: session time: 0:00:00.021 user=postgres database=postgres
host=10.0.1.17 port=36356
2022-10-17 10:59:03 UTC:10.0.1.17(36350):postgres@postgres:[31908]:LOG:
 statement: .... many more entries from 31908

Perhaps you can already see the problem. One thread randomly disconnects.

We can see this in several places.

1) In the script's output, we can see that Thread-2 first reports PID 31909
and then switches to 31908. 31909 goes silent.

and 2) The database log shows the same thing:

- 2 sessions connect
- 2 sessions get established
- shortly after, one disconnects, and the other keeps connected and
executes the entire workload of both threads. In order.

If I start with 3 threads, I see basically the same thing. Two will
disconnect right after connecting, and the remaining one will then run all
3 tasks.

Any ideas why this is happening?

Thank you!

---

From: Daniele Varrazzo <[email-masked]>
Date: Mon, 17 Oct 2022 12:55:53 +0100

Hi Stefan,

On Mon, 17 Oct 2022 at 12:25, Stefan Knecht <[email-masked]> wrote:
>
> Hello
>
> I have this situation now, that I can't wrap my head around and I'm hoping someone can shed some light onto what is going on, before I spend hours trying to reproduce this by taking the code apart into a test case.
>
> A few facts:
>
> - It initializes a dynamic number of threads. For the sake of this topic, I'll stick to just 2 threads to illustrate.
> - Each thread creates its own database connection (psycopg2.connect()) when it's started
> - Each thread, for each task it does, prints out its own name and the PID of the database session.
...

> Perhaps you can already see the problem. One thread randomly disconnects.

I understand this happens on RDS. Does it happen on normal Postgres
too, from a normal process (not some serverless thing?)

Are there processes/forks involved? Which version of psycopg are you
using? Some old one have problems with closing connections in
multiprocess environments. That was fixed in psycopg 2.8 (#829).

Cheers

-- Daniele

---

From: Stefan Knecht <[email-masked]>
Date: Mon, 17 Oct 2022 19:08:27 +0700

Ciao Daniele

Thanks for looking at this.

> too, from a normal process (not some serverless thing?)
I'll test this now.

> Are there processes/forks involved?

No, just Python's basic threading.

> Which version of psycopg are you
This is psycopg 3.1.3

And I just realized that all the other threading code I've got is on
psycopg2-binary 2.8. Has there something changed with threads in v3 ?

Stefan

---

From: Stefan Knecht <[email-masked]>
Date: Mon, 17 Oct 2022 19:13:37 +0700

Exact same behavior with psycopg2-binary 2.9.4.

---

From: Stefan Knecht <[email-masked]>
Date: Mon, 17 Oct 2022 19:35:10 +0700

Ah, the error was (of course) between the keyboard and the chair.

A database handle was defined on the thread class - not the instance. And
for some reason everything was still working, just with very unexpected
behavior :)

Have a good one Daniele

---

From: Daniele Varrazzo <[email-masked]>
Date: Mon, 17 Oct 2022 13:36:45 +0100

On Mon, 17 Oct 2022 at 13:08, Stefan Knecht <[email-masked]> wrote:

> And I just realized that all the other threading code I've got is on psycopg2-binary 2.8. Has there something changed with threads in v3 ?

Ok, you mentioned psycopg2 in the title, so I thought about that past
issue we found. Psycopg 3 shouldn't have a massively different
behaviour (and is tested for issue #829).

-- Daniele