Skip to content

v0.25.0 with grpcio==1.3.5 hangs in completion_queue.poll() #3450

Closed
Closed
v0.25.0 with grpcio==1.3.5 hangs in completion_queue.poll()#3450
Assignees
lukesneeringer
Labels
grpctype: bugError or flaw in code with unintended results or allowing sub-optimal usage patterns.

Description

@yaalaa
yaalaa
opened on May 23, 2017

I'm not sure that's the right place to file this issue. It could be something well-known one of another project. Nevertheless here it is:
I'm running Google App Engine Flexible VM.
The webservice uses gunicorn + gevent + flask chain.
It uses this lib v0.25.0
Yesterday, upon new deployment, I've faced with old and relatively seldom issue - it hangs in completion_queue.poll() in deep of grpcio.
I have been seeing such an issue from time to time.
However it has become a nightmare with recent deployment. Workers end up in critical timeout and been rebooted all the way.
And here's what I've found out:

  • my recent deployment picks grpcio==1.3.5 - it hangs all the way
  • I've added explicit dependency to grpcio==1.3.0 and things go well.

Activity

  1. dhermes
    added
    grpc
    on May 24, 2017

  2. dhermes commented on May 24, 2017

    @dhermes
    dhermes
    on May 24, 2017
    Contributor

    /cc @nathanielmanistaatgoogle

  3. dhermes commented on May 24, 2017

    @dhermes
    dhermes
    on May 24, 2017
    Contributor

    @yaalaa Thanks for taking the time to report this!

    Which subpackage are you using (other than just google-cloud==0.25.0)? Also, can you provide a code snippet that causes this failure (or describe a little bit of what is failing)?

  4. dhermes
    added
    type: bugError or flaw in code with unintended results or allowing sub-optimal usage patterns.
    on May 24, 2017

  5. yaalaa commented on May 24, 2017

    @yaalaa
    yaalaa
    on May 24, 2017
    Author

    Here's the pip freeze output that hangs (Google-specific highlighted):

    gapic-google-cloud-datastore-v1==0.15.3
gapic-google-cloud-error-reporting-v1beta1==0.15.3
gapic-google-cloud-logging-v2==0.91.3
gapic-google-cloud-pubsub-v1==0.15.4
gapic-google-cloud-spanner-admin-database-v1==0.15.3
gapic-google-cloud-spanner-admin-instance-v1==0.15.3
gapic-google-cloud-spanner-v1==0.15.3
gapic-google-cloud-speech-v1beta1==0.15.3
gapic-google-cloud-vision-v1==0.90.3
google-auth==1.0.1
google-auth-httplib2==0.0.2
google-cloud==0.25.0
google-cloud-bigquery==0.24.0
google-cloud-bigtable==0.24.0
google-cloud-core==0.24.1
google-cloud-datastore==1.0.0
google-cloud-dns==0.24.0
google-cloud-error-reporting==0.24.2
google-cloud-language==0.24.1
google-cloud-logging==1.0.0
google-cloud-monitoring==0.24.0
google-cloud-pubsub==0.25.0
google-cloud-resource-manager==0.24.0
google-cloud-runtimeconfig==0.24.0
google-cloud-spanner==0.24.2
google-cloud-speech==0.24.0
google-cloud-storage==1.1.1
google-cloud-translate==0.24.0
google-cloud-vision==0.24.0
google-gax==0.15.13
google-resumable-media==0.0.2
googleapis-common-protos==1.5.2
grpc-google-iam-v1==0.11.1
grpcio==1.3.5
oauth2client==4.0.0
proto-google-cloud-datastore-v1==0.90.4
proto-google-cloud-error-reporting-v1beta1==0.15.3
proto-google-cloud-logging-v2==0.91.3
proto-google-cloud-pubsub-v1==0.15.4
proto-google-cloud-spanner-admin-database-v1==0.15.3
proto-google-cloud-spanner-admin-instance-v1==0.15.3
proto-google-cloud-spanner-v1==0.15.3
proto-google-cloud-speech-v1beta1==0.15.3
proto-google-cloud-vision-v1==0.90.3
protobuf==3.3.0

  6. yaalaa commented on May 24, 2017

    @yaalaa
    yaalaa
    on May 24, 2017
    Author

    I've looked at the logs. Sometimes it's hard to describe an use-case.
    I think my app uses Google Cloud Datastore only.

    Here's an example of how worker feels at the end:

    16:21:06 gunicorn.1  | [2017-05-23 16:21:06 +0000] [14] [CRITICAL] WORKER TIMEOUT (pid:1335)
