OperationalError: sorry, too many clients already

Using Django Deployment
1

A few minutes ago I had a spike of this error in my Django application:

django.db.utils.OperationalError: connection to server at "name-of-the-db" (172.17.0.11), port 5432 failed: FATAL:  sorry, too many clients already

My Django app is deployed on dokku (for those who don’t know it but have experience with heroku, it’s pretty much the same thing) and connected to a postgres database. The connection is achieved using dj-datbase-url package and the setting looks like this:

DATABASES = {
    "default": {
        **dj_database_url.parse(
            os.environ.get("DATABASE_URL", False), conn_max_age=600
        ),
        "ATOMIC_REQUESTS": True,
    }
}

I use daphne in front of Django, and I’m running 3 processes with daphne.

What could have been causing this issue?

I have read that a possible solution is to drop the conn_max_age parameter or set it to a lower value, but I’m not sold on it and don’t completely understand how it works, so any guidance is welcome.

Also, I haven’t registered any abnormal traffic on my website, but I’m wondering: is this something that can happen “spontaneously”, maybe due to an incorrect setup, or could it be due to malicious activity?

The most likely explanation I can think of is there is some database connection leaks around my app, but I can’t figure out how to find them.

2

Check the max_connections setting in your database server configuration. See PostgreSQL: Documentation: 14: 20.3. Connections and Authentication

You can also look at the connections within PostgreSQL to see what processes are connected to the server and see if there are any hanging queries. (If you have something creating a long-running query that is abandoned by Django, the query will keep running - consuming a connection.)

3

It appears it was set to 100. I just set it to 350, and I also lowered the conn_max_age parameter of dj-database-url from 600 to 60, after the problem appeared again several times this morning.

I suspect the higher-than-normal amount of connections might be caused by the fact that I have 3 replicas of daphne (and therefore Django) running at the same time. Does this make sense or am I completely mistaken?

I took a look but I was only able to do so after restarting my postgres db, as I wasn’t able to connect to it via shell either due to the connection limit, so I wasn’t able to observe the phenomenon. Checking the active connections now yields about 30 rows, and it looks like this:

sai_evo_db=# SELECT * FROM pg_stat_activity;
 datid |  datname   | pid | usesysid | usename  | application_name | client_addr | client_hostname | client_port |         backend_start         |          xact_start          |          query_start          |         state_change          | wait_event_type |     wait_event      | state  | backend_xid | backend_xmin |                                                                                                                                                                                                                                                                                                                                                                       query                                                                                                                                                                                                                                                                                                                                                                        |         backend_type         
