Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Observed non-terminating stream error 500 Received RST_STREAM with error code 2 #504

Closed
saitej09 opened this issue Sep 22, 2021 · 20 comments
Labels
api: pubsub Issues related to the googleapis/python-pubsub API. type: question Request for information or clarification. Not an issue.

Comments

@saitej09
Copy link

Hi

I am using google pubsub service with flow control mechanism. I get this error very often after processing few messages.

INFO 2021-09-22 12:56:13,932 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-22 12:56:13,933 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-22 12:56:13,934 google.api_core.bidi _reopen 487 : Re-established stream
INFO 2021-09-22 12:56:13,934 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-22 12:56:13,934 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]

I am using the following code for flow control. The service restarts randomly after say half an hour to one hour. Is there a solution to handle this error so that the service is not down for that half an hour to one hour period.

subscription_path = subscriber.subscription_path(project_id, subscription_id)
flow_control = pubsub_v1.types.FlowControl(max_messages=10)
streaming_pull_future = subscriber.subscribe(
        subscription_path, callback=callback_fn, flow_control=flow_control
    )

@product-auto-label product-auto-label bot added the api: pubsub Issues related to the googleapis/python-pubsub API. label Sep 22, 2021
@plamut plamut added the type: question Request for information or clarification. Not an issue. label Sep 23, 2021
@plamut
Copy link
Contributor

plamut commented Sep 23, 2021

@saitej09 Stream errors like this are expected, either due to random network glitches or when the server terminates a stream. In fact, streams always terminate with an error. From the documentation:

StreamingPull streams always close with a non-OK status. Note that, unlike in regular RPCs, the status here is simply an indication that the stream has been broken, not that requests are failing.

Terminating a stream by the server after half an hour or so is actually expected, this is to prevent the streams to be open indefinitely, should a client crash. Upon terminating, the clients are expected to re-establish the stream, which is exactly what happens:

INFO 2021-09-22 12:56:13,934 google.api_core.bidi _reopen 487 : Re-established stream

Even in the event that re-establishing the stream fails, the client will keep retrying (with an exponential backoff), thus client applications do not have to worry about this.

@saitej09
Copy link
Author

@plamut Thanks for your reply.
The stream is re-established after half an hour or so. During this period, the subscriber cannot reach the pubsub right? Is there a way to handle this ? Also, I observe this is happening a lot more often in the recent past (a week or so ..). Can I attribute a particular reason to this ?

Also, you mentioned about a backoff factor. Is it configurable and does that affect the half an hour or so black-out period ?

@plamut
Copy link
Contributor

plamut commented Sep 23, 2021

