Nodejs-pubsub: All acks are expired after 30 min of activity with v0.23.0+

[dinvlad]

Environment details

• Hardware: on-prem 8-core compute node
• OS: RHEL 6.9
• Node.js version: 8.11.3
• npm version: 6.4.0
• @google-cloud/pubsub 0.23.0-0.24.1:

Steps to reproduce

1. Publish a moderate number of messages to a topic (~4k in our case)
2. Use a single subscriber that processes each message within 1-2 min, e.g. with the following code:

const subscription = pubSub.subscription(SUBSCRIPTION_NAME, {
  flowControl: {
    maxMessages: 2,
    allowExcessMessages: false,
  },
});
subscription.on("message", ({ ack }) => {
  setTimeout(ack, 60000 * 2 * Math.random());
});
subscription.on("error", console.error);

1. After ~30 min of churning through messages, Stackdriver shows that:
   
   
   
   • num_undelivered_messages stops going down
   
   
   • pull_ack_message_operation_count marks every message ack as expired
     
     
   
   
   • streaming_pull_message_operation_count shows that 10-min pull interval stops.
     
     
   
   

As a net result, we can't seem to ack any more messages and have to restart the subscriber.

We varied settings like flowControl.maxMessages (1-4) and ackDeadline (10, 300, 7200, 720000) and that didn't seem to have an effect.

Downgrading to 0.22.2 seems to resolve this issue. We still get occasional expired acks, but not in 100% of cases.

Thanks!

[ajaaym]

@dinvlad As its turns out its not an grpc issue anymore. Client window size is approximately 4mb, server sends all 4k messages and waits for new message for around 10 min. Since there are no new message it seems that its restarting rpc on server side and delivering all unacked message again since there is a empty window. This happens for 3 more time until it gives up and closes the stream(closing rpc). To get new message pubsub client needs to restart rpc which doesn't happen until all message in buffer gets processed. Your setting of maxMessages: 2 will have around 20 messages in buffer. Each message taking 1-2 min to process, will take lot of time for that 20 message to process. Until all this message is processed it will not restart rpc as end/status event doesn't get emitted.

Below setting will help you to resolve this issue. I tried with this setting for like hour and it seemed to work fine.

const pubsub = new PubSub(
  {
    'grpc.http2.lookahead_bytes': 4096, // big enough to hold 10 * avg message size, min 128
    'grpc.http2.bdp_probe': 0
  }
);
  const subscription = pubsub.subscription(subscriptionName, {
    flowControl: {
      maxMessages: 1, // 1 here buffers 10 message internally
      allowExcessMessages: false
    },
  });

[rossj]

I've been running into this issue consistently for the past 3 weeks (as long as we've been trying to seriously use Pub/Sub in production). I've seen it with client versions 0.25 through the latest 0.28.1.

My subscribers can sit quite happily for days when there are not many messages, but as soon as there is a burst and the subscribers get behind, things stop acking after about 1/2 hour and I have to force a restart of my subscribers. This occurs despite the subscribers appearing healthy and processing at the normal rate).

I'm using the above recommended settings from @ajaaym, along with:
streamingOptions: { maxStreams: 1 }
I also have an error handler on the subscription which will exit the process, and it's not being triggered.

[callmehiphop]

@rossj could you share any details about your environment? Are you running on GKE, GCE, etc.? About how many messages are in your queue once the subscribers stop responding? Any other notable happenings like high memory/cpu usage?

[callmehiphop]

In the past we've seen backend issues with underlying streams becoming non-responsive in certain environments if they are kept open for too long. Without a solid reproduction case I can't really say if that is what is happening here, but right now it's my best guess.