-------+------------+-----+----------+----------+------------------+-------------+-----------------+-------------+-------------------------------+------------------------------+-------------------------------+-------------------------------+-----------------+---------------------+--------+-------------+--------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------------------------
       |            | 106 |          |          |                  |             |                 |             | 2022-09-28 10:07:25.40325+00  |                              |                               |                               | Activity        | AutoVacuumMain      |        |             |              |                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    | autovacuum launcher
       |            | 108 |       10 | postgres |                  |             |                 |             | 2022-09-28 10:07:25.403645+00 |                              |                               |                               | Activity        | LogicalLauncherMain |        |             |              |                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    | logical replication launcher
 16384 | sai_evo_db | 565 |       10 | postgres |                  | 172.17.0.26 |                 |       38450 | 2022-09-28 10:18:02.886034+00 |                              | 2022-09-28 10:18:03.520524+00 | 2022-09-28 10:18:03.520831+00 | Client          | ClientRead          | idle   |             |              | SELECT "courses_eventparticipationslot"."id", "courses_eventparticipationslot"."participation_id", "courses_eventparticipationslot"."exercise_id", "courses_eventparticipationslot"."parent_id", "courses_eventparticipationslot"."populating_rule_id", "courses_eventparticipationslot"."slot_number", "courses_eventparticipationslot"."seen_at", "courses_eventparticipationslot"."answered_at", "courses_eventparticipationslot"."answer_text", "courses_eventparticipationslot"."attachment", "courses_eventparticipationslot"."execution_results", "courses_eventparticipationslot"."comment", "courses_eventparticipationslot"."_score" FROM "courses_eventparticipationslot" WHERE "courses_eventparticipationslot"."id" = 131115 LIMIT 21 | client backend
 16384 | sai_evo_db | 506 |       10 | postgres |                  | 172.17.0.26 |                 |       48502 | 2022-09-28 10:15:44.041482+00 |                              | 2022-09-28 10:15:44.251606+00 | 2022-09-28 10:15:44.263356+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             | client backend
 16384 | sai_evo_db | 503 |       10 | postgres |                  | 172.17.0.26 |                 |       58464 | 2022-09-28 10:15:05.912782+00 |                              | 2022-09-28 10:15:06.221518+00 | 2022-09-28 10:15:06.238329+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             | client backend
 16384 | sai_evo_db | 398 |       10 | postgres |                  | 172.17.0.24 |                 |       57452 | 2022-09-28 10:12:45.140442+00 |                              | 2022-09-28 10:12:45.591631+00 | 2022-09-28 10:12:45.606656+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             | client backend
 16384 | sai_evo_db | 568 |       10 | postgres |                  | 172.17.0.18 |                 |       58088 | 2022-09-28 10:18:03.04987+00  |                              | 2022-09-28 10:18:03.545809+00 | 2022-09-28 10:18:03.558378+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             | client backend
 16384 | sai_evo_db | 572 |       10 | postgres |                  | 172.17.0.26 |                 |       38480 | 2022-09-28 10:18:04.133405+00 |                              | 2022-09-28 10:18:04.367475+00 | 2022-09-28 10:18:04.381686+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             | client backend
 16384 | sai_evo_db | 517 |       10 | postgres |                  | 172.17.0.26 |                 |       34912 | 2022-09-28 10:16:53.011001+00 |                              | 2022-09-28 10:16:53.135427+00 | 2022-09-28 10:16:53.144409+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             | client backend
 16384 | sai_evo_db | 548 |       10 | postgres |                  | 172.17.0.26 |                 |       48282 | 2022-09-28 10:17:32.259567+00 |                              | 2022-09-28 10:17:32.334506+00 | 2022-09-28 10:17:32.350631+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             | client backend
 16384 | sai_evo_db | 545 |       10 | postgres |                  | 172.17.0.26 |                 |       35944 | 2022-09-28 10:17:30.561568+00 |                              | 2022-09-28 10:17:30.694493+00 | 2022-09-28 10:17:30.70505+00  | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             | client backend
 16384 | sai_evo_db | 447 |       10 | postgres |                  | 172.17.0.21 |                 |       34078 | 2022-09-28 10:14:08.861799+00 |                              | 2022-09-28 10:14:09.309714+00 | 2022-09-28 10:14:09.317616+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             | client backend
 16384 | sai_evo_db | 500 |       10 | postgres |                  | 172.17.0.26 |                 |       45942 | 2022-09-28 10:14:42.528709+00 |                              | 2022-09-28 10:14:42.725945+00 | 2022-09-28 10:14:42.725992+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             | client backend
 16384 | sai_evo_db | 512 |       10 | postgres |                  | 172.17.0.26 |                 |       58384 | 2022-09-28 10:16:18.91751+00  |                              | 2022-09-28 10:16:19.112526+00 | 2022-09-28 10:16:19.123802+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             | client backend
 16384 | sai_evo_db | 513 |       10 | postgres |                  | 172.17.0.26 |                 |       58386 | 2022-09-28 10:16:18.922063+00 |                              | 2022-09-28 10:16:18.992464+00 | 2022-09-28 10:16:18.99252+00  | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             | client backend
 16384 | sai_evo_db | 536 |       10 | postgres | psql             | 127.0.0.1   |                 |       52216 | 2022-09-28 10:17:10.281747+00 | 2022-09-28 10:19:17.23794+00 | 2022-09-28 10:19:17.23794+00  | 2022-09-28 10:19:17.237943+00 |                 |                     | active |             |       711367 | SELECT * FROM pg_stat_activity;                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    | client backend
 16384 | sai_evo_db | 551 |       10 | postgres |                  | 172.17.0.26 |                 |       48302 | 2022-09-28 10:17:39.192664+00 |                              | 2022-09-28 10:17:39.263851+00 | 2022-09-28 10:17:39.263893+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             | client backend
 16384 | sai_evo_db | 570 |       10 | postgres |                  | 172.17.0.26 |                 |       38468 | 2022-09-28 10:18:03.276124+00 |                              | 2022-09-28 10:18:03.625062+00 | 2022-09-28 10:18:03.63861+00  | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             | client backend
 16384 | sai_evo_db | 540 |       10 | postgres |                  | 172.17.0.26 |                 |       34622 | 2022-09-28 10:17:18.47889+00  |                              | 2022-09-28 10:17:19.066151+00 | 2022-09-28 10:17:19.078049+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             | client backend
 16384 | sai_evo_db | 556 |       10 | postgres |                  | 172.17.0.26 |                 |       40456 | 2022-09-28 10:17:52.211859+00 |                              | 2022-09-28 10:17:52.406077+00 | 2022-09-28 10:17:52.406191+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                             | client backend

Most of the connections are idle, and I assume that has to do with the conn_max_age paramter in dj-database-url.

Is there a reliable way to check for these types of connections? (Other than manually inspecting the code and guessing.)

4

If you’ll notice, you’ll see that the query being run for each connection is included in this view.

If you ever get into the connection-limit situation again, rerun this query. (Yes, this may mean that you need to leave a psql session running for a while to ensure you have an available connection.)

If most of the query column is blank, then your issue is (was) being caused by a too-high conn_max_age setting. If most of that column has data, then there are a lot of running queries.

Honestly, I’m not sure how Daphne manages database connections.

Are you asychronously issuing multiple queries for particular requests? Each one of those queries is going to need / use a separate connection.

Otherwise, I don’t think the three replicas themselves would cause the problem. (Although it may depend upon how many users each is servicing.)

5

I tried to recreate the situation in a staging environment by lowering the max number of connections to 50 and running some thousands fetch requests. This is the output:

evo_backend_stage_db=# SELECT * FROM pg_stat_activity;
 datid |       datname        | pid  | usesysid | usename  | application_name | client_addr | client_hostname | client_port |         backend_start         |          xact_start           |          query_start          |         state_change          | wait_event_type |     wait_event      | state  | backend_xid | backend_xmin |                                                                                                                                                                                                                                                                     query                                                                                                                                                                                                                                                                      |         backend_type         
-------+----------------------+------+----------+----------+------------------+-------------+-----------------+-------------+-------------------------------+-------------------------------+-------------------------------+-------------------------------+-----------------+---------------------+--------+-------------+--------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------------------------
       |                      |   31 |          |          |                  |             |                 |             | 2022-09-28 16:16:50.973258+00 |                               |                               |                               | Activity        | AutoVacuumMain      |        |             |              |                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                | autovacuum launcher
       |                      |   33 |       10 | postgres |                  |             |                 |             | 2022-09-28 16:16:50.973288+00 |                               |                               |                               | Activity        | LogicalLauncherMain |        |             |              |                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                | logical replication launcher
 16384 | evo_backend_stage_db | 5849 |       10 | postgres |                  | 172.17.0.31 |                 |       52324 | 2022-09-28 16:55:42.220812+00 |                               | 2022-09-28 16:55:42.361289+00 | 2022-09-28 16:55:42.361324+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         | client backend
 16384 | evo_backend_stage_db | 5850 |       10 | postgres |                  | 172.17.0.32 |                 |       51140 | 2022-09-28 16:55:42.386262+00 |                               | 2022-09-28 16:55:42.425814+00 | 2022-09-28 16:55:42.425842+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         | client backend
 16384 | evo_backend_stage_db | 5174 |       10 | postgres |                  | 172.17.0.43 |                 |       55084 | 2022-09-28 16:54:50.902415+00 |                               | 2022-09-28 16:54:50.970189+00 | 2022-09-28 16:54:50.970384+00 | Client          | ClientRead          | idle   |             |              | SELECT "silk_request"."id", "silk_request"."path", "silk_request"."query_params", "silk_request"."raw_body", "silk_request"."body", "silk_request"."method", "silk_request"."start_time", "silk_request"."view_name", "silk_request"."end_time", "silk_request"."time_taken", "silk_request"."encoded_headers", "silk_request"."meta_time", "silk_request"."meta_num_queries", "silk_request"."meta_time_spent_queries", "silk_request"."pyprofile", "silk_request"."prof_file", "silk_request"."num_sql_queries" FROM "silk_request" LIMIT 21 | client backend
 16384 | evo_backend_stage_db | 4632 |       10 | postgres |                  | 172.17.0.39 |                 |       58676 | 2022-09-28 16:54:43.388749+00 |                               | 2022-09-28 16:54:43.404283+00 | 2022-09-28 16:54:43.405533+00 | Client          | ClientRead          | idle   |             |              | SELECT "silk_request"."id", "silk_request"."path", "silk_request"."query_params", "silk_request"."raw_body", "silk_request"."body", "silk_request"."method", "silk_request"."start_time", "silk_request"."view_name", "silk_request"."end_time", "silk_request"."time_taken", "silk_request"."encoded_headers", "silk_request"."meta_time", "silk_request"."meta_num_queries", "silk_request"."meta_time_spent_queries", "silk_request"."pyprofile", "silk_request"."prof_file", "silk_request"."num_sql_queries" FROM "silk_request" LIMIT 21 | client backend
 16384 | evo_backend_stage_db | 3862 |       10 | postgres |                  | 172.17.0.33 |                 |       37462 | 2022-09-28 16:54:40.342609+00 |                               | 2022-09-28 16:54:41.341288+00 | 2022-09-28 16:54:41.341787+00 | Client          | ClientRead          | idle   |             |              | SELECT "silk_request"."id", "silk_request"."path", "silk_request"."query_params", "silk_request"."raw_body", "silk_request"."body", "silk_request"."method", "silk_request"."start_time", "silk_request"."view_name", "silk_request"."end_time", "silk_request"."time_taken", "silk_request"."encoded_headers", "silk_request"."meta_time", "silk_request"."meta_num_queries", "silk_request"."meta_time_spent_queries", "silk_request"."pyprofile", "silk_request"."prof_file", "silk_request"."num_sql_queries" FROM "silk_request" LIMIT 21 | client backend
 16384 | evo_backend_stage_db | 5321 |       10 | postgres |                  | 172.17.0.33 |                 |       50220 | 2022-09-28 16:55:30.403036+00 |                               | 2022-09-28 16:55:30.495692+00 | 2022-09-28 16:55:30.525328+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         | client backend
 16384 | evo_backend_stage_db | 4613 |       10 | postgres |                  | 172.17.0.39 |                 |       58638 | 2022-09-28 16:54:43.126092+00 |                               | 2022-09-28 16:54:43.171993+00 | 2022-09-28 16:54:43.172273+00 | Client          | ClientRead          | idle   |             |              | SELECT "silk_request"."id", "silk_request"."path", "silk_request"."query_params", "silk_request"."raw_body", "silk_request"."body", "silk_request"."method", "silk_request"."start_time", "silk_request"."view_name", "silk_request"."end_time", "silk_request"."time_taken", "silk_request"."encoded_headers", "silk_request"."meta_time", "silk_request"."meta_num_queries", "silk_request"."meta_time_spent_queries", "silk_request"."pyprofile", "silk_request"."prof_file", "silk_request"."num_sql_queries" FROM "silk_request" LIMIT 21 | client backend
 16384 | evo_backend_stage_db | 5899 |       10 | postgres |                  | 172.17.0.33 |                 |       42788 | 2022-09-28 16:55:44.245468+00 |                               | 2022-09-28 16:55:44.287278+00 | 2022-09-28 16:55:44.287489+00 | Client          | ClientRead          | idle   |             |              | SELECT "silk_request"."id", "silk_request"."path", "silk_request"."query_params", "silk_request"."raw_body", "silk_request"."body", "silk_request"."method", "silk_request"."start_time", "silk_request"."view_name", "silk_request"."end_time", "silk_request"."time_taken", "silk_request"."encoded_headers", "silk_request"."meta_time", "silk_request"."meta_num_queries", "silk_request"."meta_time_spent_queries", "silk_request"."pyprofile", "silk_request"."prof_file", "silk_request"."num_sql_queries" FROM "silk_request" LIMIT 21 | client backend
 16384 | evo_backend_stage_db | 5143 |       10 | postgres |                  | 172.17.0.40 |                 |       38612 | 2022-09-28 16:54:48.292862+00 |                               | 2022-09-28 16:54:48.333691+00 | 2022-09-28 16:54:48.333909+00 | Client          | ClientRead          | idle   |             |              | SELECT "silk_request"."id", "silk_request"."path", "silk_request"."query_params", "silk_request"."raw_body", "silk_request"."body", "silk_request"."method", "silk_request"."start_time", "silk_request"."view_name", "silk_request"."end_time", "silk_request"."time_taken", "silk_request"."encoded_headers", "silk_request"."meta_time", "silk_request"."meta_num_queries", "silk_request"."meta_time_spent_queries", "silk_request"."pyprofile", "silk_request"."prof_file", "silk_request"."num_sql_queries" FROM "silk_request" LIMIT 21 | client backend
 16384 | evo_backend_stage_db | 5421 |       10 | postgres |                  | 172.17.0.33 |                 |       39560 | 2022-09-28 16:55:33.636056+00 |                               | 2022-09-28 16:55:33.651791+00 | 2022-09-28 16:55:33.652021+00 | Client          | ClientRead          | idle   |             |              | SELECT "silk_request"."id", "silk_request"."path", "silk_request"."query_params", "silk_request"."raw_body", "silk_request"."body", "silk_request"."method", "silk_request"."start_time", "silk_request"."view_name", "silk_request"."end_time", "silk_request"."time_taken", "silk_request"."encoded_headers", "silk_request"."meta_time", "silk_request"."meta_num_queries", "silk_request"."meta_time_spent_queries", "silk_request"."pyprofile", "silk_request"."prof_file", "silk_request"."num_sql_queries" FROM "silk_request" LIMIT 21 | client backend
 16384 | evo_backend_stage_db |  959 |       10 | postgres | psql             | 127.0.0.1   |                 |       42780 | 2022-09-28 16:54:20.696987+00 | 2022-09-28 16:56:09.140191+00 | 2022-09-28 16:56:09.140191+00 | 2022-09-28 16:56:09.140193+00 |                 |                     | active |             |         6343 | SELECT * FROM pg_stat_activity;                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                | client backend
 16384 | evo_backend_stage_db | 5882 |       10 | postgres |                  | 172.17.0.39 |                 |       53730 | 2022-09-28 16:55:44.04418+00  |                               | 2022-09-28 16:55:44.084618+00 | 2022-09-28 16:55:44.084827+00 | Client          | ClientRead          | idle   |             |              | SELECT "silk_request"."id", "silk_request"."path", "silk_request"."query_params", "silk_request"."raw_body", "silk_request"."body", "silk_request"."method", "silk_request"."start_time", "silk_request"."view_name", "silk_request"."end_time", "silk_request"."time_taken", "silk_request"."encoded_headers", "silk_request"."meta_time", "silk_request"."meta_num_queries", "silk_request"."meta_time_spent_queries", "silk_request"."pyprofile", "silk_request"."prof_file", "silk_request"."num_sql_queries" FROM "silk_request" LIMIT 21 | client backend
 16384 | evo_backend_stage_db | 5862 |       10 | postgres |                  | 172.17.0.41 |                 |       59244 | 2022-09-28 16:55:43.421437+00 |                               | 2022-09-28 16:55:43.460567+00 | 2022-09-28 16:55:43.460593+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         | client backend
 16384 | evo_backend_stage_db | 5854 |       10 | postgres |                  | 172.17.0.41 |                 |       59198 | 2022-09-28 16:55:42.728621+00 |                               | 2022-09-28 16:55:42.769025+00 | 2022-09-28 16:55:42.769055+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         | client backend
 16384 | evo_backend_stage_db | 5855 |       10 | postgres |                  | 172.17.0.42 |                 |       40852 | 2022-09-28 16:55:42.788393+00 |                               | 2022-09-28 16:55:42.827239+00 | 2022-09-28 16:55:42.827269+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         | client backend
 16384 | evo_backend_stage_db | 5870 |       10 | postgres |                  | 172.17.0.43 |                 |       50398 | 2022-09-28 16:55:43.693828+00 |                               | 2022-09-28 16:55:43.734868+00 | 2022-09-28 16:55:43.735076+00 | Client          | ClientRead          | idle   |             |              | SELECT "silk_request"."id", "silk_request"."path", "silk_request"."query_params", "silk_request"."raw_body", "silk_request"."body", "silk_request"."method", "silk_request"."start_time", "silk_request"."view_name", "silk_request"."end_time", "silk_request"."time_taken", "silk_request"."encoded_headers", "silk_request"."meta_time", "silk_request"."meta_num_queries", "silk_request"."meta_time_spent_queries", "silk_request"."pyprofile", "silk_request"."prof_file", "silk_request"."num_sql_queries" FROM "silk_request" LIMIT 21 | client backend
 16384 | evo_backend_stage_db | 3277 |       10 | postgres |                  | 172.17.0.43 |                 |       37960 | 2022-09-28 16:54:38.192371+00 |                               | 2022-09-28 16:54:42.891526+00 | 2022-09-28 16:54:42.892027+00 | Client          | ClientRead          | idle   |             |              | SELECT "silk_request"."id", "silk_request"."path", "silk_request"."query_params", "silk_request"."raw_body", "silk_request"."body", "silk_request"."method", "silk_request"."start_time", "silk_request"."view_name", "silk_request"."end_time", "silk_request"."time_taken", "silk_request"."encoded_headers", "silk_request"."meta_time", "silk_request"."meta_num_queries", "silk_request"."meta_time_spent_queries", "silk_request"."pyprofile", "silk_request"."prof_file", "silk_request"."num_sql_queries" FROM "silk_request" LIMIT 21 | client backend
 16384 | evo_backend_stage_db | 5610 |       10 | postgres |                  | 172.17.0.33 |                 |       40060 | 2022-09-28 16:55:38.092832+00 |                               | 2022-09-28 16:55:38.132689+00 | 2022-09-28 16:55:38.132716+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         | client backend
 16384 | evo_backend_stage_db | 5254 |       10 | postgres |                  | 172.17.0.40 |                 |       34362 | 2022-09-28 16:55:02.927281+00 |                               | 2022-09-28 16:55:03.015546+00 | 2022-09-28 16:55:03.096955+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         | client backend
 16384 | evo_backend_stage_db | 3317 |       10 | postgres |                  | 172.17.0.43 |                 |       38064 | 2022-09-28 16:54:38.493288+00 |                               | 2022-09-28 16:54:43.058393+00 | 2022-09-28 16:54:43.058682+00 | Client          | ClientRead          | idle   |             |              | SELECT "silk_request"."id", "silk_request"."path", "silk_request"."query_params", "silk_request"."raw_body", "silk_request"."body", "silk_request"."method", "silk_request"."start_time", "silk_request"."view_name", "silk_request"."end_time", "silk_request"."time_taken", "silk_request"."encoded_headers", "silk_request"."meta_time", "silk_request"."meta_num_queries", "silk_request"."meta_time_spent_queries", "silk_request"."pyprofile", "silk_request"."prof_file", "silk_request"."num_sql_queries" FROM "silk_request" LIMIT 21 | client backend
 16384 | evo_backend_stage_db | 5158 |       10 | postgres |                  | 172.17.0.39 |                 |       59794 | 2022-09-28 16:54:49.791823+00 |                               | 2022-09-28 16:54:49.833412+00 | 2022-09-28 16:54:49.833443+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         | client backend
 16384 | evo_backend_stage_db | 5159 |       10 | postgres |                  | 172.17.0.40 |                 |       38676 | 2022-09-28 16:54:49.852948+00 |                               | 2022-09-28 16:54:49.895564+00 | 2022-09-28 16:54:49.895601+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         | client backend
 16384 | evo_backend_stage_db | 5260 |       10 | postgres |                  | 172.17.0.33 |                 |       50066 | 2022-09-28 16:55:28.533591+00 |                               | 2022-09-28 16:55:28.572451+00 | 2022-09-28 16:55:28.572477+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         | client backend
 16384 | evo_backend_stage_db | 5900 |       10 | postgres |                  | 172.17.0.40 |                 |       57990 | 2022-09-28 16:55:44.245876+00 |                               | 2022-09-28 16:55:44.29003+00  | 2022-09-28 16:55:44.290243+00 | Client          | ClientRead          | idle   |             |              | SELECT "silk_request"."id", "silk_request"."path", "silk_request"."query_params", "silk_request"."raw_body", "silk_request"."body", "silk_request"."method", "silk_request"."start_time", "silk_request"."view_name", "silk_request"."end_time", "silk_request"."time_taken", "silk_request"."encoded_headers", "silk_request"."meta_time", "silk_request"."meta_num_queries", "silk_request"."meta_time_spent_queries", "silk_request"."pyprofile", "silk_request"."prof_file", "silk_request"."num_sql_queries" FROM "silk_request" LIMIT 21 | client backend
 16384 | evo_backend_stage_db | 3296 |       10 | postgres |                  | 172.17.0.39 |                 |       42216 | 2022-09-28 16:54:38.290139+00 |                               | 2022-09-28 16:54:42.99205+00  | 2022-09-28 16:54:42.992354+00 | Client          | ClientRead          | idle   |             |              | SELECT "silk_request"."id", "silk_request"."path", "silk_request"."query_params", "silk_request"."raw_body", "silk_request"."body", "silk_request"."method", "silk_request"."start_time", "silk_request"."view_name", "silk_request"."end_time", "silk_request"."time_taken", "silk_request"."encoded_headers", "silk_request"."meta_time", "silk_request"."meta_num_queries", "silk_request"."meta_time_spent_queries", "silk_request"."pyprofile", "silk_request"."prof_file", "silk_request"."num_sql_queries" FROM "silk_request" LIMIT 21 | client backend
 16384 | evo_backend_stage_db | 5372 |       10 | postgres |                  | 172.17.0.41 |                 |       52200 | 2022-09-28 16:55:31.776005+00 |                               | 2022-09-28 16:55:31.825371+00 | 2022-09-28 16:55:31.825624+00 | Client          | ClientRead          | idle   |             |              | SELECT "silk_request"."id", "silk_request"."path", "silk_request"."query_params", "silk_request"."raw_body", "silk_request"."body", "silk_request"."method", "silk_request"."start_time", "silk_request"."view_name", "silk_request"."end_time", "silk_request"."time_taken", "silk_request"."encoded_headers", "silk_request"."meta_time", "silk_request"."meta_num_queries", "silk_request"."meta_time_spent_queries", "silk_request"."pyprofile", "silk_request"."prof_file", "silk_request"."num_sql_queries" FROM "silk_request" LIMIT 21 | client backend
 16384 | evo_backend_stage_db | 5904 |       10 | postgres |                  | 172.17.0.31 |                 |       52684 | 2022-09-28 16:55:46.141645+00 |                               | 2022-09-28 16:55:46.206784+00 | 2022-09-28 16:55:46.206994+00 | Client          | ClientRead          | idle   |             |              | SELECT "silk_request"."id", "silk_request"."path", "silk_request"."query_params", "silk_request"."raw_body", "silk_request"."body", "silk_request"."method", "silk_request"."start_time", "silk_request"."view_name", "silk_request"."end_time", "silk_request"."time_taken", "silk_request"."encoded_headers", "silk_request"."meta_time", "silk_request"."meta_num_queries", "silk_request"."meta_time_spent_queries", "silk_request"."pyprofile", "silk_request"."prof_file", "silk_request"."num_sql_queries" FROM "silk_request" LIMIT 21 | client backend
 16384 | evo_backend_stage_db | 3860 |       10 | postgres |                  | 172.17.0.33 |                 |       37456 | 2022-09-28 16:54:40.340493+00 |                               | 2022-09-28 16:54:40.434745+00 | 2022-09-28 16:54:40.435903+00 | Client          | ClientRead          | idle   |             |              | SELECT "silk_request"."id", "silk_request"."path", "silk_request"."query_params", "silk_request"."raw_body", "silk_request"."body", "silk_request"."method", "silk_request"."start_time", "silk_request"."view_name", "silk_request"."end_time", "silk_request"."time_taken", "silk_request"."encoded_headers", "silk_request"."meta_time", "silk_request"."meta_num_queries", "silk_request"."meta_time_spent_queries", "silk_request"."pyprofile", "silk_request"."prof_file", "silk_request"."num_sql_queries" FROM "silk_request" LIMIT 21 | client backend
 16384 | evo_backend_stage_db | 5180 |       10 | postgres |                  | 172.17.0.40 |                 |       45558 | 2022-09-28 16:54:51.434526+00 |                               | 2022-09-28 16:54:51.473901+00 | 2022-09-28 16:54:51.473931+00 | Client          | ClientRead          | idle   |             |              | COMMIT                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         | client backend
