Timeouts issued by client are not waiting for query to actually be canceled

[Zarathustra2]

Elixir version

1.18.7-otp-27

Database and Version

17.2

Postgrex Version

master branch

Current behavior

Hi,

I think there is a possible bug in the way that the cancels of queries are being handeled
that can result in exceeding the connection pools in a high fashion and creating additional
load on Postgresql.

1. Run a query where canceling the query takes long
2. Query times out on the client (Ecto/Postgrex) with whatever timeout the user has set
3. Postgrex intializes a cancel but never awaits/confirms the query has been canceled
4. The slot in the pool gets returned and a new connection can be opened
5. On postgres on the other hand the connection is not closed/still active because the query has not been canceled yet
6. Now whatever limit we have set as POOL limit will exceed because we are allowing opening new connections
   when the old connection has not been terminated.
7. This is not good because in the worst case if a malicious actor identifies this you can create a huge load on Postgresql and bypassing the POOL limits.

I am having a hard time to reproduce this behaviour with a test case but I think this test case reproduces it.
I am creating a partitioned table and I am forcing parallel execution so that canceling will
require to cancel all parallel workers which should increase the time until the query gets canceled.

  test "partitioned table query cancellation", context do
    conn = context[:pid]
    %Postgrex.Result{connection_id: connection_id} = Postgrex.query!(conn, "SELECT 1", [])

    :ok = query("SET max_parallel_workers_per_gather = 8;", [])
    :ok = query("SET parallel_setup_cost = 0;", [])
    :ok = query("SET parallel_tuple_cost = 0;", [])


    Postgrex.query!(
      conn,
      """
        CREATE TABLE IF NOT EXISTS test_partitioned (
          id SERIAL,
          varchar_col VARCHAR(50),
          int_col INTEGER,
          time_col TIMESTAMPTZ
        ) PARTITION BY RANGE (time_col)
      """,
      []
    )

    base_time = ~U[2023-01-01 00:00:00Z]

    partitions_range = 0..350

    IO.inspect("creating partitions")

    for i <- partitions_range do
      start_time = DateTime.add(base_time, i * 86400, :second)
      end_time = DateTime.add(base_time, (i + 1) * 86400, :second)

      Postgrex.query!(
        conn,
        """
          CREATE TABLE IF NOT EXISTS test_partitioned_#{i} PARTITION OF test_partitioned
          FOR VALUES FROM ('#{start_time}') TO ('#{end_time}')
        """,
        []
      )
    end

    IO.inspect("inserting into partitions")

    for i <- partitions_range do
      partition_time = DateTime.add(base_time, i * 86400 + 3600, :second)

      values =
        for j <- 1..20000 do
          "('varchar_#{rem(j, 100)}', #{j}, '#{DateTime.to_iso8601(partition_time)}')"
        end
        |> Enum.join(", ")

      Postgrex.query!(
        conn,
        """
          INSERT INTO test_partitioned (varchar_col, int_col, time_col)
          VALUES #{values}
        """,
        []
      )
    end

    Process.flag(:trap_exit, true)

    IO.inspect("running query then cancel")

    result =
      capture_log(fn ->
        case query(
               """
                 SELECT * FROM test_partitioned ORDER BY RANDOM() * int_col, varchar_col
               """,
               [],
               timeout: 2_000
             ) do
          %Postgrex.Error{postgres: %{message: "canceling statement due to user request"}} ->
            :ok

          %DBConnection.ConnectionError{message: "tcp recv: closed" <> _} ->
            :ok

          other ->
            IO.inspect("unexpected result: #{inspect(other)}")
            :ok
        end

        # assert_receive {:EXIT, ^conn, :killed}
      end)

    assert result =~ "disconnected: ** (DBConnection.ConnectionError)"

    {:ok, new_conn} = Postgrex.start_link(context[:options])

    assert %Postgrex.Result{rows: []} =
             Postgrex.query!(
               new_conn,
               "SELECT * from pg_stat_activity where state = 'active' and pid = $1",
               [connection_id]
             )
  end

I hope my explanations are clear, if there are any questions please let me know.

Expected behavior

Properly wait/force the cancel of active queries before giving the connection slot back to the pool for new connections/queries.

[josevalim]

I understand why you would want this feature but it comes with the side-effect that you can now have an empty pool because you started too many slow queries which, have been cancelled, but you are waiting for them anyway. Therefore, I believe we could add this, but it needs to be implemented behind a flag. A pull request is welcome!

[Zarathustra2]

I can possibly take a look. Do you happen to have an idea from the top of your head where to put that logic? Would that go into the the disconnect method in protocol.ex?

[josevalim]

That’s where I would look, yeah. Once you cancel, instead of immediately disconnecting, you want until you either receive something else or your submit a ping immediately and wait to get a pong back.

[josevalim]

Now that I think about it, I am not sure your change would necessarily improve things. The root cause here is that there are some expensive queries which allegedly can be started by a malicious actor. In the current approach, we end up putting more load in the database, which will eventually run out of connections (PG has a limit) or become too busy, causing other queries to potentially fail. If you adopt your solution, then the pool will become busy (because we wait for them to finish anyway), and then further requests will fail anyway since they won't have any connection to check out. Both lead to resource exhaustion, just to different types of resources, because the root cause is an unbounded expensive computation somewhere.

[Zarathustra2]

When setting a pool size I am expecting not to exceed this pool size because that is what I limited the application to. I have seen other clients not having this behavior. Some even have a max pool size but will lazily open connections up to the pool size based on if they need additional connections.

If the behavior gets changes so that an ecto pool cannot exceed its pool size we improve things by isolating the issue and not possibly impact other applications. Say you have multiple applications interacting/connecting to the database and your DB has a connection limit of 20.

With current behavior you are allowing one application to exceed its set pool size (say 10) and grow its connection count (assuming you have a bad query) uncontrollably. Once you hit 20 you are now locking other applications out and cascading the issues to other applications that now cannot connect to the DB anymore.

If you treat the pool size variable as a hard max upper bound and wait for the cancel/termination to finish then your application will not exceed its connection limit and thus not impacting other application's ability to connect to the DB (obviously you are still impacting other applications given you are running a bad query but this is a different issue). And now the issue is just isolated to the one bad application and that application cannot prevent others to connect.

If you have a bad query like the one in my test example where you are querying a partition and have parallel execution the cancelation can take a bit of time. If that is not being awaited and immediately retried then you can easily get up to 3x your original pool size of connections because the cancel/termination is not being awaited. (There are obviously solutions do this, you can limit the connection limits per user in PG to prevent this but I feel like especially for people that might not be aware of this situation and expecting pool size as the total fixed connection count the current behavior would be unwanted/unexpected and changing it would be safer as you are limiting the issue to the bad application)

[josevalim]

Thanks for expanding! So let's go ahead indeed and explore adding an option for this (and we may consider changing the default value in the future).

[Zarathustra2]

First time working/reading on postgresql protocl but https://www.postgresql.org/docs/current/protocol-flow.html#PROTOCOL-FLOW-CANCELING-REQUESTS says

The upshot of all this is that for reasons of both security and efficiency, the frontend has no direct way to tell whether a cancel request has succeeded. It must continue to wait for the backend to respond to the query. Issuing a cancel simply improves the odds that the current query will finish soon, and improves the odds that it will fail with an error message instead of succeeding.

Makes me think we have to rework a lot more? Because as far as I can tell the current implementation will just disconnect on timeout and then issue cancel but it should rather on timeout send a cancel request and not terminate and wait for postgresql to send a response (either error as got canceled or the results as they came available when we sent the cancel).

Possible that requires tweaks in DbConnection as well?