Skip to content

Core: Race condition in bidi.BackgroundConsumer? #15094

Closed as not planned
Closed as not planned
Core: Race condition in bidi.BackgroundConsumer?#15094
Labels
externalThis issue is blocked on a bug with the actual product.priority: p2Moderately-important priority. Fix may not be included in next release.status: blockedResolving the issue is dependent on other work.type: bugError or flaw in code with unintended results or allowing sub-optimal usage patterns.

Description

@plamut
plamut
opened on Apr 29, 2019

Environment details

Any OS, any Python version, google-api-core==1.9.0.

Steps to reproduce

No actual steps, spotted this in bidi.py while working on a different issue. This is how the "Am I paused?" snippet in BackgroundConsumer._thread_main() looks like:

with self._wake:
    if self._paused:
        _LOGGER.debug("paused, waiting for waking.")
        self._wake.wait()
        _LOGGER.debug("woken.")

_LOGGER.debug("waiting for recv.")
response = self._bidi_rpc.recv()

The _paused state can be set / cleared by the pause() and resume() methods, respectively.

If paused, the code snippet from above blocks at the _wake.wait() call, and is unblocked some time after _wake.notifyAll() is invoked in the resume() method. When resume() method notifies the waiting threads and releases the internal lock held by the self._wake condition, _wake.wait() tries to re-obtain that lock.

Now, suppose that some other thread invokes the pause() method in the meantime, and the latter obtains the self._wake's lock before _wake.wait() can grab it. The _paused flag will again be set to True, and when _wake.wait() finally acquires the lock and resumes, the code will invoke _bidi_rpc.recv() in the paused state.

For this reason the self._paused condition must be checked in a loop, and not in a single if statement, as the docs on threading.Condition state:

The while loop checking for the application’s condition is necessary because wait() can return after an arbitrary long time, and the condition which prompted the notify() call may no longer hold true. This is inherent to multi-threaded programming.

How much of a problem this is, i.e. invoking recv() in a paused state?

Edit:
The same can happen when exiting the with self._wake block. The lock gets released, pause() can acquire it and set _self._paused to True, but _bidi_rpc.recv() will nevertheless be called, because it is placed outside the with block.

Code example

I created a demo script that demonstrates why if <condition> is not sufficient, and subject to race conditions (requires Python 3.6+). The "worker" thread waits until a shared global number is set to 10, while five "changer threads" randomly change that number, and notify other threads if they change it to 10.

Sometimes the "worker" is invoked too late, and another "changer" thread changes 10 to something else, causing the "worker" to continue running when the target condition is no longer true. Replacing if not <condition> with while not <condition> gets rid of the bug.

...
INFO     [2019-04-29 23:09:20,327] Thread-Changer-0: Changing number from  9 to 10
INFO     [2019-04-29 23:09:20,327] Thread-Changer-0: New number == 10, notifying others
INFO     [2019-04-29 23:09:20,327] Thread-Worker   : I see the number 10
INFO     [2019-04-29 23:09:20,327] Thread-Changer-1: Changing number from 10 to  4
INFO     [2019-04-29 23:09:20,327] Thread-Changer-4: Changing number from  4 to 10
INFO     [2019-04-29 23:09:20,327] Thread-Changer-4: New number == 10, notifying others
INFO     [2019-04-29 23:09:20,328] Thread-Changer-2: Changing number from 10 to  3
INFO     [2019-04-29 23:09:21,328] Thread-Changer-3: Changing number from  3 to  9
INFO     [2019-04-29 23:09:21,328] Thread-Changer-1: Changing number from  9 to  6
INFO     [2019-04-29 23:09:21,328] Thread-Changer-4: Changing number from  6 to  4
INFO     [2019-04-29 23:09:21,328] Thread-Worker   : the number is not 10, will wait for condition
INFO     [2019-04-29 23:09:21,328] Thread-Changer-0: Changing number from  4 to  6
INFO     [2019-04-29 23:09:21,329] Thread-Changer-2: Changing number from  6 to  9
INFO     [2019-04-29 23:09:22,329] Thread-Changer-3: Changing number from  9 to 10
INFO     [2019-04-29 23:09:22,329] Thread-Changer-3: New number == 10, notifying others
INFO     [2019-04-29 23:09:22,329] Thread-Changer-1: Changing number from 10 to  5
INFO     [2019-04-29 23:09:22,329] Thread-Worker   : I see the number 5
...

The expected behavior is that the worker thread always prints out "I see the number 10" (the desired condition), and never "I see <non 10>". In other words, it should only proceed when the condition number == 10 is currently fulfilled.

In the bidi.py case, this would translate to BackgroundConsumer._thread_main() only resuming when self._paused == False, and never resuming when self._paused == True.

Activity

  1. tseaver commented on Jul 23, 2019

    @tseaver
    tseaver
    on Jul 23, 2019
    Contributor

    @plamut I'm in agreement with your analysis here: the stdlib's docs hightlght the problem clearly.

  2. tseaver commented on Jul 23, 2019

    @tseaver
    tseaver
    on Jul 23, 2019
    Contributor

    The "obvious" fix:

    --- a/api_core/google/api_core/bidi.py
+++ b/api_core/google/api_core/bidi.py
@@ -642,14 +642,15 @@ class BackgroundConsumer(object):
                 # In the future, we could use `Condition.wait_for` if we drop
                 # Python 2.7.
                 with self._wake:
-                    if self._paused:
+                    while self._paused:
                         _LOGGER.debug("paused, waiting for waking.")
                         self._wake.wait()
                         _LOGGER.debug("woken.")
 
-                _LOGGER.debug("waiting for recv.")
-                response = self._bidi_rpc.recv()
-                _LOGGER.debug("recved response.")
+                    _LOGGER.debug("waiting for recv.")
+                    response = self._bidi_rpc.recv()
+                    _LOGGER.debug("recved response.")
+
                 self._on_response(response)
 
         except exceptions.GoogleAPICallError as exc:

    passes all unit tests in api_core, but causes system tests to hang for firestore:

    $ .nox/system-3-7/bin/py.test --verbose tests/system.py 
============================= test session starts ==============================
platform linux -- Python 3.7.1, pytest-5.0.1, py-1.8.0, pluggy-0.12.0 -- /.../firestore/.nox/system-3-7/bin/python3.7
cachedir: .pytest_cache
rootdir: /.../firestore
collected 25 items                                                             

tests/system.py::test_collections PASSED                                 [  4%]
tests/system.py::test_create_document PASSED                             [  8%]
tests/system.py::test_create_document_w_subcollection PASSED             [ 12%]
tests/system.py::test_cannot_use_foreign_key PASSED                      [ 16%]
tests/system.py::test_no_document PASSED                                 [ 20%]
tests/system.py::test_document_set PASSED                                [ 24%]
tests/system.py::test_document_integer_field PASSED                      [ 28%]
tests/system.py::test_document_set_merge PASSED                          [ 32%]
tests/system.py::test_document_set_w_int_field PASSED                    [ 36%]
tests/system.py::test_document_update_w_int_field PASSED                 [ 40%]
tests/system.py::test_update_document PASSED                             [ 44%]
tests/system.py::test_document_get PASSED                                [ 48%]
tests/system.py::test_document_delete PASSED                             [ 52%]
tests/system.py::test_collection_add PASSED                              [ 56%]
tests/system.py::test_query_stream PASSED                                [ 60%]
tests/system.py::test_query_unary PASSED                                 [ 64%]
tests/system.py::test_collection_group_queries PASSED                    [ 68%]
tests/system.py::test_collection_group_queries_startat_endat PASSED      [ 72%]
tests/system.py::test_collection_group_queries_filters PASSED            [ 76%]
tests/system.py::test_get_all PASSED                                     [ 80%]
tests/system.py::test_batch PASSED                                       [ 84%]
tests/system.py::test_watch_document PASSED                              [ 88%]^C
...
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! KeyboardInterrupt !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
/opt/Python-3.7.1/lib/python3.7/threading.py:241: KeyboardInterrupt

    and pubsub:

    $ .nox/system-3-7/bin/py.test --verbose tests/system.py tests/system/
============================= test session starts ==============================
platform linux -- Python 3.7.1, pytest-5.0.1, py-1.8.0, pluggy-0.12.0 -- /.../pubsub/.nox/system-3-7/bin/python3.7
cachedir: .pytest_cache
rootdir: /.../pubsub
collected 12 items                                                             