...

It appears as though silk may be the culprit. I only turned it on in production a few days ago to profile a query that I had a hard time reproducing in development, and boom, this error appeared.

1 Like
6

Unfortunately, it appears the problem was not silk. This error appeared over and over again for a few days, until I installed django-postgrespool2 · PyPI

Now connections should be cached via the pooling engine. Unfortunately, after working as intended for a few days, the problem presented itself again. This time, the app keeps working normally because of the existing connection pool, but sometimes it still tries to open new connections. This fails because, for some reason, postgres reports having more than 350 connections already.

This is the output of SELECT * FROM pg_stat_activity;

I’m having a hard time understanding where those connections come from.

These are the two possible options in my opinion:

  1. even if using django-postgrespool2, the different instances of daphne aren’t sharing the pool and somehow create different pools
  2. there is something else in my application creating connections outside of the pool (e.g. celery)

I really have no clue what’s going on, so any guidance is very welcome.

7

So I see just a handful of ip addresses as creating the connections - all in the 172.17.0 subnet → .16, .27, .29 (more than 110 for each) and a handful from .4 and .24.

I’m going to guess that the big three (.16, .27, .29) are your Daphne instances and either (or both) .4 and .24 are your celery instance.

It’s tough for me to say what to look at next - this is one of those issues where you may just end up needing to look at everything along the line. I don’t know enough about your application or your deployment architecture to offer any substantial advice.

