René's URL Explorer Experiment

{"@context":"https://schema.org","@type":"DiscussionForumPosting","headline":"Deadlock in streaming_pull_manager and ResumableBidiRpc after receiving 504 deadline exceeded error","articleBody":"#### Environment details\r\n\r\n  - OS type and version: alpine 3.11\r\n  - Python version: 3.7.7\r\n  - pip version: 20.0.2\r\n  - `google-cloud-pubsub` version: 1.4.2\r\n\r\n#### Steps to reproduce\r\n\r\n  1. Start subscriber client\r\n  2. Wait for 10 minutes (server should return 504 Deadline Exceeded error)\r\n  3. Messages no longer received and heartbeat no longer sent\r\n\r\nHere are the debug logs just after 10 mins.\r\n```\r\nDEBUG:google.cloud.pubsub_v1.subscriber._protocol.leaser:The current deadline value is 10 seconds.\r\nDEBUG:google.cloud.pubsub_v1.subscriber._protocol.leaser:Snoozing lease management for 7.152175 seconds.\r\nINFO:google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager:Observed non-terminating stream error 504 Deadline Exceeded\r\nINFO:google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager:Observed recoverable stream error 504 Deadline Exceeded\r\nDEBUG:google.api_core.bidi:Re-opening stream from gRPC callback.\r\nDEBUG:google.api_core.bidi:Empty queue and inactive call, exiting request generator.\r\nDEBUG:google.cloud.pubsub_v1.subscriber._protocol.leaser:The current deadline value is 10 seconds.\r\nDEBUG:google.cloud.pubsub_v1.subscriber._protocol.leaser:Snoozing lease management for 4.379558 seconds.\r\nDEBUG:google.cloud.pubsub_v1.subscriber._protocol.leaser:The current deadline value is 10 seconds.\r\nDEBUG:google.cloud.pubsub_v1.subscriber._protocol.leaser:Snoozing lease management for 7.720803 seconds.\r\nDEBUG:google.cloud.pubsub_v1.subscriber._protocol.leaser:The current deadline value is 10 seconds.\r\nDEBUG:google.cloud.pubsub_v1.subscriber._protocol.leaser:Snoozing lease management for 3.224825 seconds.\r\nDEBUG:google.cloud.pubsub_v1.subscriber._protocol.leaser:The current deadline value is 10 seconds.\r\nDEBUG:google.cloud.pubsub_v1.subscriber._protocol.leaser:Snoozing lease management for 0.857948 seconds.\r\n```\r\n\r\nLooking at the logs, I'm expected to see `_LOGGER.debug(\"Call to retryable %r caused %s.\", method, exc)` since it should be printed on error https://github.com/googleapis/python-api-core/blob/5e5559202891f7e5b6c22c2cbc549e1ec26eb857/google/api_core/bidi.py#L508. However, the message was not printed so the thread was stuck acquiring `self._operational_lock`.\r\n\r\nI've sampled the top functions running on all threads after getting into the deadlock state (attached as stacktrace below). The heartbeater's background thread seems to be frequently holding the lock as it performs the `is_active` check https://github.com/googleapis/python-pubsub/blob/master/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py#L425. I'm not sure why it's not being released.\r\n\r\n#### Code example\r\n\r\n```python\r\nimport logging\r\n\r\nfrom google.cloud.pubsub_v1 import SubscriberClient\r\n\r\n\r\ndef main():\r\n    logging.basicConfig(level=logging.DEBUG)\r\n\r\n    client = SubscriberClient()\r\n    sub = client.subscription_path(\"project\", \"subscription\")\r\n\r\n    def callback(message):\r\n        print(message)\r\n        message.ack()\r\n\r\n    future = client.subscribe(sub, callback)\r\n\r\n    try:\r\n        future.result()\r\n    except KeyboardInterrupt:\r\n        future.cancel()\r\n\r\nif __name__ == \"__main__\":\r\n    main()\r\n```\r\n\r\n#### Stack trace\r\n```\r\nCollecting samples from 'python main.py' (python v3.7.7)\r\nTotal Samples 2000\r\nGIL: 0.00%, Active: 12.00%, Threads: 17\r\n\r\n  %Own   %Total  OwnTime  TotalTime  Function (filename:line)\r\n 10.00%  10.00%    1.94s     1.94s   _worker (concurrent/futures/thread.py:78)\r\n  2.00%   2.00%   0.640s    0.640s   _recoverable (api_core/bidi.py:508)\r\n  0.00%   0.00%   0.330s    0.330s   is_active (api_core/bidi.py:578)\r\n  0.00%   0.00%   0.000s    0.330s   heartbeat (pubsub_v1/subscriber/_protocol/streaming_pull_manager.py:425)\r\n  0.00%  12.00%   0.000s     2.91s   _bootstrap (threading.py:890)\r\n  0.00%  12.00%   0.000s     2.91s   _bootstrap_inner (threading.py:926)\r\n  0.00%   2.00%   0.000s    0.640s   recv (api_core/bidi.py:562)\r\n  0.00%  12.00%   0.000s     2.91s   run (threading.py:870)\r\n  0.00%   0.00%   0.000s    0.330s   heartbeat (pubsub_v1/subscriber/_protocol/heartbeater.py:40)\r\n  0.00%   2.00%   0.000s    0.640s   _thread_main (api_core/bidi.py:655)\r\n```","author":{"url":"https://github.com/sweatybridge","@type":"Person","name":"sweatybridge"},"datePublished":"2020-04-16T07:34:13.000Z","interactionStatistic":{"@type":"InteractionCounter","interactionType":"https://schema.org/CommentAction","userInteractionCount":10},"url":"https://github.com/74/python-pubsub/issues/74"}