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
PubSub Subscriber with StreamingPull Suddenly Stops Regularly #11793
Comments
Can you please share a minimal but complete project that would reproduce the problem? A console application should be fine. Note I understand your theory requires something specific to happen to trigger the issue, so I understand this repro project won't be able to consistently reproduce the problem, that's fine, still I'd expect it would reproduce it if we run it long enough. We need to see exactly how your code looks like, for instance, you mention |
my apologies, I meant StartAsync. Will follow up with a sample console app. |
Thanks for the code and the detailed explanation. One reamining question is which Google.Cloud.PubSub.V1 version are you using, exactly. I'll try to get to this later today or tomorrow. |
3.7.0 Thanks! We deployed the change to OrderingKey yesterday, usually takes a day to see the StreamingPull drop off. Will be checking for the remainder of the week to see if it follows the same pattern as before. |
It seems we are still in the same situation even after changing the OrderingKey to file prefix "FileTypeA", "FileTypeB", ... instead of "FileTypeA_20240228" "FileTypeA_20240229", "FileTypeB_20240228", "FileTypeB_20240229", ... Every time the daily batch messages are processed (approx 9 individual files per day with 5 different file prefixes, originating from a batch of files uploaded to bucket), there are fewer open streaming pulls until eventually they stop altogether. If it helps, some of the message processing requires a ModifyAckDeadline due to taking longer than 10 mins. Perhaps this is part of the problem, perhaps not. |
Thanks for the extra info. I'll take a look as soon as I can but just for expectations it will probably be early next week. |
Assigning to @jskeet as he's more familiar with this library than I am. |
Okay, I'm looking into this now - I'm afraid my experience with diagnosing Pub/Sub issues is that there'll be a lot of back and forth with various questions and tests before we get to the root problem. Thanks so much for all the info you've already provided. I can explain one thing off the bat: the reason that Now, to understand your situation a bit better:
All of this is just trying to play divide-and-conquer at the moment (and giving me enough information to reproduce the issue myself, which will massively reduce the back-and-forth). I don't have any concrete ideas about what's happening at the moment - but if I can reproduce the issue myself, I can easily add a load of logging etc. I'm going to try a simple repro to start with of just starting a single client on my Windows box, using the same topic configuration that you've got, and occasionally adding messages to it, with a mixture of "needs modify ack deadline" and "ack quickly". |
Okay, my simplest tests didn't show anything - which is pretty much what I expected. I'll try leaving the code running for multiple hours (if I can remember not to shut my laptop down!) before moving onto the next scenarios... |
Nearly 24 hours later, the subscriber is still running fine, and the number of open streaming pull requests is stable (goes up and down a bit, as expected, but returns to the right level). I've sent large and small batches of messages, with a mixture of different simulated processing times. No joy reproducing the problem yet :( (I'll stop this test now, as it's not getting anywhere.) |
Dropping in to add a very similar case we're encountering. We've got a few .NET apps on GKE that use the Pub/Sub queues. They're fairly high-volume queues - processing ~110k messages a day, peaking at around 3-4k messages an hour. It works fine on weekdays, but on weekends the number of messages published drops down a lot and we might get 1-2 an hour. We recently updated the PubSub NuGet package from So far our workaround is to just restart it, but we are looking at something more automated if we can't land on a fix in the upstream library. I hope this additional context might help with determining the cause of the issue. |
@Mihier-Roy: Are you able to reproduce the issue outside GKE? Given the mention of Docker boundaries in the linked NodeJS issue, I'm wondering whether I might be able to reproduce this in a "simple" Docker container. (Rather than having to deploy to GKE.) Will give it a try. Any more information you can provide would be really useful - see my earlier comments for the sort of thing I'm interested in. (If you could let us know your topic configuration too, that'd be great. Things like message ordering and exactly-once delivery have some interesting effects in terms of how the clients behave.) |
@jskeet: I haven't tried to re-produce outside of GKE just yet, but I'll take a stab at it today/tomorrow! I hope it's something we can reproduce on a Docker container. Some additional info:
As for topic configuration:
|
Getting a break at last from the day-to-day to respond @jskeet - your name is familiar, I think I've read your writing or watched some videos in the past. Anyhow, here's some info you requested and some findings of our own: We're definitely running in linux containers with .NET 6 runtime. mcr.microsoft.com/dotnet/aspnet:6.0 in fact. Thanks for clarifying about the Build vs Run context for the cancellation token, it seems relevant in our workaround. As we poured over the code, that token was quite difficult to track down. There are many cancellation tokens in play and tokens created from others IIRC (it was many lines of code ago). We found a workaround that seems stable. In a shared library, we've had a method that sets up the subscriber.
Previously:
Because if the process was being shut down gracefully - during deployment, for example - we'd want the subscriber to shut down gracefully as well. We now have the following implementation in which we no longer pass the ambient cancellationToken to BuildAsync.
However, since StartAsync doesn't take a cancellation token and we're awaiting, there doesn't seem to be a way to tell the subscriber client to stop. Our consumer is a BackgroundService
Background service is registered as a Singleton service
As I said, this is in a library that we use for several services to wire up subscribers so it uses generics. A more concrete implementation might be easier to debug. Our fix works, so...I think what was happening is this: Since we were passing the I'm thinking something inside somewhere was switching that stoppingToken.IsCancellationRequested == true and our re-subscribe loop was opened causing it to stop altogether. This is speculation on my part, but it led to a solution that has been working for some time now. However... something isn't quite right with this scenario. What's causing it to stop? This single change to NOT pass that token into BuildAsync fixed the problem. one error was logged recently which may (or not) be related, this was after our fix was in place. We don't retain logs long enough to have any from before our fix.
|
@philvmx1: Your new code is still somewhat confusing. Firstly, the cancellation token here is pointless: var subscriberCancellationToken = new CancellationToken();
var subscriber = await subscriberClientBuilder.BuildAsync(subscriberCancellationToken); That's just equivalent to not passing in a cancellation token: var subscriber = await subscriberClientBuilder.BuildAsync(); Secondly, this comment is pretty misleading in its current location: // DO NOT USE THE CANCELLATION TOKEN THAT IS PASSED INTO THIS METHOD.
// We need a new cancellation token because the SubscriberClient can cancel the token itself. If the
// SubscriberClient cancels, we want to restart the subscription. The caller of ProcessMessages should re-invoke this
// method when it completes. It looks like you're talking about the cancellation token passed into
The task returned by If you want a kind of Note that in your original code, when you were passing |
@philvmx1: Separately, regarding this:
That looks like it could very well be related. That certainly looks like it's a single channel failing - which would then (if I'm reading the code correctly) stop the whole Of course, that just means that the next question is why you're seeing that exception. That's where it may be GKE-specific. I've tried a long-running task in plain Docker (not running on GCP) and it's working fine for me. I'd still be really interested in knowing whether you can reproduce the error at all when not running in GKE. Additionally, if you're collecting metrics about when you're restarting the |
@jskeet I realized that the comment is not correct now that you've cleared up that the cancellation token in BuildAsync is not passed to the built client. It doesn't quite explain why it seems to have solve our problem. There must be something else. I'll look closely if anything else changed. What I can't quite understand is how the client doesn't reconnect on its own after the other side hangs up.Or if it can't, why it wouldn't throw, in which case we would catch, log an error (which we never did see in the logs or this would have been much clearer to us) and StartAsync again - even in the old code. |
I believe that's what it is doing, effectively, by making the task returned by I would expect errors like this to usually indicate a fatal problem - something we wouldn't want to just retry, or at least not for long. (It's possible that there's already retry going on, although we normally don't retry for streaming calls.) If the application wants to retry the whole subscription, that's up to the app (and it sounds like you're doing that). It's hard to say anything more until we can reproduce the failure though. |
If StartAsync completed in any state, we should expect to see the Warning logged at the end of the following (our log level is >= Warning).
|
So how did you capture the log you included in #11793 (comment)? I'd assumed that was already from awaiting StartAsync. Note that the code you've shown above wouldn't log a warning if Rather than getting snippets of code in various places, I'd really like to go back to a minimal but complete example which actually demonstrates the problem. It's not clear to me what you observed with the code in #11793 (comment). Did you actually run that code and see the problem, or was it just meant to be sample code to show how you set things up? (It's really important that we end up with shared code which does definitely demonstrate the problem.) |
Error should have been logged in the BackgroundWorker in #11793 (comment) via Understood about the working sample, I am working on creating something that models the problem with much less abstraction. I do have test environments to run them in. What I don't have is a lot of dedicated time for this since I'm running a project with a fixed deadline. So I have to squeeze in time to try things, build isolated test code, and dig for additional information. Digging into metrics in DataDog, found that each GRPC POST last 15 minutes until error. Interestingly, the number of errors tapers off over time. As does the number of requests. minimal problem model code I have so far:
csproj
|
@amanda-tarafa it's gcloud auth application-default login locally. They probably should expire in that case. |
In GKE as well? Can you show how you are initializing the clients in both environments, basically what, if any, credentials are you passing to the |
@amanda-tarafa We're using service credentials in GKE. 99% sure this was a "locally debugging using dev credentials" issue only and not an issue in GKE. As I mentioned, we didn't see any log entries in prod. |
Ok, my point was then that you don't need to worry about tokens expiring in GKE, those will be refreshed automatically for you is you are using explicit service account credentials or default account credentials. I'm also surprised that you have to re-authenticate locally when using |
@amanda-tarafa I'm creating the client using the code shared in an above comment. look for |
@philvmx1 I also think the token expiring is not related to your issues, I simply wante to address your previous comment:
If you are ever ready to look into why you need to re-authenticate locally, feel free to create a separate issue. |
I was able to repro this issue from local process to GCP subscription. I kept the subscriber program running over the weekend. It logged the following message over and over again, so it looks like it's connecting.
I published a message and waited, but it did not get picked up for processing by the streaming pull. Then I published another, same thing. They're sitting unacked. No open streaming pull requests since March 16. |
@philvmx1: Really glad we've been able to reproduce locally. Do you still have the logs, and are you able to show more of the lines (e.g. about 30 of them)? I'd like to get a sense of the timing. (I'm also setting ClientCount=1 in the builder in my current tests, to try to make the logging simpler to understand.) Also, just to go back to auth briefly - what auth were you using this time? I've got a sneaking suspicion about this, but I'm going to run some tests locally to confirm. One thing I do want to do is add more diagnostics to the library - now that we've got |
I've made some potential progress, but I've got an odd situation in terms of credentials now which I don't think is due to the Pub/Sub library itself (I'm seeing invalid JWT grants). However, I have seen a situation where a subscriber appears to start but never makes progress. It's a bit of a mess at the moment, but I'm hopeful that by the end of the day we'll have more progress. |
Okay, I know what was odd about the credentials: I had a service account key that had expired. I can now reproduce four different situations:
My next step will be to try the same code with Compute credentials (which admittedly might be slightly different in GKE than other environments, but it'll be good to at least see). I'll definitely be working on adding logging into SubscriberClient and PublisherClient. (Admittedly the log levels to use end up being slightly tricky to decide - if the library is going to "silently" retry, should we actually be logging an error, or just debug?) Additionally, we need to consider a retry policy that doesn't keep going forever. Now, what I don't know yet is whether this is the situation you're facing. Please could you let me know:
|
I've just tried with a Compute credential which is bogus in some way (it's not entirely clear how, but that's a different matter) - and again, we ended up with an Internal status code which was retried forever. So this could indeed be what you're seeing in GKE. |
So token stops refreshing for whatever reason, pull thinks it's working but it's actually failing silently forever. May or may not be the same issue in prod, but who knows. I'll see if there was any change to our credentials between the last time it failed there and when it started seemingly working again...although since the # of open pulls keeps dropping every day nearly at the 24 hour mark (token lifetime is how long again? ;) ), I'm thinking it's fragile at best. I don't fully understand the question "What credentials..." but I'll give answering a try anyway. Locally, I'm logging in with my own credentials using NOTE: I also do realized the removed was from earlier in the day (AM not PM) |
here we go... IAM metrics for the SA. fetch consumed_api |
So in prod, are you doing anything to authenticate, or just using the default credentials for the cluster? (I suspect the latter - basically unless you've got a service account JSON file somewhere.) Will talk with Amanda about this. I think we may well be onto something. (It could be a red herring in the end of course.) In terms of "what kind of credentials" there are three different types I can see at play here:
Then there's the matter of whether token exchange is involved or self-signed JWTs, but that's a second order. To clarify this:
I believe it actually knows it's failing, but just retries with exponential backoff (30s max) - but it retries forever rather than eventually failing, which is probably a mistake. I've merged some logging - I'll chat with Amanda, but I suspect we'll be able to release a beta (or patch) tomorrow which will clarify things. |
#12160 will publish version 3.10.1 of Google.Cloud.PubSub.V1 - the only change is the addition of logging in PublisherClient and SubscriberClient. The release should be complete and the package published in around an hour. If you're able to test that version both locally and in GKE and collect any logs (you'll need to specify a |
Try this log file. I started the debug session from zero. I remember something when I was first starting to debug with this test program: I started it, but it did not pull messages. I consulted a colleague. He reminded me to auth. Now I see exactly why it was failing - the lib keeps retrying auth without throwing. To me, it looks like it was running but inside it was silently failing over and over again. In GKE, we create a K8s service account for each service. Then bind that to an IAM role. I'll see what I can do to get something running with Trace in one of our test envs and post some logs from that as well. All done via Terraform. |
Firstly - thanks for jumping on this, that's really useful. It'll be really interesting to see if we get the same sort of pattern on GKE - it's unlikely to be the same auth issue, but if it's an auth issue that surfaces as an internal error, that would explain a lot. (And if something else is going wrong, hopefully the logs will show that instead.) |
@Mihier-Roy: You may want to upgrade to 3.10.1 and specify a logger as well, to see if that helps to pin down the issue for you. |
@jskeet I'm working on getting something running in a dev env to model the problem. We don't see a decline in open streaming pulls in our dev/test envs today - only in prod where the worker is busy around the same every day slogging through files that it pulls down from a bucket. First pass at modeling this will be a Task.Delay that's controlled by a message attribute. No CPU, Memory pressure, Get object from bucket calls, or API calls between microservices in the GKE cluster, additional logging, etc that we would normally have. I'll be out until next week so I won't have findings to post until then. Will ask a colleague to check up and post if anything interesting comes up in the meantime. |
@philvmx1: Any updates with more logging? |
@jskeet I had it running in a dev env until Friday when trunk deployed over it. Logging in the dev env showed a lot of detail but no issues. Even then, it didn't model prod very well since we weren't doing any daily file drops there. We haven't seen the issue in production since Feb 21, which has been good for us but not for understanding the issue at hand. Not understanding what caused the instability makes it difficult to accept that it's stable going forward. At the moment, we don't have any other information. The only notable change RE Pub/Sub is going from OrderingKey FileName (FileType__.txt) to OrderingKey FilePrefix (FileType). That made its way into prod on Feb 29. Is there something in the OrderingKey algo that could cause streaming pulls to cease pulling as the number of OrderingKeys increases? I made some prelim tests on that theory in dev but I used random ordering keys not TestFile_20240101_1010.txt, TestFile_20240102_1001.txt, ... |
No, I wouldn't expect so - although I can't say I'm an expert on the precise details of all the options in Pub/Sub. I'm still hopeful that this was really due to the perpetual retry loop we can currently get into if auth fails with an error of "internal" (which we're still discussing internally, in terms of the best fix). |
Any more information on this? I'm still hopeful that this is due to the perpetual retry on certain types of auth failure - which we're tracking internally. |
This is the first part of addressing googleapis#11793. The next step will be to allow a custom retry predicate to be provided, which can examine the previous exceptions etc, with a default which will fail after a certain time, or after multiple internal failures for example. (The list of exceptions here could easily turn into a map of from "status code to number of exceptions".) We may also want to implement something similar for Publisher operations, but that can be done separately.
This is the first part of addressing googleapis#11793. The next step will be to allow a custom retry predicate to be provided, which can examine the previous exceptions etc, with a default which will fail after a certain time, or after multiple internal failures for example. (The list of exceptions here could easily turn into a map of from "status code to number of exceptions".) We may also want to implement something similar for Publisher operations, but that can be done separately.
This is the first part of addressing googleapis#11793. The next step will be to allow a custom retry predicate to be provided, which can examine the previous exceptions etc, with a default which will fail after a certain time, or after multiple internal failures for example. (The list of exceptions here could easily turn into a map of from "status code to number of exceptions".) We may also want to implement something similar for Publisher operations, but that can be done separately.
This is the first part of addressing #11793. The next step will be to allow a custom retry predicate to be provided, which can examine the previous exceptions etc, with a default which will fail after a certain time, or after multiple internal failures for example. (The list of exceptions here could easily turn into a map of from "status code to number of exceptions".) We may also want to implement something similar for Publisher operations, but that can be done separately.
This is a consistent problem for us and many others. My theory is that the server side hangs up in the middle of a keepalive and RpcException has IsRpcCancellation on the line linked below which shuts down the subscription.
Since we expect StartNew to continue to run and RPC connection issues to be resolved, this causes our workers to stop silently leaving us dead in the water.
google-cloud-dotnet/apis/Google.Cloud.PubSub.V1/Google.Cloud.PubSub.V1/SubscriberClientImpl.SingleChannel.cs
Line 232 in 2e2659b
The text was updated successfully, but these errors were encountered: