PubSub message.ack() has no effect after calling subscription.removeListener

[lc-chrisbarton]

Calling 'subscription.removeListener('message', on_message)' causes 'message.ack()' to have no effect.

This doesn't work
subscription.on('message', on_message)
...
subscription.removeListener('message', on_message)
...
messages.forEach(message => message.ack())

This works
subscription.on('message', on_message)
...
messages.forEach(message => message.ack())
...
subscription.removeListener('message', on_message)

[callmehiphop]

So we open a bi-directional stream when event listeners are added to a subscription and when the listeners are removed we close the stream. In the scenario above we end up batching together all the message.ack() calls to send through a single rpc call.

Are you running this in a cloud function? Because we are using a 1 second timeout to batch together all the messages.

[lc-chrisbarton]

Yep I am using a CloudFunction. So is it expected behaviour that you cannot call message.ack() after the 'message' listener has been removed? It all works if I just comment out the call to 'removeListener' because I have a delay of a few seconds when closing the subscription. BTW this is not a problem for me now as I have refactored the code to work on messages as they arrive instead of in batches and so all acks are called before the message listener is removed. I guess there needs to be a note about the behaviour, especially for people using Cloud Functions that are so ephemeral and so need to be careful about the caching.

[callmehiphop]

The expectation is that you can call message.ack() after removing the message listeners, but it will take a little longer (about 1 second or so) to actually ack the message. I'm unable to reproduce this bug locally, so if you wouldn't mind putting together some code to replicate the bug that would be awesome and very much appreciated.

[lukesneeringer]

@callmehiphop Would it be reasonable to have the stream closure (after the final listener is removed) be gated on a flush of the acks?

[lc-chrisbarton]

OK problem reproduced, see attached file 'debug-pubsub.js.txt'.
I am running locally using:
node --version
v6.11.1

gcloud beta pubsub topics create tmp
gcloud beta pubsub subscriptions create tmp --topic=tmp --ack-deadline=10
gcloud beta pubsub topics publish tmp hi
gcloud beta pubsub topics publish tmp hi2
gcloud beta pubsub topics publish tmp hi3
gcloud beta pubsub topics publish tmp hi4
gcloud beta pubsub topics publish tmp hi5

node -e 'require("./debug-pubsub").debug()'
Listening for messages...
Retrieved message hi2
Retrieved message hi3
Retrieved message hi4
Retrieved message hi5
Retrieved message hi
Finished listening for messages after 15000 milliseconds
Acknowledging first message from a total of 5 hi2
Removing subscription listener...
Acknowledging message after subscription listener removed hi2
Acknowledging message after subscription listener removed hi3
Acknowledging message after subscription listener removed hi4
Acknowledging message after subscription listener removed hi5
Acknowledging message after subscription listener removed hi
Closing subscription...
Finished waiting for subscription to close after 3000 milliseconds

node -e 'require("./debug-pubsub").debug()'
Listening for messages...
Retrieved message hi3
Retrieved message hi4
Retrieved message hi
Retrieved message hi5
Finished listening for messages after 15000 milliseconds
Acknowledging first message from a total of 4 hi3
Removing subscription listener...
Acknowledging message after subscription listener removed hi3
Acknowledging message after subscription listener removed hi4
Acknowledging message after subscription listener removed hi
Acknowledging message after subscription listener removed hi5
Closing subscription...
Finished waiting for subscription to close after 3000 milliseconds

node -e 'require("./debug-pubsub").debug()'
Listening for messages...
Retrieved message hi4
Retrieved message hi
Retrieved message hi5
Finished listening for messages after 15000 milliseconds
Acknowledging first message from a total of 3 hi4
Removing subscription listener...
Acknowledging message after subscription listener removed hi4
Acknowledging message after subscription listener removed hi
Acknowledging message after subscription listener removed hi5
Closing subscription...
Finished waiting for subscription to close after 3000 milliseconds

debug-pubsub.js.txt

[lc-chrisbarton]

If I also added a pause prior to closing the subscription in addition to pausing after the subscription was closed and the behaviour is the same

[callmehiphop]

While this issue is unresolved, I'm closing it because the core issue is a duplicate of #2558.