@saitej09 The stream is established (or at least should be) almost immediately after the server terminates it, and you should still be receiving messages. Or did you observe that you had not been receiving new messages for full 30 minutes? (the latter would be an actual issue that should be investigated.

Also, I observe this is happening a lot more often in the recent past (a week or so ..). Can I attribute a particular reason to this ?

I cannot think of anything from the top of my head. Did you perhaps update any dependencies, change any dependencies, vhanged the message load, or do any other changes to your system? If not or if those changes are minor, I can check with the backend people if they have noticed anything unusual in the metrics recently.

Also, you mentioned about a backoff factor. Is it configurable and does that affect the half an hour or so black-out period ?

I don't believe the exact call that initiates/reopens a streaming pull channel is exposed to the end users, but it should not, in principle affect this. A blackout period this long should not happen, but if understood correctly, you actually observe it often?

In other words, do you see the following messages being repeated in the logs over and over again for 30 minutes before a stream is finally re-established?

INFO 2021-09-22 12:56:13,932 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-22 12:56:13,933 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-22 12:56:13,934 google.api_core.bidi _reopen 487 : Re-established stream
...

It would also help if you could paste the output of $ pip freeze to see what library versions are installed on your system. Looking forward to it!

@saitej09
Copy link
Author

Or did you observe that you had not been receiving new messages for full 30 minutes? (the latter would be an actual issue that should be investigated.

Yes, I have observed that there are no incoming messages (new or repetitive) during this 30 min or so.

I see the errors in this manner.

INFO 2021-09-24 08:08:01,737 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 08:08:01,737 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 08:08:01,740 google.api_core.bidi _reopen 487 : Re-established stream
INFO 2021-09-24 08:08:01,740 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 08:08:01,740 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 08:43:01,884 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 08:43:01,885 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 08:43:01,886 google.api_core.bidi _reopen 487 : Re-established stream
INFO 2021-09-24 08:43:01,886 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 08:43:01,886 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 09:18:02,009 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 09:18:02,009 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 09:18:02,011 google.api_core.bidi _reopen 487 : Re-established stream
INFO 2021-09-24 09:18:02,011 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 09:18:02,011 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 09:53:02,070 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 09:53:02,071 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 09:53:02,072 google.api_core.bidi _reopen 487 : Re-established stream
INFO 2021-09-24 09:53:02,072 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 09:53:02,072 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 10:28:02,096 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 10:28:02,097 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 10:28:02,099 google.api_core.bidi _reopen 487 : Re-established stream
INFO 2021-09-24 10:28:02,099 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 10:28:02,099 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 11:03:02,290 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 11:03:02,290 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 11:03:02,292 google.api_core.bidi _reopen 487 : Re-established stream
INFO 2021-09-24 11:03:02,292 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 11:03:02,292 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 11:38:02,314 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 11:38:02,315 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 11:38:02,317 google.api_core.bidi _reopen 487 : Re-established stream
INFO 2021-09-24 11:38:02,317 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 11:38:02,317 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 12:13:02,435 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 12:13:02,436 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 12:13:02,437 google.api_core.bidi _reopen 487 : Re-established stream
INFO 2021-09-24 12:13:02,438 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 12:13:02,438 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 12:48:02,463 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 12:48:02,464 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 12:48:02,466 google.api_core.bidi _reopen 487 : Re-established stream
INFO 2021-09-24 12:48:02,466 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 12:48:02,466 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 13:23:02,634 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 13:23:02,634 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 13:23:02,636 google.api_core.bidi _reopen 487 : Re-established stream
INFO 2021-09-24 13:23:02,636 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 13:23:02,636 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 13:58:02,655 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 13:58:02,656 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 13:58:02,658 google.api_core.bidi _reopen 487 : Re-established stream
INFO 2021-09-24 13:58:02,658 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_terminate 685 : Observed non-terminating stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]
INFO 2021-09-24 13:58:02,658 google.cloud.pubsub_v1.subscriber._protocol.streaming_pull_manager _should_recover 663 : Observed recoverable stream error 503 The service was unable to fulfill your request. Please try again. [code=8a75]

@plamut
Copy link
Contributor

plamut commented Sep 27, 2021

@saitej09 Thanks for confirming. Assuming that publishing the messages works without issues, a 30-minute long "blackout" on the subscriber side is not expected behavior.

Periodically disconnecting and re-connecting is expected (every 35 minutes in this case), but it's not clear why the client stops receiving messages. Could you please post the library versions that you application uses?

In the meantime I also checked with the people on the backend and they suggested to file a support ticket at https://console.cloud.google.com/support/cases. Somebody can then examine the server logs of your project and see exactly what happens when the client tries to re-connect after the stream get terminated.

@saitej09
Copy link
Author

@plamut Thanks a lot ! I will create a support ticket and try to debug there.

@plamut
Copy link
Contributor

plamut commented Sep 28, 2021

@saitej09 Sounds good, fingers crossed. And if there's anything we could do on the client side to assist with debugging, please let me know.

@Tonow
Copy link

Tonow commented Nov 19, 2021

Hello @saitej09 @plamut
They is a solution to solve this issue ?
Cause I have the same trouble 😞

@plamut
Copy link
Contributor

plamut commented Nov 21, 2021

@Tonow To date we haven't heard back from the OP, unfortunately, but would you mind sharing the requested information? The OS and Python version, the output of $ pip freeze, the typical load in the application (i.e. the number of messages sent/received), and any other patterns in behavior that might have been observed.

In addition, a support ticked should be created at https://console.cloud.google.com/support/cases so that the backend people can examine the server logs to see if they can spot anything unusual.

All this can help with narrowing down the possible causes for this behavior, thanks!

@Tonow
Copy link

Tonow commented Nov 23, 2021

@plamut
yes it is easier when the question is detailed 👍
pip freeze :

astroid==2.8.6
backports.entry-points-selectable==1.1.1
bcrypt==3.2.0
cachetools==4.2.4
certifi==2021.10.8
cffi==1.15.0
cfgv==3.3.1
cftime==1.5.1.1
charset-normalizer==2.0.7
coverage==6.1.2
cryptography==36.0.0
decorator==5.1.0
distlib==0.3.3
filelock==3.4.0
google-api-core==2.2.2
google-auth==2.3.3
google-cloud-core==2.2.1
google-cloud-pubsub==2.9.0
google-cloud-storage==1.43.0
google-crc32c==1.3.0
google-resumable-media==2.1.0
googleapis-common-protos==1.53.0
grpc-google-iam-v1==0.12.3
grpcio==1.42.0
grpcio-status==1.42.0
h5py==3.6.0
identify==2.4.0
idna==3.3
influxdb==5.3.1
influxdb-client==1.23.0
invoke==1.6.0
isort==5.10.1
lazy-object-proxy==1.6.0
libcst==0.3.22
mccabe==0.6.1
msgpack==1.0.2
mypy-extensions==0.4.3
netCDF4==1.5.8
nodeenv==1.6.0
numpy==1.21.4
pandas==1.3.4
paramiko==2.8.0
platformdirs==2.4.0
pre-commit==2.15.0
proto-plus==1.19.8
protobuf==3.19.1
pvlib==0.9.0
pyasn1==0.4.8
pyasn1-modules==0.2.8
pycparser==2.21
pylint==2.11.1
PyNaCl==1.4.0
pysftp==0.2.9
python-dateutil==2.8.2
pytz==2021.3
PyYAML==6.0
requests==2.26.0
rsa==4.7.2
Rx==3.2.0
scipy==1.7.2
six==1.16.0
slack-sdk==3.11.2
steadysun-libbaseconnection==1.6.0
steadysun-libsolar==0.0.3
toml==0.10.2
typing-extensions==4.0.0
typing-inspect==0.7.1
urllib3==1.26.7
validators==0.18.2
virtualenv==20.10.0
wrapt==1.13.3
xarray==0.20.1

the code runs on GKE on a cluster version 1.20.10-gke.1600

uname -a :

Linux 91dd13b704e0 5.4.0-90-generic #101~18.04.1-Ubuntu SMP Fri Oct 22 09:25:04 UTC 2021 x86_64 GNU/Linux

The pubsub stream following this bucket https://console.cloud.google.com/marketplace/product/noaa-public/goes-16
projects/gcp-public-data---goes-16/topics/gcp-public-data-goes-16

Without any apparent incident, the pod disconnects from the stream, then seems to reconnect:

2021/11/23 03:09:36 AM INFO: Observed non-terminating stream error 500 Received RST_STREAM with error code 2
2021/11/23 03:09:36 AM INFO: Observed recoverable stream error 500 Received RST_STREAM with error code 2
2021/11/23 03:09:36 AM INFO: Re-established stream

However it does not process any message afterwards. However, it sends back this same error every half hour (normally there are messages on this thread every 10 minutes at most).

And these three logs loop every 30 min for hours until my pod is stopped because my node is preempted

Yes I will create a ticket on https://console.cloud.google.com/support/cases and link it to this issue :-)

@meredithslota
Copy link
Contributor

Internal support case was closed, closing this as well.

@diazidabagus
Copy link

Hi is it possible to ignore this logging messages? any params like verbose=false that will ignore the messages sent here?
Observed non-terminating stream error 500

@sls-cat
Copy link

sls-cat commented Apr 6, 2022

Is there any hints as to what causes this? Having an application go into infinite error scroll like this is not helpful. I would except a certain number of reconnect attempts and then failure, instead of an infinite look up reconnect attempts. This has been attempting reconnects for a week now.

INFO 2022-04-06 13:11:09 streaming_pull_manager.py:1030 Observed recoverable stream error 503 failed to connect to all addresses
INFO 2022-04-06 13:11:09 bidi.py:486 Re-established stream
INFO 2022-04-06 13:12:01 streaming_pull_manager.py:1052 Observed non-terminating stream error 503 Connection timed out
INFO 2022-04-06 13:12:01 streaming_pull_manager.py:1030 Observed recoverable stream error 503 Connection timed out
INFO 2022-04-06 13:12:01 bidi.py:486 Re-established stream
INFO 2022-04-06 13:14:32 streaming_pull_manager.py:1052 Observed non-terminating stream error 503 Connection timed out
INFO 2022-04-06 13:14:32 streaming_pull_manager.py:1030 Observed recoverable stream error 503 Connection timed out
INFO 2022-04-06 13:14:32 bidi.py:486 Re-established stream
INFO 2022-04-06 13:15:32 streaming_pull_manager.py:1052 Observed non-terminating stream error 503 Connection timed out
INFO 2022-04-06 13:15:32 streaming_pull_manager.py:1030 Observed recoverable stream error 503 Connection timed out
INFO 2022-04-06 13:15:32 bidi.py:486 Re-established stream
INFO 2022-04-06 13:16:42 streaming_pull_manager.py:1052 Observed non-terminating stream error 503 keepalive watchdog timeout
INFO 2022-04-06 13:16:42 streaming_pull_manager.py:1030 Observed recoverable stream error 503 keepalive watchdog timeout
INFO 2022-04-06 13:16:42 bidi.py:486 Re-established stream
INFO 2022-04-06 13:18:02 streaming_pull_manager.py:1052 Observed non-terminating stream error 503 Connection timed out
INFO 2022-04-06 13:18:02 streaming_pull_manager.py:1030 Observed recoverable stream error 503 Connection timed out
INFO 2022-04-06 13:18:02 bidi.py:486 Re-established stream
INFO 2022-04-06 13:19:31 streaming_pull_manager.py:1052 Observed non-terminating stream error 503 Connection timed out
INFO 2022-04-06 13:19:31 streaming_pull_manager.py:1030 Observed recoverable stream error 503 Connection timed out
INFO 2022-04-06 13:19:32 bidi.py:486 Re-established stream
INFO 2022-04-06 13:20:57 streaming_pull_manager.py:1052 Observed non-terminating stream error 503 keepalive watchdog timeout
INFO 2022-04-06 13:20:57 streaming_pull_manager.py:1030 Observed recoverable stream error 503 keepalive watchdog timeout
INFO 2022-04-06 13:20:57 bidi.py:486 Re-established stream
INFO 2022-04-06 13:21:50 streaming_pull_manager.py:1052 Observed non-terminating stream error 503 keepalive watchdog timeout
INFO 2022-04-06 13:21:50 streaming_pull_manager.py:1030 Observed recoverable stream error 503 keepalive watchdog timeout
INFO 2022-04-06 13:21:50 bidi.py:486 Re-established stream
INFO 2022-04-06 13:22:55 streaming_pull_manager.py:1052 Observed non-terminating stream error 503 keepalive watchdog timeout
INFO 2022-04-06 13:22:55 streaming_pull_manager.py:1030 Observed recoverable stream error 503 keepalive watchdog timeout
INFO 2022-04-06 13:22:55 bidi.py:486 Re-established stream
INFO 2022-04-06 13:24:20 streaming_pull_manager.py:1052 Observed non-terminating stream error 503 keepalive watchdog timeout
INFO 2022-04-06 13:24:20 streaming_pull_manager.py:1030 Observed recoverable stream error 503 keepalive watchdog timeout
INFO 2022-04-06 13:24:20 bidi.py:486 Re-established stream
INFO 2022-04-06 13:25:40 streaming_pull_manager.py:1052 Observed non-terminating stream error 503 failed to connect to all addresses
INFO 2022-04-06 13:25:40 streaming_pull_manager.py:1030 Observed recoverable stream error 503 failed to connect to all addresses
INFO 2022-04-06 13:25:40 bidi.py:486 Re-established stream
INFO 2022-04-06 13:26:53 streaming_pull_manager.py:1052 Observed non-terminating stream error 503 keepalive watchdog timeout
INFO 2022-04-06 13:26:53 streaming_pull_manager.py:1030 Observed recoverable stream error 503 keepalive watchdog timeout
INFO 2022-04-06 13:26:53 bidi.py:486 Re-established stream```

```astroid==2.9.3
attrs==21.4.0
box-pyvault==1.7.0
cachetools==4.2.4
certifi==2021.10.8
charset-normalizer==2.0.12
click==8.0.4
coverage[toml]==6.2
google-api-core[grpc]==2.7.1
google-api-python-client==2.41.0
google-auth==2.6.0
google-auth-httplib2==0.1.0
google-cloud-access-context-manager==0.1.10
google-cloud-asset==3.8.1
google-cloud-bigquery==2.34.2
google-cloud-core==2.2.3
google-cloud-org-policy==1.3.1
google-cloud-os-config==1.11.1
google-cloud-pubsub==2.11.0
google-crc32c==1.3.0
google-resumable-media==2.3.2
googleapis-common-protos[grpc]==1.56.0
grpc-google-iam-v1==0.12.3
grpcio==1.44.0
grpcio-status==1.44.0
httplib2==0.20.4
hvac==0.11.2
idna==3.3
importlib-metadata==4.8.3
iniconfig==1.1.1
isort==5.10.1
lazy-object-proxy==1.7.1
mccabe==0.6.1
mock==4.0.3
packaging==21.3
platformdirs==2.4.0
pluggy==1.0.0
proto-plus==1.20.3
protobuf==3.19.4
py==1.11.0
pyasn1==0.4.8
pyasn1-modules==0.2.8
pylint==2.12.2
pyparsing==3.0.7
pytest==7.0.1
pytest-cov==3.0.0
python-dateutil==2.8.2
requests==2.27.1
rsa==4.8
six==1.16.0
toml==0.10.2
tomli==1.2.3
typed-ast==1.5.2
typing-extensions==4.1.1
uritemplate==4.1.1
urllib3==1.26.9
wrapt==1.13.3
zipp==3.6.0

I see it started with this, which appears to have some issues in the SDK:

0 message_size 28611 ack_id U0RQBhYsXUZIUTcZCGhRDk9eIz81IChFEgggagktQlgeDwdcXHUHUQweJChjcztTQAdWT1F3XlwdB2h0bG251Ke7RF9BcWlaEQYETVF_W1keDG1V
WF3zkbe42uXDQ3BmK7-H7_FIf7qtx9ZvZiA9WxJLLD5-NSNFQV5AEkw-FkRJUytDCypYEU4EISE-MD5F) at 2022-03-31 23:24:15.
INFO 2022-03-31 23:24:43 streaming_pull_manager.py:1052 Observed non-terminating stream error 503 Connection timed out
INFO 2022-03-31 23:24:43 streaming_pull_manager.py:1030 Observed recoverable stream error 503 Connection timed out
INFO 2022-03-31 23:24:43 bidi.py:486 Re-established stream
INFO 2022-03-31 23:26:03 streaming_pull_manager.py:1052 Observed non-terminating stream error 503 failed to connect to all addresses
ERROR 2022-03-31 23:26:03 helper_threads.py:120 Error in queue callback worker: 'NoneType' object has no attribute 'set_exception'
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/google/api_core/grpc_helpers.py", line 66, in error_remapped_callable
    return callable_(*args, **kwargs)
  File "/usr/local/lib64/python3.6/site-packages/grpc/_channel.py", line 946, in __call__
    return _end_unary_response_blocking(state, call, False, None)
  File "/usr/local/lib64/python3.6/site-packages/grpc/_channel.py", line 849, in _end_unary_response_blocking
    raise _InactiveRpcError(state)
grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with:
        status = StatusCode.UNAVAILABLE
        details = "failed to connect to all addresses"
        debug_error_string = "{"created":"@1648794363.414576733","description":"Failed to pick subchannel","file":"src/core/ext/filters/clie
nt_channel/client_channel.cc","file_line":3128,"referenced_errors":[{"created":"@1648794363.414575083","description":"failed to connect to all addresses","file":"src/core/lib/transport/error_utils.cc","file_line":163,"grpc_status":14}]}"
>

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/google/api_core/retry.py", line 190, in retry_target
    return target()
  File "/usr/local/lib/python3.6/site-packages/google/api_core/grpc_helpers.py", line 68, in error_remapped_callable
    raise exceptions.from_grpc_error(exc) from exc
google.api_core.exceptions.ServiceUnavailable: 503 failed to connect to all addresses

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 589, in send_unary_ack
    self._client.acknowledge(subscription=self._subscription, ack_ids=ack_ids)
  File "/usr/local/lib/python3.6/site-packages/google/pubsub_v1/services/subscriber/client.py", line 1201, in acknowledge
    request, retry=retry, timeout=timeout, metadata=metadata,
  File "/usr/local/lib/python3.6/site-packages/google/api_core/gapic_v1/method.py", line 154, in __call__
    return wrapped_func(*args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/google/api_core/retry.py", line 288, in retry_wrapped_func
    on_error=on_error,
  File "/usr/local/lib/python3.6/site-packages/google/api_core/retry.py", line 210, in retry_target
    ) from last_exc