I created a branch (https://github.com/callmehiphop/nodejs-pubsub/tree/dg--468) to allow setting a pullDeadline option. This should allow you to specify how long the internal streams stay open for. If anyone has the bandwidth to test this change, I'd be interested to see what the results are when pullDeadline is set to 10 minutes (or less).

const subscription = topic.subscription('my-sub', {
  streamingOptions: {pullDeadline: 60000 * 10}
});

[rossj]

We have multiple topics that are part of a processing workflow / pipeline. I've seen this behavior on a topic with a single subscriber running on GCE, and with other topics that have subscribers running on GKE with horizontal pod autoscalers tied to the undelivered message count.

Below are some Stackdriver graphs from today which I think show the situation pretty well. Essentially there was a steady stream of incoming messages that started around 1:30. Around 2, the expire rate jumps up, but messages are still being processed because there are healthy, more recent subscribers that have been brought online by the HPA.

The switch between ACKing and expiration is a bit more obvious later on, when the replicaset is at its max (5) and all of the subscribers are being restarted more or less in unison. I forced a revision / restart of the subscriber pods around 2:45, 4:15, and 5:05.

I've checked the node statistics and pod logs during these periods of non-acking, and everything seems normal and healthy. The subscribers are still receiving and handling messages at the normal rate.

[slavoroi]

Running Those fixes locally didn't help us (0.22.2 , the flowcontrol/streamingOptions/ updating to c1da94980b595024d0954f00769e7572279c62da commit or master-https://github.com/googleapis/nodejs-pubsub/pull/556), we got some messages on the server start and from than on nothing.
Maybe the distant servers has to be updated in order for it to work?

[bcoe]

@dinvlad @rossj @ajaaym are you still running into the original issue?

I'm wondering if there's a chance this issue potentially needs to be broken into a few more specific issues (if @callmehiphop's patch fixed the bug for some folks).

[slavoroi]

The issue wasnt solved for us.The nodejs services that use dozens of messages are working fine, but whenever we send thousands of messages in a mettar of seconds subscription.on stops working.
Our workaround is calling pull every few seconds with a few threads (does work).

[dinvlad]

We haven't had enough load of messages lately, but I'd be curious to hear about any improvements.

[rossj]

Still an issue for me. Things have been working great for a week (low load), last night there was a large burst of activity and I have 20k unacked messages this morning, with high expiration rate all night.

Expiration rate in yellow. Very interesting how there seems to be a clear 1-hr periodic pattern between 5-7 am where messages are successfully acked at the start of every hour, and then all expired until the next hour. Very strange.

[rossj]

This issue has actually gotten a lot worse for me. It used to be that in these high-unacked situations, messages would start expiring after about 30 minutes of successful processing, so I would have to restart every 30 minutes. Now it only seems to last 15 minutes. Has anything changed recently on the backend that could be causing this?

I'll make a test project to try and reproduce.

[callmehiphop]

@rossj no we made change in the client to kill the stream after 15 minutes, although my understanding is that in certain environments the backend may close streams earlier to prevent the exact issue you're seeing.

[rossj]

@callmehiphop OK, got it. Does this point to a problem with how the client handles writing acks to the stream pool after one of the steams has been killed? For me, the graphs clearly show that after 15 minutes, when the stream is killed, that there is a long period where none of the acks go through and instead things are expiring.

My understanding is that the client holds on to additional queued / pending messages, regardless of maxMessages, and it seems to me that once the stream is killed / restarted, all of the response for these messages just disappear. Not sure if related to my use of streamingOptions: { maxStreams: 1 }

I restarted the subscriber pods around 11:15 and 11:50

[callmehiphop]

@rossj nope, actually we only read from the stream pool, all acks and modacks are sent as a plain requests. It sounds more like the grpc channel dies without giving any sort of indication as to why.

[callmehiphop]

I just want to make sure I'm on the right track, after about 15 minutes (the default stream timeout) under a moderate size load we think the following is happening:

1. Messages stop coming in
2. Unable to acknowledge any messages in inventory
3. Any locks on pending messages are released

My current hunch is that the gRPC channel dies and as a result we're unable to ack/modAck which causes any messages captured by the client to become expired. Can anyone confirm or refute the symptoms? For example does anyone still see acks going through and an increased number of expired messages?

[rossj]

I've been playing around with some test code today and I've been able to reproduce locally against a test GCP project. Not sure about the 15 minutes... my last test run lasted 40 minutes until switching into expiring mode. I'm still trying to nail down what specific parameters & conditions cause this to happen.

A couple observations so far:

1) Problem seems dependent on having large publish batches, which seems to correlate with subscribers having large local inventory.
2) It seems like acks stop working, but modAcks keep working... If all ack / modAcks stopped, I would expect a big spike after about 30s as all of the inventoried messages expire. Instead, notice that the remaining messages continue to expire at the same rate as they were acking previously. EDIT: I misunderstood the "acknowledge requests" graph... it's showing the response code to attempts to ack a message, not the actual expiration of delivered messages. This seems to me like the communication from subscriber to PubSub backend is happening fine, just that the backend doesn't like any of the ack IDs.

[rossj]

I've run some more test scenarios and I'm starting to get an idea of what's going on. Here is my testing code, along with some results of test scenarios I ran.

Let's start with some basic observations:

• This expired ack result is a consistent and reproducible problem. I've done multiple runs of various test scenarios (over a dozen total runs), and every one has shown similar weirdness and expired ack results after 30-40 minutes.

• The "Undelivered Messages" graph in Stackdriver (based on num_undelivered_messages metric) is very misleading, and will only change when a whole batch of published messages has been ackd. For example, if you publish a single batch of 1000 messages, those 1000 will show as undelivered until each one of the 1000 has been ackd.

