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

[saitej09]

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
    )

[plamut]

@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]

@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]

@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]

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]

@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]

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

[plamut]

@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]

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

[plamut]

@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]

@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 :-)