16:21:06 gunicorn.1  | [2017-05-23 16:21:06 +0000] [1335] [INFO] gunicorn_config.worker_abort:
16:21:06 gunicorn.1  | [2017-05-23 16:21:06 +0000] [1335] [DEBUG]
16:21:06 gunicorn.1  | # Thread: (140447432369920)
16:21:06 gunicorn.1  | File: "/env/local/lib/python2.7/site-packages/gevent/threadpool.py", line 200, in _worker
16:21:06 gunicorn.1  |   task = task_queue.get()
16:21:06 gunicorn.1  | File: "/env/local/lib/python2.7/site-packages/gevent/_threading.py", line 437, in get
16:21:06 gunicorn.1  |   self.not_empty.wait()
16:21:06 gunicorn.1  | File: "/env/local/lib/python2.7/site-packages/gevent/_threading.py", line 153, in wait
16:21:06 gunicorn.1  |   waiter.acquire()
16:21:06 gunicorn.1  |
16:21:06 gunicorn.1  | # Thread: (140447440762624)
16:21:06 gunicorn.1  | File: "/env/local/lib/python2.7/site-packages/gevent/threadpool.py", line 200, in _worker
16:21:06 gunicorn.1  |   task = task_queue.get()
16:21:06 gunicorn.1  | File: "/env/local/lib/python2.7/site-packages/gevent/_threading.py", line 437, in get
16:21:06 gunicorn.1  |   self.not_empty.wait()
16:21:06 gunicorn.1  | File: "/env/local/lib/python2.7/site-packages/gevent/_threading.py", line 153, in wait
16:21:06 gunicorn.1  |   waiter.acquire()
16:21:06 gunicorn.1  |
16:21:06 gunicorn.1  | # Thread: (140447547774720)
16:21:06 gunicorn.1  | File: "/env/local/lib/python2.7/site-packages/gevent/greenlet.py", line 536, in run
16:21:06 gunicorn.1  |   result = self._run(*self.args, **self.kwargs)
16:21:06 gunicorn.1  | File: "/usr/lib/python2.7/threading.py", line 783, in __bootstrap
16:21:06 gunicorn.1  |   self.__bootstrap_inner()
16:21:06 gunicorn.1  | File: "/usr/lib/python2.7/threading.py", line 810, in __bootstrap_inner
16:21:06 gunicorn.1  |   self.run()
16:21:06 gunicorn.1  | File: "/usr/lib/python2.7/threading.py", line 763, in run
16:21:06 gunicorn.1  |   self.__target(*self.__args, **self.__kwargs)
16:21:06 gunicorn.1  | File: "/env/local/lib/python2.7/site-packages/grpc/_channel.py", line 852, in _poll_connectivity
16:21:06 gunicorn.1  |   event = completion_queue.poll()
16:21:06 gunicorn.1  | File: "/env/local/lib/python2.7/site-packages/gunicorn/workers/base.py", line 191, in handle_abort
16:21:06 gunicorn.1  |   self.cfg.worker_abort(self)
16:21:06 gunicorn.1  | File: "gunicorn_config.py", line 41, in worker_abort
16:21:06 gunicorn.1  |   for filename, lineno, name, line in traceback.extract_stack( stack ):

  7. yaalaa commented on May 24, 2017

    @yaalaa
    yaalaa
    on May 24, 2017
    Author

    I suppose each worker timeout is preceded by query or get.

  8. tcroiset commented on May 30, 2017

    @tcroiset
    tcroiset
    on May 30, 2017

    We have the same issue (and indeed grpcio==1.3.0 fix it)

  9. dhermes commented on May 31, 2017

    @dhermes
    dhermes
    on May 31, 2017
    Contributor

    @nathanielmanistaatgoogle Bump

  10. dhermes commented on May 31, 2017

    @dhermes
    dhermes
    on May 31, 2017
    Contributor

    @tcroiset Which subpackage are you using? (Is it google-cloud-datastore or something else?) Could you provide a code snippet that fails?

  11. tcroiset commented on May 31, 2017

    @tcroiset
    tcroiset
    on May 31, 2017

    It's google-cloud
    The service is a custom flex engine based on gcr.io/google_appengine/python

    It's part of a big project but I'll try by tomorrow to extract only the relevant code and reproduce the issue

  12. dhermes commented on May 31, 2017

    @dhermes
    dhermes
    on May 31, 2017
    Contributor

    Thanks @tcroiset.

    It's worth pointing out that google-cloud doesn't actually have any code in it. It is literally just a setup.py, a README and some other package artifacts:

    $ wget https://pypi.python.org/packages/10/a8/\