• More about the batching - how Pub/Sub delivers messages to subscribers seems to be heavily dependent on how it received them... if you publish batches of 10 messages (e.g. with batching.maxMessages setting), the subscribers will receive batches of 10 messages. If you publish in batches of 100, the client will receive batches of 100. There seems to be an upper limit of 315 batched messages that Pub/Sub will send to a subscriber, but this could have to do with my test message size.

In my tests, I've observed both of the following, which result in ack message requests being expired on the graph:

1) In multiple test runs, Pub/Sub backend has re-delivered whole duplicate batches of messages after they were already ackd earlier. In one test run it even delivered a batch of 315 duplicate messages after all messages had been ackd (and undelivered count was 0). These duplicate batches only seem to be delivered after the 30 min mark. The subsequent re-acking of these duplicate messages then gives the expired ack result. I observed duplicate batches up to 315 messages in size, and these all must be re-handled until there's a chance of getting actually new messages. I've also seen delivered batches flip-flop between being duplicate and non-duplicate after the 30 min mark, effectively cutting real performance in half. See this test run, this one and this one.

2) In other runs, involving large, slow-to-process batches, Pub/Sub backend has started responding with expired to non-duplicate ack requests, starting in the middle of the batch, sometime after the 30 minute mark.

Some things left to try:
1) Does setting publish batch size to 1 or very low improve anything?
2) Experiment with messages size and age - perhaps the max 315 batch size I keep seeing is related to the message size.
3) Experiment with intentional expiration... perhaps Pub/Sub backend is re-sending an entire message batch just because one message didn't get properly extended or ackd by client.
4) There seems to be a 30-minute window, even going back to first post. What was causing the 15 minute window I saw in production?

Also, ref for related Java client issue: https://github.com/googleapis/google-cloud-java/issues/3567

[hden]

Similar issue here. It seems that there are a 1 - 1.5 hr cycle if you let it run long enough.

@google-cloud/pubsub: 0.28.1
flowControl: maxMessages: 1

[rossj]

Just to show that this issue doesn't just involve short periods of expired messages, this morning I was welcomed by a night of wasted compute work and 40k undelivered messages.

Expired response are the blue line below. Very interesting how the expiring period starts short, but then seems to get longer over time. There's a whole 2.5 hr window with essentially no successful acks. Perhaps I need to run my test scenarios for more than an hour.

[callmehiphop]

I've been trying to dig into this over the last several days and so far my findings appear to match https://github.com/googleapis/google-cloud-java/issues/3567#issuecomment-414083920, it looks like gRPC is buffering messages internally and by the time the client receives them they're already expired. The bad news is that I can't find any documentation suggesting that gRPC flow control is configurable, the good news is that this appears to be a non-issue with the pure JS version of gRPC (grpc-js). That being said I see 2 solutions to move forward

1. Direct users experiencing this issue to use grpc-js until the client uses it by default
2. Allow the (older) polling strategy to be used through an option

Regarding option 1, grpc-js is still in beta and I'm unaware if that will change with Node v6 going EOL at the end of the month, so I don't actually know if this suggestion is viable. @alexander-fenster do you have any insight into this?

[callmehiphop]

@rossj would you be interested in testing grpc-js? You can enable it via env var GOOGLE_CLOUD_USE_GRPC_JS="1"

[naugtur]

We're also observing no results from _some_ .ack() calls on v0.24.1
Might be related to this: https://github.com/googleapis/nodejs-pubsub/issues/575 but I'm not sure.

[rossj]

@callmehiphop I tried with @grpc/grpc-js and it seems to have the same issue. All acks gave expired result after ~40 min.

In addition, after 60 min it seems that every modAck attempt failed with a message like:
Failed to "modifyAckDeadline" for X message(s). Reason: Getting metadata from plugin failed with error: New streams cannot be created after receiving a GOAWAY

I don't remember ever seeing these errors with straight grpc.

I'll try the polling PR next.

[ajaaym]

@dinvlad @rossj With this PR #556 from @callmehiphop (not yet released) and using below option, subscriber works fine with slow ack processing. You can see in below charts there was a minor hiccup for around 2:30 to 2:35 but it recovered from that. hiccup was at around after 1 hour run time.

Options to use:

const pubsub = new PubSub(
  {
    'grpc.http2.lookahead_bytes': 4096,
    'grpc.http2.bdp_probe': 0
  }
);
  const subscription = pubsub.subscription(subscriptionName, {
    flowControl: {
      maxMessages: 1,
      allowExcessMessages: false
    },
    streamingOptions: {
      highWaterMark: 1,
      pullTimeout: 100000, //less than 10 min
    }
  });

