"sqlalchemy.exc.TimeoutError: QueuePool limit of size 5 overflow 50 reached, connection timed out, timeout 30.00" error raised after repeated calls of Flavor.get_* methods

[melanie witt]

This bug was reported downstream by a user who is using some automation to query nova API for periodically for flavor information and occasionally they receive a HTTP 500 error from nova API with a message related to database connection pools.

The error:

  sqlalchemy.exc.TimeoutError: QueuePool limit of size 5 overflow 50 reached, connection timed out, timeout 30.00 (Background on this error at: https://sqlalche.me/e/14/3o7r)

is being raised in nova-api, causing a 500 error to be returned.

I think this is happening because of the placement of the @api_db_api.context_manager.reader decorator (which manages the database session) on a helper method instead of on the methods that actually execute the database queries. I think it's resulting in connections not being closed and eventually reaching the database connection pool size limits.

The database context manager decorator needs to be on the methods that execute the queries because part of what it does is close connections after the method is run.

Full traceback:

Jul 13 22:06:48 ubuntu-jammy <email address hidden>[270259]: DEBUG nova.api.openstack.wsgi [None req-b47b7ad6-eecd-44a9-8264-706742dd8539 demo demo] Calling method '<bound method FlavorExtraSpecsController.index of <nova.api.openstack.compute.flavors_extraspecs.FlavorExtraSpecsController object at 0x7ff2813d6ce0>>' {{(pid=270259) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:513}}
Jul 13 22:06:58 ubuntu-jammy <email address hidden>[270259]: DEBUG dbcounter [-] [270259] Writing DB stats nova_api:SELECT=2 {{(pid=270259) stat_writer /usr/local/lib/python3.10/dist-packages/dbcounter.py:117}}
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi [None req-b47b7ad6-eecd-44a9-8264-706742dd8539 demo demo] Unexpected exception in API method: sqlalchemy.exc.TimeoutError: QueuePool limit of size 5 overflow 50 reached, connection timed out, timeout 30.00 (Background on this error at: https://sqlalche.me/e/14/3o7r)
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi Traceback (most recent call last):
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/opt/stack/nova/nova/api/openstack/wsgi.py", line 658, in wrapped
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi return f(*args, **kwargs)
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/opt/stack/nova/nova/api/openstack/compute/flavors_extraspecs.py", line 64, in index
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi return self._get_extra_specs(context, flavor_id)
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/opt/stack/nova/nova/api/openstack/compute/flavors_extraspecs.py", line 34, in _get_extra_specs
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi flavor = common.get_flavor(context, flavor_id)
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/opt/stack/nova/nova/api/openstack/common.py", line 494, in get_flavor
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi return objects.Flavor.get_by_flavor_id(context, flavor_id)
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/usr/local/lib/python3.10/dist-packages/oslo_versionedobjects/base.py", line 184, in wrapper
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi result = fn(cls, context, *args, **kwargs)
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/opt/stack/nova/nova/objects/flavor.py", line 395, in get_by_flavor_id
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi db_flavor = cls._flavor_get_by_flavor_id_from_db(context,
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/opt/stack/nova/nova/db/utils.py", line 35, in wrapper
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi return f(*args, **kwargs)
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/opt/stack/nova/nova/objects/flavor.py", line 320, in _flavor_get_by_flavor_id_from_db
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi first()
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/usr/local/lib/python3.10/dist-packages/sqlalchemy/orm/query.py", line 2823, in first
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi return self.limit(1)._iter().first()
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/usr/local/lib/python3.10/dist-packages/sqlalchemy/orm/query.py", line 2907, in _iter
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi result = self.session.execute(
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/usr/local/lib/python3.10/dist-packages/sqlalchemy/orm/session.py", line 1711, in execute
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi conn = self._connection_for_bind(bind)
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/usr/local/lib/python3.10/dist-packages/sqlalchemy/orm/session.py", line 1552, in _connection_for_bind
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi return self._transaction._connection_for_bind(
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/usr/local/lib/python3.10/dist-packages/sqlalchemy/orm/session.py", line 747, in _connection_for_bind
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi conn = bind.connect()
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/usr/local/lib/python3.10/dist-packages/sqlalchemy/engine/base.py", line 3315, in connect
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi return self._connection_cls(self, close_with_result=close_with_result)
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/usr/local/lib/python3.10/dist-packages/sqlalchemy/engine/base.py", line 96, in __init__
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi else engine.raw_connection()
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/usr/local/lib/python3.10/dist-packages/sqlalchemy/engine/base.py", line 3394, in raw_connection
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi return self._wrap_pool_connect(self.pool.connect, _connection)
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/usr/local/lib/python3.10/dist-packages/sqlalchemy/engine/base.py", line 3361, in _wrap_pool_connect
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi return fn()
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/usr/local/lib/python3.10/dist-packages/sqlalchemy/pool/base.py", line 320, in connect
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi return _ConnectionFairy._checkout(self)
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/usr/local/lib/python3.10/dist-packages/sqlalchemy/pool/base.py", line 884, in _checkout
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi fairy = _ConnectionRecord.checkout(pool)
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/usr/local/lib/python3.10/dist-packages/sqlalchemy/pool/base.py", line 486, in checkout
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi rec = pool._do_get()
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi File "/usr/local/lib/python3.10/dist-packages/sqlalchemy/pool/impl.py", line 134, in _do_get
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi raise exc.TimeoutError(
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi sqlalchemy.exc.TimeoutError: QueuePool limit of size 5 overflow 50 reached, connection timed out, timeout 30.00 (Background on this error at: https://sqlalche.me/e/14/3o7r)
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: ERROR nova.api.openstack.wsgi
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: INFO nova.api.openstack.wsgi [None req-b47b7ad6-eecd-44a9-8264-706742dd8539 demo demo] HTTP exception thrown: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: <class 'sqlalchemy.exc.TimeoutError'>
Jul 13 22:07:18 ubuntu-jammy <email address hidden>[270259]: DEBUG nova.api.openstack.wsgi [None req-b47b7ad6-eecd-44a9-8264-706742dd8539 demo demo] Returning 500 to user: Unexpected API Error. Please report this at http://bugs.launchpad.net/nova/ and attach the Nova API log if possible.

[melanie witt (melwitt)]

Patch is proposed at https://review.opendev.org/c/openstack/nova/+/888513

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/nova/+/888513
Committed: https://opendev.org/openstack/nova/commit/9ae6240c92e212b2fa96d5163f68ef1b30ee03b7
Submitter: "Zuul (22348)"
Branch: master

commit 9ae6240c92e212b2fa96d5163f68ef1b30ee03b7
Author: melanie witt <email address hidden>
Date: Fri Jul 14 02:23:23 2023 +0000

    Decorate only Flavor.get_* methods that execute queries

    The get_* methods on the Flavor object use a common helper method to
    build a query object to execute later.

    Currently, the @api_db_api.context_manager.reader decorator which
    manages the session is located on the helper method instead of on the
    methods that actually execute the database queries. Part of the context
    manager's job is to close the session after the query is executed.
    Because the decorator is not on the methods that actually execute the
    queries, those database connections are not being closed and it will
    eventually lead to errors like:

      sqlalchemy.exc.TimeoutError: QueuePool limit of size 5 overflow 50
      reached, connection timed out, timeout 30.00 (Background on this
      error at: https://sqlalche.me/e/14/3o7r)

    which means the connection pool size plus the overflow size has been
    reached and the pool will block for a fixed period of time before
    timing out and raising this error.

    This removes the @api_db_api.context_manager.reader decorator from the
    query build helper method and adds it to the Flavor.get_* methods that
    execute the database queries.

    Closes-Bug: #2027755

    Change-Id: I4bf83d1642b62ab103716aff6dae7438646e2b31

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/2023.1
Review: https://review.opendev.org/c/openstack/nova/+/891749

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 28.0.0.0rc1 release candidate.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/nova/+/891749
Committed: https://opendev.org/openstack/nova/commit/4f4f27be27cb202be6a8fb949ad21021a5cd735d
Submitter: "Zuul (22348)"
Branch: stable/2023.1

commit 4f4f27be27cb202be6a8fb949ad21021a5cd735d
Author: melanie witt <email address hidden>
Date: Fri Jul 14 02:23:23 2023 +0000

    Decorate only Flavor.get_* methods that execute queries

    The get_* methods on the Flavor object use a common helper method to
    build a query object to execute later.

    Currently, the @api_db_api.context_manager.reader decorator which
    manages the session is located on the helper method instead of on the
    methods that actually execute the database queries. Part of the context
    manager's job is to close the session after the query is executed.
    Because the decorator is not on the methods that actually execute the
    queries, those database connections are not being closed and it will
    eventually lead to errors like:

      sqlalchemy.exc.TimeoutError: QueuePool limit of size 5 overflow 50
      reached, connection timed out, timeout 30.00 (Background on this
      error at: https://sqlalche.me/e/14/3o7r)

    which means the connection pool size plus the overflow size has been
    reached and the pool will block for a fixed period of time before
    timing out and raising this error.

    This removes the @api_db_api.context_manager.reader decorator from the
    query build helper method and adds it to the Flavor.get_* methods that
    execute the database queries.

    Closes-Bug: #2027755

    Change-Id: I4bf83d1642b62ab103716aff6dae7438646e2b31
    (cherry picked from commit 9ae6240c92e212b2fa96d5163f68ef1b30ee03b7)

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/zed
Review: https://review.opendev.org/c/openstack/nova/+/899119

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/c/openstack/nova/+/899119
Committed: https://opendev.org/openstack/nova/commit/53e3afe3a6024be6ead35132230dc468dd808850
Submitter: "Zuul (22348)"
Branch: stable/zed

commit 53e3afe3a6024be6ead35132230dc468dd808850
Author: melanie witt <email address hidden>
Date: Fri Jul 14 02:23:23 2023 +0000

    Decorate only Flavor.get_* methods that execute queries

    The get_* methods on the Flavor object use a common helper method to
    build a query object to execute later.

    Currently, the @api_db_api.context_manager.reader decorator which
    manages the session is located on the helper method instead of on the
    methods that actually execute the database queries. Part of the context
    manager's job is to close the session after the query is executed.
    Because the decorator is not on the methods that actually execute the
    queries, those database connections are not being closed and it will
    eventually lead to errors like:

      sqlalchemy.exc.TimeoutError: QueuePool limit of size 5 overflow 50
      reached, connection timed out, timeout 30.00 (Background on this
      error at: https://sqlalche.me/e/14/3o7r)

    which means the connection pool size plus the overflow size has been
    reached and the pool will block for a fixed period of time before
    timing out and raising this error.

    This removes the @api_db_api.context_manager.reader decorator from the
    query build helper method and adds it to the Flavor.get_* methods that
    execute the database queries.

    Closes-Bug: #2027755

    Change-Id: I4bf83d1642b62ab103716aff6dae7438646e2b31
    (cherry picked from commit 9ae6240c92e212b2fa96d5163f68ef1b30ee03b7)
    (cherry picked from commit 4f4f27be27cb202be6a8fb949ad21021a5cd735d)

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/yoga
Review: https://review.opendev.org/c/openstack/nova/+/900821

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/xena
Review: https://review.opendev.org/c/openstack/nova/+/900822

[melanie witt (melwitt)]

Fixed in stable/2023.1 by https://review.opendev.org/c/openstack/nova/+/891749

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/wallaby
Review: https://review.opendev.org/c/openstack/nova/+/900832

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 27.2.0 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 26.2.1 release.

[OpenStack Infra (hudson-openstack)]

Change abandoned by "Elod Illes <email address hidden>" on branch: stable/yoga
Review: https://review.opendev.org/c/openstack/nova/+/900821
Reason: stable/yoga branch of openstack/nova is about to be deleted. To be able to do that, all open patches need to be abandoned. Please cherry pick the patch to unmaintained/yoga if you want to further work on this patch.

[OpenStack Infra (hudson-openstack)]

Change abandoned by "Elod Illes <email address hidden>" on branch: stable/wallaby
Review: https://review.opendev.org/c/openstack/nova/+/900832
Reason: stable/wallaby branch of openstack/nova is about to be deleted. To be able to do that, all open patches need to be abandoned. Please cherry pick the patch to unmaintained/wallaby if you want to further work on this patch.

[OpenStack Infra (hudson-openstack)]

Change abandoned by "Elod Illes <email address hidden>" on branch: stable/xena
Review: https://review.opendev.org/c/openstack/nova/+/900822
Reason: stable/xena branch of openstack/nova is about to be deleted. To be able to do that, all open patches need to be abandoned. Please cherry pick the patch to unmaintained/xena if you want to further work on this patch.