google.api_core.exceptions.RetryError: Deadline of 60.0s exceeded while calling target function, last exception: 503 failed to connect to all addresses

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/helper_threads.py", line 118, in __call__
    self._callback(items)
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/dispatcher.py", line 159, in dispatch_callback
    self.ack(ack_requests)
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/dispatcher.py", line 192, in ack
    ack_reqs_dict=ack_reqs_dict,
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 604, in send_unary_ack
    _process_requests(status, ack_reqs_dict, None)
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 204, in _process_requests
    future.set_exception(exc)
AttributeError: 'NoneType' object has no attribute 'set_exception'
INFO 2022-03-31 23:26:03 streaming_pull_manager.py:1030 Observed recoverable stream error 503 failed to connect to all addresses
ERROR 2022-03-31 23:26:03 bidi.py:673 Thread-ConsumeBidirectionalStream caught unexpected exception 'NoneType' object has no attribute 'set_exception' and will exit.
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/google/api_core/grpc_helpers.py", line 66, in error_remapped_callable
    return callable_(*args, **kwargs)
  File "/usr/local/lib64/python3.6/site-packages/grpc/_channel.py", line 946, in __call__
    return _end_unary_response_blocking(state, call, False, None)
  File "/usr/local/lib64/python3.6/site-packages/grpc/_channel.py", line 849, in _end_unary_response_blocking
    raise _InactiveRpcError(state)
grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with:
        status = StatusCode.UNAVAILABLE
        details = "failed to connect to all addresses"
        debug_error_string = "{"created":"@1648794363.414594016","description":"Failed to pick subchannel","file":"src/core/ext/filters/client_channel/client_channel.cc","file_line":3128,"referenced_errors":[{"created":"@1648794363.414592880","description":"failed to connect to all addresses","file":"src/core/lib/transport/error_utils.cc","file_line":163,"grpc_status":14}]}"
>

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/google/api_core/retry.py", line 190, in retry_target
    return target()
  File "/usr/local/lib/python3.6/site-packages/google/api_core/grpc_helpers.py", line 68, in error_remapped_callable
    raise exceptions.from_grpc_error(exc) from exc
google.api_core.exceptions.ServiceUnavailable: 503 failed to connect to all addresses

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 644, in send_unary_modack
    ack_deadline_seconds=deadline,
  File "/usr/local/lib/python3.6/site-packages/google/pubsub_v1/services/subscriber/client.py", line 1098, in modify_ack_deadline
    request, retry=retry, timeout=timeout, metadata=metadata,
  File "/usr/local/lib/python3.6/site-packages/google/api_core/gapic_v1/method.py", line 154, in __call__
    return wrapped_func(*args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/google/api_core/retry.py", line 288, in retry_wrapped_func
    on_error=on_error,
  File "/usr/local/lib/python3.6/site-packages/google/api_core/retry.py", line 210, in retry_target
    ) from last_exc