[sduskis]

This is a duplicate of #11. Closing 11 in favor of this issue.

[callmehiphop]

👋 @dinvlad @rossj @slavoroi assuming this is still a relevant issue for everyone, is anyone interested in testing out @ajaaym's configuration with the latest PubSub release (0.29.0)

[sduskis]

@kamalaboulhosn, given the conversation today, are you comfortable with the settings described here?

[kamalaboulhosn]

@sduskis I feel like this is more of a band-aid than anything. From what I understand, the solution here is shutting down streaming connections more frequently than the default, is that correct? With long processing of messages as is the case here, the solution might just be to use the underlying pull API instead of the client library. I'm hesitant to expand the API in this way unless we think it is a good thing to do and do it across all languages.

[sduskis]

@kamalaboulhosn
+1 on this being a band-aid. Also, +1 on careful consideration of a design around pull.

556 was merged in March, but released about a day ago (https://github.com/googleapis/nodejs-pubsub/releases). Do you feel like we ought to revert the change, and quickly make a new release?

(I don't know enough about this change to say that it ought to be applied to other languages)

[kamalaboulhosn]

@sduskis If possible, I think rolling back would be ideal, thanks.

[sduskis]

@kamalaboulhosn and @kir-titievsky I'd like to remove the triaged for GA label. The solution here is "async pull", which is out of scope for GA.

[kamalaboulhosn]

@sduskis I see that the initial report indicated that this issue only started with version 0.23. Is there something in that version that caused this to start happening? Was that when this library moved to streaming pull? If streaming pull was used prior to that version, it might be good to understand why the new version of the library seems to have introduced issues before we decide that async pull is the solution.

[sduskis]

@kamalaboulhosn that's a great point.

@callmehiphop, do you have any idea what change happened between 0.22.2 and 0.23.0 that could have caused this?

[callmehiphop]

@sduskis @kamalaboulhosn there was a pretty sizable refactor between those two versions and it looks like the grpc version did not change. It may be worth noting that we've had somewhat conflicting reports in this thread in regards to that factor - one user saying pinning 0.22.2 didn't work, another mentioned 0.25.0 being the earliest version they experienced the issue.

As far as notable changes between those two specific versions, one thing that comes to mind was a decision to bypass google-gax and work with the grpc bidi stream directly instead. google-gax automatically applies a DEADLINE (currently set to 15 minutes) and initially that was left off causing streams to stay open for up to 30+ minutes. We've since applied the same deadline that google-gax would, but never received any confirmation if it resolved @dinvlad's issue.

[dinvlad]

FWIW I've finally upgraded from 0.22.2 to 0.29.1, and suddenly receive no messages at all! I.e. my sole subscriber with a single message in the queue stays open for 60+ minutes, without receiving the message (this is with @ajaaym's settings from above). I think I'll have to downgrade back to 0.22.2, where everything seemed to work just fine :(

[sduskis]

we've seen similar issues with grpc-js. We may need to revert that change.

[dinvlad]

Apologies, false alarm. I was using an incorrect service account key. Too many projects :-) 0.29.1 is working now, though I'm not yet sure if the original issue is resolved.

[callmehiphop]

@sduskis this client still uses the C extension version of gRPC, nothing to revert.

@dinvlad glad to hear! Let us know if you encounter any issues 😎

[sduskis]

@dinvlad, have you seen any issues? If not, perhaps it's time to close this issue.

[dinvlad]

Let's close it for now, as we haven't had a chance to run into issues with our current scale. Feel free to re-open if needed.

[rossj]

IMHO this service and / or library still has a critical outstanding issue involving expiring acks, resulting in wasted work and duplicate messages. These issues still appear consistently for me using simple test code and the latest version of the library (0.29.1). My conclusion is that either this service is not widely used / tested, its intended use case is far from the type of task queue we are trying to use it for, or perhaps I'm just an idiot and have been doing something very wrong (edit: not angry sarcasm - the problem could really be on my end). Regardless, my company's solution has been to stop using Google Pub Sub altogether in favor of a more traditional message queue.

[camsjams]

I am experiencing similar symptoms, which result in a large backlog growth of messages that create outages in our application. These start off as DEADLINE_EXCEEDED errors that progress into a general failure of the application for about 20-40mins (we are working on adjusting resiliency here for this part).

The backlog size and unacked messages grow together on the same subscription, and renders the subscription inactive and unusable.

[callmehiphop]

@camsjams would you mind opening a new issue?

[camsjams]

Sure, thanks!