PubSub Subscriber fatal error "Can not recv() on an RPC that has never been open()ed"

[dmsolow]

I'm running google-cloud-pubsub 0.37.2 on python 3.6.6. This code is running on the google cloud container OS. The code runs fine for days at a time, pulling messages from PubSub and processing them, but it occasionally crashes as follows:

First I see the following logging messages:

Call to retryable <bound method BidiRpc.recv of <google.cloud.pubsub_v1.subscriber._protocol.bidi.ResumableBidiRpc object at 0x7fba5c24b908>> caused Can not recv() on an RPC that has never been open()ed..
Observed non-recoverable stream error Can not recv() on an RPC that has never been open()ed.
Not retrying <bound method BidiRpc.recv of <google.cloud.pubsub_v1.subscriber._protocol.bidi.ResumableBidiRpc object at 0x7fba5c24b908>> due to Can not recv() on an RPC that has never been open()ed..
RPC termination has signaled streaming pull manager shutdown.
Stopping consumer.

Then I see this stack trace:

Thread-ConsumeBidirectionalStream caught unexpected exception Can not recv() on an RPC that has never been open()ed. and will exit.
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/bidi.py", line 491, in _thread_main
    response = self._bidi_rpc.recv()
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/bidi.py", line 404, in recv
    super(ResumableBidiRpc, self).recv)
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/bidi.py", line 393, in _recoverable
    raise exc
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/bidi.py", line 385, in _recoverable
    return method(*args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/bidi.py", line 258, in recv
    'Can not recv() on an RPC that has never been open()ed.')
ValueError: Can not recv() on an RPC that has never been open()ed."   

This is followed by the following logging messages:

Thread-ConsumeBidirectionalStream exiting
Stopping scheduler.
Stopping leaser.
Thread-LeaseMaintainer exiting.
Stopping dispatcher.
Exiting the QueueCallbackWorker.
Stopping heartbeater.
Thread-Heartbeater exiting.
Finished stopping manager.

After this point the application continues to run but it receives no new PubSub messages.

Please advise.

[theacodes]

Alright, this is the second instance I've seen of this bug so it warrants some investigation.

You can work around this in the meantime by catching the error (returned by subscribe_future.result()) and just re-subscribing.

[crwilcox]

@dmsolow, are there any logs leading up to this? I am curious if it shows an attempt to close the subscriber or attempts to recover.

[dmsolow]

@crwilcox Sorry for the delay, I was on vacation. I've attached additional CSV logs for context. The error occurs at 2018-09-02T19:06:49.088123503Z

pubsub_error.log

[theacodes]

Thanks, @dmsolow I'm trying to reproduce this now. This one is tough, as it doesn't seem to appear very often for us.