For example - you could look at those individual systems to find out what process is using a specific port. The first entry shows a connection from .16 on port 49630. You could see if that port was currently active on the client side, and what process has it open.

You mentioned earlier that you’ve set the CONN_MAX_AGE parameter to 60, which means that Django should be trying to close connections if it grabs one to use that is older than that age - however, you’re showing connections covering a range of more than 30 minutes here. This means that something isn’t “releasing” the connections properly. See the General Notes in the databases docs for more information about how this parameter is supposed to work.

You might want to enhance your PostgreSQL logging to see if connections are actually getting closed. (See log_connections and log_disconnections at PostgreSQL: Documentation: 14: 20.8. Error Reporting and Logging)

If the tcp ports aren’t currently allocated to a running process, then for some reason PostgreSQL isn’t “seeing” that the connection went away - you may want to look at the tcp keepalives settings on that server and the idle_session_timeout settings.

You might also want to try setting your CONN_MAX_AGE to 0 just to verify that connections can be closed and released and that you don’t have something in your application causing these to be held.

(I know these types of issues are aggravating and tough to diagnose - but sometimes all you can do it start pulling threads to see where they lead you.)

8

So, I tried running the query and immediately picking some PID’s and ports to see if there were any active processes running with those PID’s and ports, but I wasn’t able to detect any process. So it almost appears as if the process is killed and by the time I can look at the output on postgres it doesn’t exist anymore?