google.api_core.exceptions.RetryError: Deadline of 60.0s exceeded while calling target function, last exception: 503 failed to connect to all addresses

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/google/api_core/bidi.py", line 657, in _thread_main
    self._on_response(response)
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 986, in _on_response
    self._send_lease_modacks(ack_id_gen, self.ack_deadline)
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 932, in _send_lease_modacks
    self._dispatcher.modify_ack_deadline(items)
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/dispatcher.py", line 295, in modify_ack_deadline
    ack_reqs_dict=ack_reqs_dict,
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 660, in send_unary_modack
    _process_requests(status, ack_reqs_dict, None)
  File "/usr/local/lib/python3.6/site-packages/google/cloud/pubsub_v1/subscriber/_protocol/streaming_pull_manager.py", line 204, in _process_requests
    future.set_exception(exc)
AttributeError: 'NoneType' object has no attribute 'set_exception'
INFO 2022-03-31 23:26:03 bidi.py:486 Re-established stream
INFO 2022-03-31 23:26:03 bidi.py:676 Thread-ConsumeBidirectionalStream exiting

@meredithslota
Copy link
Contributor

meredithslota commented Apr 6, 2022

@sls-cat I'll reopen this issue and see if someone can address the issue.

@acocuzzo
Copy link
Contributor