> 94cb99ec6e61814fc6e1093f9b81570b998028b7a5a9a6efe3ebc116acf7/\
> google-cloud-0.25.0.tar.gz#md5=59fa23b57e806e267153ac041c834fbc
$
$ tar xzvf google-cloud-0.25.0.tar.gz
google-cloud-0.25.0/
google-cloud-0.25.0/google_cloud.egg-info/
google-cloud-0.25.0/google_cloud.egg-info/not-zip-safe
google-cloud-0.25.0/google_cloud.egg-info/top_level.txt
google-cloud-0.25.0/google_cloud.egg-info/dependency_links.txt
google-cloud-0.25.0/google_cloud.egg-info/PKG-INFO
google-cloud-0.25.0/google_cloud.egg-info/requires.txt
google-cloud-0.25.0/google_cloud.egg-info/SOURCES.txt
google-cloud-0.25.0/MANIFEST.in
google-cloud-0.25.0/PKG-INFO
google-cloud-0.25.0/setup.cfg
google-cloud-0.25.0/setup.py
google-cloud-0.25.0/README.rst

    So in general, you may be happier being explicit with the google-cloud-${SERVICE} packages you use (these are the ones that actually have code in them).

  13. nathanielmanistaatgoogle commented on May 31, 2017

    @nathanielmanistaatgoogle
    nathanielmanistaatgoogle
    on May 31, 2017

    We've known for a while that gRPC Python doesn't yet play nicely with gevent (and gunicorn? I don't know as much about gunicorn), but the most likely change responsible for what you're seeing is pull request 11154. It added a use of threading, and gevent breaks use of threading, so... there's probably not an immediate or readily available solution other than pinning the grpcio dependency to the version that happens to work for you.

    @kpayson64, anything to add that I've missed?

  14. dhermes commented on May 31, 2017

    @dhermes
    dhermes
    on May 31, 2017
    Contributor

    Thanks for the pointers @nathanielmanistaatgoogle

  15. lukesneeringer commented on Aug 8, 2017

    @lukesneeringer
    lukesneeringer
    on Aug 8, 2017
    Contributor

    As this seems to be an upstream dependency issue, closing here.

  16. lukesneeringer
    closed this as completedon Aug 8, 2017

  17. AnilkumarKomanduru commented on Jun 22, 2018

    @AnilkumarKomanduru
    AnilkumarKomanduru
    on Jun 22, 2018

    Hi,
    Im using ttn version 2.1.1, and still seeing same issue,
    I did not use any certificate for your info for testing.

    gapic-google-cloud-datastore-v1==0.15.3
    gapic-google-cloud-error-reporting-v1beta1==0.15.3
    gapic-google-cloud-logging-v2==0.91.3
    gapic-google-cloud-pubsub-v1==0.15.4
    gapic-google-cloud-spanner-admin-database-v1==0.15.3
    gapic-google-cloud-spanner-admin-instance-v1==0.15.3
    gapic-google-cloud-spanner-v1==0.15.3
    gapic-google-cloud-speech-v1beta1==0.15.3
    gapic-google-cloud-vision-v1==0.90.3
    gitdb==0.6.4
    gitdb2==2.0.2
    gitpython==2.1.10
    google-api-core==0.1.4
    google-api-python-client==1.7.3
    google-auth==1.5.0
    google-auth-httplib2==0.0.3
    google-cloud==0.33.1
    google-cloud-bigquery==0.28.0
    google-cloud-bigquery-datatransfer==0.1.1
    google-cloud-bigtable==0.28.1
    google-cloud-container==0.1.1
    google-cloud-core==0.28.1
    google-cloud-datastore==1.4.0
    google-cloud-dns==0.28.0
    google-cloud-error-reporting==0.28.0
    google-cloud-firestore==0.28.0
    google-cloud-language==1.0.2
    google-cloud-logging==1.4.0
    google-cloud-monitoring==0.28.1
    google-cloud-pubsub==0.30.1
    google-cloud-resource-manager==0.28.1
    google-cloud-runtimeconfig==0.28.1
    google-cloud-spanner==0.29.0
    google-cloud-speech==0.30.0
    google-cloud-storage==1.6.0
    google-cloud-trace==0.17.0
    google-cloud-translate==1.3.1
    google-cloud-videointelligence==1.0.1
    google-cloud-vision==0.29.0
    google-gax==0.15.16
    google-resumable-media==0.3.1
    googleapis-common-protos==1.5.3
    grpc-google-iam-v1==0.11.4
    grpcio==1.7.3
    httplib2==0.11.3
    idna==2.7
    imagesize==0.7.1
    intelhex==2.1
    Jinja2==2.9.6
    MarkupSafe==1.0
    oauth2client==3.0.0
    packaging==17.1
    paho-mqtt==1.3.1
    ply==3.8
    proto-google-cloud-datastore-v1==0.90.4
    proto-google-cloud-error-reporting-v1beta1==0.15.3
    proto-google-cloud-logging-v2==0.91.3
    proto-google-cloud-pubsub-v1==0.15.4
    proto-google-cloud-spanner-admin-database-v1==0.15.3
    proto-google-cloud-spanner-admin-instance-v1==0.15.3
    proto-google-cloud-spanner-v1==0.15.3
    proto-google-cloud-speech-v1beta1==0.15.3
    proto-google-cloud-vision-v1==0.90.3
    protobuf==3.6.0
    psutil==5.4.6
    PTable==0.9.2
    pyasn1==0.4.3
    pyasn1-modules==0.2.1
    pycparser==2.18
    Pygments==2.2.0
    pyparsing==2.2.0
    pyreadline==2.1
    pyserial==3.3
    python-jose==3.0.0
    pytz==2017.2
    PyYAML==3.12
    requests==2.19.1
    rsa==3.4.2
    selenium==2.53.6
    six==1.10.0
    smmap==0.9.0
    smmap2==2.0.3
    snowballstemmer==1.2.1
    Sphinx==1.5.1
    spider==3.3.1
    ttn==2.1.1.

  18. JustinBeckwith
    assigned
    lukesneeringer
    on Feb 1, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

grpctype: 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