I tried setting CONN_MAX_AGE to 0 on my staging environment (which has the same exact setup as my prod env, except that I’m running 5 replicas of daphne and 1 of celery). After doing some requests to my application, postgres shows I have 6 connections + the “bookkeeping” ones unrelated to Django.

Those connections stay there and don’t get closed. So this seems to mean connections aren’t getting closed, but on the other side I think that having connections kept open is the point of pooling: I tested this with django-postgrespool2 as my db engine. I haven’t yet tried by using plain postgres, but this finding already tells me there’s something wrong: I tested this on a staging environment and I was the only user, refreshing the page on my frontend to do some requests. Why open 6 connections?

If all daphne workers shared the same pool, they’d probably be able to always pick that same one connection opened initially, without having to resort to open a new one, wouldn’t they?

9

If I’m understanding you correctly, 5 instances of daphne and 1 celery = 6 connections.

The connection pooling you are using is per-process, not per-system. There’s not some “external to the process” pool through which connections are being shared - so that’s the minimum number of connections I would expect to see.

You would need to use pgpool (or some other) “system-wide” pool facility to share connections between processes.

10

Yeah, now I understand I was making a wrong assumption: each worker has its own db connection pool, unlike what I was assuming, that is, all processes would use a single pool, so in order to prevent my db connection limit from being exceeded, I need to use pool settings in Django so that num_workers * (pool_size + max_pool_overflow) < db connection limit. Is my understanding correct at this point?