tests/system.py::test_publish_messages PASSED                            [  8%]
tests/system.py::test_subscribe_to_messages PASSED                       [ 16%]
tests/system.py::test_subscribe_to_messages_async_callbacks ^C
...
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! KeyboardInterrupt !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
/opt/Python-3.7.1/lib/python3.7/threading.py:241: KeyboardInterrupt

  3. plamut commented on Jul 23, 2019

    @plamut
    plamut
    on Jul 23, 2019
    ContributorAuthor

    Did a quick check (for pubsub at least) with the above patch applied, and the async callbacks test hangs when cancelling the future. Might be related to #8616.

    Update:
    Or maybe not. It seems that the problem here is waiting for recv() while holding the self._wake lock. If the future gets cancelled then, the consumer tries to resume the thread, but resume() method first needs to acquire the very same self._wake lock and gets blocked.

  4. tseaver
    self-assigned this
    on Aug 1, 2019
  5. tseaver
    added a commit that references this issue on Aug 1, 2019

    Fix race in 'BackgroundConsumer._thread_main'. (#8883)

    5c7246f

  6. tseaver commented on Aug 1, 2019

    @tseaver
    tseaver
    on Aug 1, 2019
    Contributor

    @plamut believes that #8883 did not completely resolve the race, so I updated it to avoid closing this issue.

  7. tseaver commented on Oct 10, 2019

    @tseaver
    tseaver
    on Oct 10, 2019
    Contributor

    Both BidiRpc.recv and ResumableBidiRpc.recv are implemented by calling next() on the underling gRPC Call object, which provides no timeout mechanism.

    PR #9337 deals with the race / hang by timing out the call to join the daemonized worker thread, but it doesn't really fix the issue here.

    I've filed grpc/grpc#20562 to ask that the grpc._channel._Rendezvous class expose an alternative method which takes a timeout: we could then close this issue by calling that method rather than using next(self.call).

  8. tseaver
    removed their assignment
    on Oct 10, 2019
  9. busunkim96
    transferred this issue fromgoogleapis/google-cloud-pythonon Feb 7, 2020
  10. busunkim96
    added
    externalThis issue is blocked on a bug with the actual product.
    priority: p2Moderately-important priority. Fix may not be included in next release.
    type: bugError or flaw in code with unintended results or allowing sub-optimal usage patterns.
    on Feb 7, 2020

  11. vchudnov-g commented on Jan 31, 2023

    @vchudnov-g
    vchudnov-g
    on Jan 31, 2023
    Contributor

    UPDATE: PR #9337 was merged, but it's not immediately clear whether grpc/grpc#20562 was addressed. Pinging this issue so we consider it in future planning.

  12. vchudnov-g commented on May 19, 2023

    @vchudnov-g
    vchudnov-g
    on May 19, 2023
    Contributor

    Pinged grpc/grpc#20562 to see whether that was implemented, which would unblock us from implementing the rest of the solution here.

  13. vchudnov-g commented on Jul 23, 2024

    @vchudnov-g
    vchudnov-g
    on Jul 23, 2024
    Contributor

    It looks like grpc/grpc#20562 won't happen this quarter at least. We're waiting on that.

  14. vchudnov-g commented on Apr 21, 2025

    @vchudnov-g
    vchudnov-g
    on Apr 21, 2025
    Contributor

    I don't see any progress on grpc/grpc#20562; i just pinged them for an update.

  15. vchudnov-g
    added
    status: blockedResolving the issue is dependent on other work.
    on Apr 21, 2025

  16. parthea commented on Jan 12, 2026

    @parthea
    parthea
    on Jan 12, 2026
    Contributor

    Transferring to google-cloud-python as the code for python-api-core will be migrated there in 1-3 weeks.

  17. parthea
    transferred this issue fromgoogleapis/python-api-coreon Jan 12, 2026

  18. daniel-sanche commented on May 28, 2026

    @daniel-sanche
    daniel-sanche
    on May 28, 2026
    Contributor

    This issue is being bulk closed due to inactivity. Please re-open if you think this still requires attention, and we'll take another look. Thanks!

  19. daniel-sanche
    closed this as not plannedon May 28, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    externalThis issue is blocked on a bug with the actual product.priority: p2Moderately-important priority. Fix may not be included in next release.status: blockedResolving the issue is dependent on other work.type: bugError or flaw in code with unintended results or allowing sub-optimal usage patterns.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions