FATAL: sorry, too many clients already when deleting lots of repos via the web UI

[MoralCode]

In trying to clear out some repos from my instance using the web UI so i could get to testing another PR, I remembered how #3347 was recently fixed and used that method to issue the deletes (i.e. login -> my profile -> my repos -> click a repo group -> click the delete button in the table that shows up)

After doing this for several dozen repos in a large organization that was added, I started to get this error:

  File "/augur/.venv/lib/python3.11/site-packages/flask/app.py", line 2073, in wsgi_app
    response = self.full_dispatch_request()
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/flask/app.py", line 1518, in full_dispatch_request
    rv = self.handle_user_exception(e)
         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/flask_cors/extension.py", line 178, in wrapped_function
    return cors_after_request(app.make_response(f(*args, **kwargs)))
                                                ^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/flask/app.py", line 1516, in full_dispatch_request
    rv = self.dispatch_request()
         ^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/flask/app.py", line 1502, in dispatch_request
    return self.ensure_sync(self.view_functions[rule.endpoint])(**req.view_args)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/flask_login/utils.py", line 272, in decorated_view
    return func(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^
  File "/augur/augur/api/view/routes.py", line 315, in user_group_view
    page_count = current_user.get_group_repo_count(group, search = query)[0] or 0
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/augur/application/db/models/augur_operations.py", line 571, in get_group_repo_count
    result = controller.get_repo_count(source="group", group_name=group_name, user=self, search=search)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/augur/util/repo_load_controller.py", line 193, in get_repo_count
    query, result = self.generate_repo_query(source, count=True, **kwargs)
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/augur/util/repo_load_controller.py", line 249, in generate_repo_query
    group_id = UserGroup.convert_group_name_to_id(self.session, user.user_id, group_name)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/augur/application/db/models/augur_operations.py", line 734, in convert_group_name_to_id
    user_group = session.query(UserGroup).filter(UserGroup.user_id == user_id, UserGroup.name == group_name).one()
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/orm/query.py", line 2798, in one
    return self._iter().one()  # type: ignore
           ^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/orm/query.py", line 2847, in _iter
    result: Union[ScalarResult[_T], Result[_T]] = self.session.execute(
                                                  ^^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 2306, in execute
    return self._execute_internal(
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 2178, in _execute_internal
    conn = self._connection_for_bind(bind)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 2045, in _connection_for_bind
    return trans._connection_for_bind(engine, execution_options)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "<string>", line 2, in _connection_for_bind
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/orm/state_changes.py", line 139, in _go
    ret_value = fn(self, *arg, **kw)
                ^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 1143, in _connection_for_bind
    conn = bind.connect()
           ^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 3268, in connect
    return self._connection_cls(self)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 147, in __init__
    Connection._handle_dbapi_exception_noconnection(
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 2430, in _handle_dbapi_exception_noconnection
    raise sqlalchemy_exception.with_traceback(exc_info[2]) from e
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 145, in __init__
    self._dbapi_connection = engine.raw_connection()
                             ^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 3292, in raw_connection
    return self.pool.connect()
           ^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 452, in connect
    return _ConnectionFairy._checkout(self)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 1269, in _checkout
    fairy = _ConnectionRecord.checkout(pool)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 716, in checkout
    rec = pool._do_get()
          ^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/pool/impl.py", line 169, in _do_get
    with util.safe_reraise():
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/util/langhelpers.py", line 146, in __exit__
    raise exc_value.with_traceback(exc_tb)
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/pool/impl.py", line 167, in _do_get
    return self._create_connection()
           ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 393, in _create_connection
    return _ConnectionRecord(self)
           ^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 678, in __init__
    self.__connect()
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 902, in __connect
    with util.safe_reraise():
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/util/langhelpers.py", line 146, in __exit__
    raise exc_value.with_traceback(exc_tb)
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/pool/base.py", line 898, in __connect
    self.dbapi_connection = connection = pool._invoke_creator(self)
                                         ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/engine/create.py", line 637, in connect
    return dialect.connect(*cargs, **cparams)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/sqlalchemy/engine/default.py", line 616, in connect
    return self.loaded_dbapi.connect(*cargs, **cparams)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/augur/.venv/lib/python3.11/site-packages/psycopg2/__init__.py", line 122, in connect
    conn = _connect(dsn, connection_factory=connection_factory, **kwasync)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

OperationalError: (psycopg2.OperationalError) connection to server at "augur-db" (10.89.0.4), port 5432 failed: FATAL:  sorry, too many clients already

(Background on this error at: https://sqlalche.me/e/20/e3q8)

This strongly indicates that this delete operation is creating a new connection each time and is not closing them properly, eventually leading to postgres hitting a connection limit.

[sgoggins]

@MoralCode : Seems like the frontend is not using our connection pooling. How many connections does your postgresql instance allow? That's a curiosity, because I have mine set pretty high, but I also have not tried to use the UI to delete repos.

[MoralCode]

I don't believe the augur repo provides any postgres configs, so I think its just using the default config you would get with a fresh postgres startup (therefore this potentially affects both install methods of augur). IIRC that default has a limit of 100.

The stack trace has a lot of files in a sqlalchemy/pool directory within sqlalchemy, so it feels to me like this may be less of a "not using the pooling" (especially since i think the frontend routes are one of the more recently-cleaned up parts of augur thanks to @Ulincsys). It seems more like the frontend may be taking connections from the pool and not giving them back/not properly closing them.

[shlokgilda]

I think I found it. When we delete repos through the UI, I think this is what happens:

1. Delete repo redirects to user_group_view()
2. That view calls current_user.get_group_repo_count() at line 315 to render the page
3. With rapid deletions, this gets called repeatedly in quick succession

The problem is in User.get_group_repo_count() at line 565 in augur/application/db/models/augur_operations.py. The session is being closed before it's actually used:

def get_group_repo_count(self, group_name, search = None):
    from augur.util.repo_load_controller import RepoLoadController

    with DatabaseSession(logger) as session:
        controller = RepoLoadController(session)
    # session closes here

    result = controller.get_repo_count(source="group", group_name=group_name, user=self, search=search)
    # but we try to use it here

    return result

When the context manager exits after creating the controller, the session is already closed. So when controller.get_repo_count() tries to execute the query, SQLAlchemy has to create a new connection. With rapid deletions, these connections pile up and hit postgres's connection limit.

I think the fix is just moving that line inside the context manager (I didn't declare a new controller but rewrote it how other functions in the same file perform the operation).

  def get_group_repo_count(self, group_name, search = None):
      from augur.util.repo_load_controller import RepoLoadController

      with DatabaseSession(logger) as session:
          result = RepoLoadController(session).get_repo_count(source="group", group_name=group_name, user=self, search=search)

      return result

This matches what other similar methods like get_group_repos() and get_user_repo_count() already do correctly.

[MoralCode]

oh wow, that seems like a fairly thorough analysis and potentially a very simple PR!