This raises one question though: what’s the difference between using a per-process pool and simply using the CONN_MAX_AGE setting on a normal connection? If the point is to re-use connections, even if the mechanism is slightly different, isn’t the effect roughly the same?

Do you think I would be better off using pgpool than sticking with django-postgrespool2 with settings that don’t exceed the db connection limit?

The latter seems less complex, but I am afraid that if the individual pools are too small, I would end up getting some other error, this time related to the pull being overflown.

11

You are correct.

I don’t know enough about Django’s management of connections to answer that.

I think you would be better off using a CONN_MAX_AGE = 0 with pgpool-II than django-postgrespool2. But if the root issue is that some aspect of the application isn’t allowing connections to be released and closed, you may only be delaying the issue.

12

That’s what worries me the most. I have no clue what could possibly be causing this. Unless there’s some bug with Django, which is highly unlikely I’d say, I have no idea what could be wrong with my code.

Mind you, according to Sentry this issue first appeared in my app a few days after I first scaled my web workers from 1, which had always been the case up to that point, to 3. So I can’t say if this happened because of some quiescent issue in my application that simply never got a chance to show up, or if that proves that the cause is related to having multiple instances of daphne.

Assuming there’s something wrong with my app, where would you start looking if you were me?
I only use “normal” ORM methods, no hand-written queries, nothing too crazy honestly.

The only thing I can think of is the fact that I have ATOMIC_REQUESTS set to true, but again, that couldn’t possibly be the sole cause.

GitHub - Evo-Learning-project/sai_evo_backend this is my application for additional context.

13

You’ve got some third-party dependencies that cloud the issue. Between sentry and djangochannelsrestframework, there’s too much outside your control to be sure about anything.

At this stage, my only recommendation would be to do whatever you need to do to track where connections are being opened and where they’re closed. This may mean either changing your database configuration to enhance logging or to provide your own database backend to log connections. (What you’re really looking for is the event or code in the application layer that’s causing the connection to be opened. This means you’ll need to log the complete call stack to see where this is happening.)

14

