subscription pull deadline exceeded

[mwytock]

Calling sub.pull() sometimes results in deadline exceeded exceptions from lower layer, I believe when the topic is empty.

Traceback (most recent call last):
  File "/usr/lib/python2.7/runpy.py", line 162, in _run_module_as_main
    "__main__", fname, loader, pkg_name)
  File "/usr/lib/python2.7/runpy.py", line 72, in _run_code
    exec code in run_globals
  File "/tlaloc/python/tlaloc/data/bq_loader.py", line 145, in <module>
    pulled = sub.pull()
  File "/usr/local/lib/python2.7/dist-packages/google/cloud/pubsub/subscription.py", line 325, in pull
    self.full_name, return_immediately, max_messages)
  File "/usr/local/lib/python2.7/dist-packages/google/cloud/pubsub/_gax.py", line 396, in subscription_pull
    return_immediately=return_immediately)
  File "/usr/local/lib/python2.7/dist-packages/google/cloud/gapic/pubsub/v1/subscriber_api.py", line 545, in pull
    return self._pull(request, options)
  File "/usr/local/lib/python2.7/dist-packages/google/gax/api_callable.py", line 481, in inner
    return api_caller(api_call, this_settings, request)
  File "/usr/local/lib/python2.7/dist-packages/google/gax/api_callable.py", line 469, in base_caller
    return api_call(*args)
  File "/usr/local/lib/python2.7/dist-packages/google/gax/api_callable.py", line 434, in inner
    errors.create_error('RPC failed', cause=exception))
  File "/usr/local/lib/python2.7/dist-packages/google/gax/api_callable.py", line 430, in inner
    return a_func(*args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/google/gax/api_callable.py", line 64, in inner
    return a_func(*updated_args, **kwargs)
  File "/usr/local/lib/python2.7/dist-packages/grpc/_channel.py", line 481, in __call__
    return _end_unary_response_blocking(state, False, deadline)
  File "/usr/local/lib/python2.7/dist-packages/grpc/_channel.py", line 432, in _end_unary_response_blocking
    raise _Rendezvous(state, None, None, deadline)
google.gax.errors.GaxError: GaxError(RPC failed, caused by <_Rendezvous of RPC that terminated with (StatusCode.DEADLINE_EXCEEDED, Deadline Exceeded)>)

(tlaloc-dev)Matts-MacBook-Air-2:notebooks mwytock$ pip show google-cloud

---
Metadata-Version: 2.0
Name: google-cloud
Version: 0.20.0
Summary: API Client library for Google Cloud
Home-page: https://github.com/GoogleCloudPlatform/google-cloud-python
Author: Google Cloud Platform
Author-email: jjg+google-cloud-python@google.com
Installer: pip
License: Apache 2.0
Location: /Users/mwytock/tlaloc-dev/lib/python2.7/site-packages
Requires: google-cloud-vision, google-cloud-monitoring, google-cloud-core, google-cloud-error-reporting, google-cloud-pubsub, google-cloud-storage, google-cloud-logging, google-cloud-datastore, google-cloud-bigtable, google-cloud-resource-manager, google-cloud-bigquery, google-cloud-dns, google-cloud-translate, google-cloud-language
Classifiers:
  Development Status :: 4 - Beta
  Intended Audience :: Developers
  License :: OSI Approved :: Apache Software License
  Operating System :: OS Independent
  Programming Language :: Python :: 2
  Programming Language :: Python :: 2.7
  Programming Language :: Python :: 3
  Programming Language :: Python :: 3.4
  Programming Language :: Python :: 3.5
  Topic :: Internet

[daspecster]

Thanks for reporting @mwytock!

Unless I'm missing some context, this seems like it could be the correct reaction in certain scenarios?

The request did not complete in the time allocated. This can be caused by network issues from the client to the server, and it can also occur rarely on the server. On this error, the server may or may not execute the operation requested.

Typically the client would retry the operation. Keep in mind that this may result in the operation being executed more than once on the server.

See: https://cloud.google.com/pubsub/docs/error-codes

There is talk of adding retry logic to the client but that hasn't been done yet.

There are some pretty good libraries out there for retrying.

• https://pypi.python.org/pypi/retrying
• https://pypi.python.org/pypi/backoff/1.3.1

[mwytock]

well, the previous behavior was that it would wait for awhile and then
return a response with no pulled messages, this seems more reasonable

if you do actually want to throw an exception here, you should throw
something from google.cloud.exceptions, not google.gax.errors.GaxError
which is an internal implementation detail that makes no sense from this
level API

On Thu, Oct 20, 2016 at 7:32 AM, Thomas Schultz notifications@github.com
wrote:

Thanks for reporting @mwytock https://github.com/mwytock!

Unless I'm missing some context, this seems like it could be the correct
reaction in certain scenarios?

The request did not complete in the time allocated. This can be caused by
network issues from the client to the server, and it can also occur rarely
on the server. On this error, the server may or may not execute the
operation requested.

Typically the client would retry the operation. Keep in mind that this may
result in the operation being executed more than once on the server.

See: https://cloud.google.com/pubsub/docs/error-codes

There is talk of adding retry logic to the client but that hasn't been
done yet.

There are some pretty good libraries out there for retrying.

• https://pypi.python.org/pypi/retrying
• https://pypi.python.org/pypi/backoff/1.3.1

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#2574 (comment),
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAkH1ouQER1LXEU4wFy0l3G9Nn_VYvfKks5q13uFgaJpZM4KcMNp
.

[daspecster]

When you say "before", do you remember what version of the library you were using for that behavior? I don't think much has changed with pubsub in a while so that would a place I could start looking.

Usually we catch and rethrow exceptions when the gRPC ones don't say much about what happened. In this case it actually seems like a decent message.

@dhermes @tseaver WDYT?

[mwytock]

in my case "before" was using a version that did not default to the grpc implementation 0.18.X

in my opinion its weird to have to deal with this exception in a fairly standard use case (subscription empty), but if this is the intended behavior so be it

[dhermes]

@mwytock This isn't the intended behavior. So far we've tried to catch gRPC errors and re-wrap them as standard ones from our google.cloud.exceptions. Thanks for bringing it to our attention.

FWIW, this would still have thrown an exception, since it's really just a timeout on the backend (though we don't yet have a GatewayTimeout / 504 exception).

Is this exception happening on a regular basis or just some of the time?

[daspecster]

My bad, I thought there were only special cases that we wanted to catch and reraise from gRPC.

[mwytock]

great, that makes sense

it seems to happen just about every time I call sub.pull() and there are no messages available in this subscription. im guessing whats happening behind the scenes is the rpc is sitting and waiting and hits the deadline before any messages arrive. this seemed to work more cleanly in the previous non-grpc world

for now, i just used the simple workaround

pulled = sub.pull(return_immediately=True)
if not pulled:
  time.sleep(args.pubsub_empty_delay)

this subscription has an ack deadline of 60 seconds, not sure if that effects setting of rpc deadlines, etc.

[daspecster]

@mwytock thanks for helping out with this!

I was able to merge in a fix via #2576.