acocuzzo commented Apr 8, 2022

@sls-cat I believe your issue was caused by a bug, which was fixed in version 2.12. Please update, and let me know if that fixes your issue. Thanks!

@Tonow
Copy link

Tonow commented May 23, 2022

@acocuzzo
Copy link
Contributor

It was PR #626.

@gzamb
Copy link

gzamb commented Jun 6, 2022

I'm seeing the same thing as @sls-cat. Here are my dependencies:

Package                           Version
--------------------------------- ---------
astroid                           2.8.2
attrs                             21.2.0
backports.entry-points-selectable 1.1.0
bitarray                          2.3.4
black                             21.9b0
CacheControl                      0.12.11
cachetools                        4.2.4
cachy                             0.3.0
certifi                           2021.10.8
cfgv                              3.3.1
charset-normalizer                2.0.7
cleo                              0.8.1
click                             8.0.3
clikit                            0.6.2
coverage                          6.0.2
crashtest                         0.3.1
datadog                           0.42.0
ddtrace                           0.54.0
dependency-injector               4.36.2
distlib                           0.3.3
dotenv-cli                        2.2.0
filelock                          3.3.0
google-api-core                   2.7.3
google-auth                       2.3.0
google-cloud-bigquery             3.0.1
google-cloud-bigquery-storage     2.13.1
google-cloud-core                 2.1.0
google-cloud-pubsub               2.12.1
google-cloud-spanner              3.11.1
google-crc32c                     1.3.0
google-resumable-media            2.0.3
googleapis-common-protos          1.53.0
grpc-google-iam-v1                0.12.3
grpcio                            1.46.3
grpcio-status                     1.41.0
html5lib                          1.1
httpretty                         1.1.4
identify                          2.3.0
idna                              3.2
importlib-metadata                4.11.4
iniconfig                         1.1.1
isort                             5.9.3
keyring                           23.5.1
lazy-object-proxy                 1.6.0
lockfile                          0.12.2
mccabe                            0.6.1
msgpack                           1.0.4
mypy-extensions                   0.4.3
nodeenv                           1.6.0
numpy                             1.22.3
packaging                         21.0
pastel                            0.2.1
pathspec                          0.9.0
pexpect                           4.8.0
pip                               22.1.2
pkginfo                           1.8.2
platformdirs                      2.4.0
pluggy                            1.0.0
poetry                            1.1.13
poetry-core                       1.0.8
powlet                            2.10.1
pre-commit                        2.15.0
proto-plus                        1.19.5
protobuf                          3.18.1
ptyprocess                        0.7.0
py                                1.10.0
pyarrow                           7.0.0
pyasn1                            0.4.8
pyasn1-modules                    0.2.8
pylev                             1.4.0
pylint                            2.11.1
pyparsing                         2.4.7
pytest                            6.2.5
pytest-cov                        2.12.1
pytest-mock                       3.6.1
python-dateutil                   2.8.2
python-dotenv                     0.20.0
python-json-logger                2.0.2
PyYAML                            5.4.1
regex                             2021.10.8
requests                          2.26.0
requests-toolbelt                 0.9.1
rsa                               4.7.2
setuptools                        62.1.0
shellingham                       1.4.0
six                               1.16.0
sqlparse                          0.4.2
tenacity                          8.0.1
toml                              0.10.2
tomli                             1.2.1
tomlkit                           0.11.0
typing-extensions                 3.10.0.2
urllib3                           1.26.7
virtualenv                        20.8.1
webencodings                      0.5.1
wheel                             0.37.1
wrapt                             1.12.1
zipp                              3.8.0

I was previously on v2.8 on python3.9 and it worked fine.

@acocuzzo
Copy link
Contributor

acocuzzo commented Sep 7, 2022

@gzamb Are you able to attach the errors you are seeing?

@acocuzzo
Copy link
Contributor

Creating new issue for reference, as these are different errors: #785

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
api: pubsub Issues related to the googleapis/python-pubsub API. type: question Request for information or clarification. Not an issue.
Projects
None yet
Development

No branches or pull requests

8 participants