Something I’m considering is fork django-postgrespool2 and adding logging to the function that tries to get a usable connection from the pool or create a new one. I’m actually also considering tracking this issue somewhere else:

this is the stacktrace of an exception thrown due to overflow of the pool: it’s not quite the same error we’ve been discussing, but the cause should pretty much the same—requesting a db connection when none can be opened

Screenshot 2022-10-06 at 09.03.07
Screenshot 2022-10-06 at 09.03.071394×1676 123 KB

looking at the stack trace, there appears to be a function in particular that’s used by django as an entry point into getting a db connection:

Screenshot 2022-10-06 at 09.02.47
Screenshot 2022-10-06 at 09.02.471776×1058 82.2 KB

do you think it would be wise to add a debug log here? For example, I could use the inspect package to log the whole call stack.

Do you think this could be a good approach? I’m kinda worried about how to achieve this: the only way I know would be to fork django, release it in pip, and install that onto my application.

However, seen as this should be db engine independent, and only related to how my application works and interacts with any database, in principle I could test this in local, therefore manually editing the file from django on my machine. Would that be sensible in your opinion, or just wasted time?

15

(I apologize for answering questions here out-of-order - hopefully the reason for my doing so becomes clear.)

Actually, I think that’s a great idea.

Yep, that’s the right place.

If you’re working local as you suggest - yes, that’s probably the easiest thing to do.

You might also want to find the location where connections are closed to see if you can find where in your app that’s supposed to be happening as well. (No firm suggestion here, just an idea for more “information gathering.”)

(I see where psycopg2 allows for a “LoggingConnection”, but my quick attempts at trying to figure out how to use this in Django hasn’t worked, so I can’t recommend it yet.)

16

Apparently, per what I wrote in this thread, connections are closed in a close method (that I linked in the thread) if CONN_AGE_MAX is 0, but are closed “somewhere else” otherwise. I posted a report of what I observed so far in that thread. Do you have an idea where the connections opened with a CONN_MAX_AGE value greater than 0 might be being closed at?

17

So, continuing my investigation, here’s something I did:

  • I scaled the daphne workers down to just 1
  • I removed django-postgrespool2 ad my db engine
  • I set ATOMIC_REQUESTS to False
  • I kept CONN_MAX_AGE at 60

the third one is important; I was suspecting that might have had something to do with my issue.

Here’s the thing: by scaling down to one worker, I would for sure have expected to see less db connections, but with a similar pattern: increasing in number pretty much consistently with time, and hanging in idle after being completed.

Instead, what I found was that the number of connections varied wildly even in the span of a few minutes.

Here’s the output of the SELECT * FROM pg_stat_activity; command at three different points in time just a few minutes apart: gist:e5a627a897f0d51371c1520cb913cc39 · GitHub

It appears connections are correctly pruned now. Could the culprit be ATOMIC_REQUESTS?

I thought the best thing to do for robustness would’ve been to wrap all requests inside of a transaction; for the time being, I decorated with transaction.atomic() only the views in which multiple objects are created or updated together; that’ll probably suffice.

Now I guess I need to work up the courage to scale up daphne again and see what happens without the atomic requests.

1 Like
18

After a couple of weeks of no issues, today the problem resumed occurring.
I’m starting to get pretty desperate as this just made me lose all the confidence in the fact that I thought I had found the issue and a solution to it.

For reference, this is what the connections to postgres looked like at two different points in time today. In both instances, the problem had already occurred and was not in the middle of occurring:
gist:f7d27b63f1e394223f5a036eea867820 · GitHub

I had 2 daphne workers and 2 celery workers, no atomic requests except for a few viewset methods decorated with transaction.atomic().

I think the next step will be to temporarily disable my djangochannelsrestframework entry points and see what happens. Ideally, I would remove channels altogether but that would affect the functionality of my application way too much for me to afford.

The very next step will be to install pgbouncer and turn conn_max_age to 0.

I’m definitely hating this issue.

19

After a day of having removed all usages of channels (I decided to try this), I am once again faced with this problem.

A sample output from pg_stat: gist:def8ccb850a08cdaac7080b63a4b7680 · GitHub

The most common query seems to look like this:

SELECT 
"courses_usercourseprivilege"."id",
"courses_usercourseprivilege"."user_id",
"courses_usercourseprivilege"."course_id",
"courses_usercourseprivilege"."allow_privileges",
"courses_usercourseprivilege"."deny_privileges" 
FROM "courses_usercourseprivilege"
 WHERE ("courses_usercourseprivilege"."course_id" = 27 AND "courses_usercourseprivilege"."user_id" = 990)
LIMIT 21

I believe it could come from here: sai_evo_backend/view_mixins.py at master · Evo-Learning-project/sai_evo_backend · GitHub

class RequestingUserPrivilegesMixin:
    @cached_property
    def user_privileges(self):
        return get_user_privileges(
            self.request.user,
            self.kwargs["course_pk"],
        )

Could the fact that I’m making a query inside of a cached property have anything to do with this? I saw that cached_property uses a thread lock; maybe it has something to do with the issue, I honeslty don’t know what to think…

20

So you’re still having this with conn_max_age = 0 and pgbouncer?