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

pubsub: unacked messages being redelivered #2756

Closed
rhodgkins opened this issue Nov 23, 2017 · 2 comments
Closed

pubsub: unacked messages being redelivered #2756

rhodgkins opened this issue Nov 23, 2017 · 2 comments
Assignees

Comments

@rhodgkins
Copy link

rhodgkins commented Nov 23, 2017

In previous (I think v0.12 and lower) versions of pubsub messages were auto acked upon receiving a message (or if this was turned off, had to be manually acked). As I understood this had to happen within the ackDeadlineSeconds time and this could be modified with subscription.modifyAckDeadline().

Now the newer version (v0.15), from looking at the code, uses timers to "lease" out the message (using the acDeadlineSeconds time as the initial lease interval), automatically extending the ack deadline until either message.ack() or message.nack() is called?
What happens if you don't do this for a long period of time? Does the lease timer keep on and on extending the ack deadline?

The reason I'm asking for clarification is that I've seen unacked (that is neither .ack() or .nack() has been called on the message) messages being delivered again after a period of time.

So the following would happen:

  1. Message A published
  2. Message A received and not acked or nacked
  3. Period of time passes - say 3 mins
  4. Message A is received again

I've also had it where I've nacked a message and the current message I'm processing is delivered again.

  1. Message A published
  2. Message A received and not acked or nacked
  3. Message B published and nacked
  4. Message A is received again

I'll try and post some replication steps for the latter issue (its not consistent when I have seen it), but if anyone can confirm by above questions that would be great! Cheers!

@rhodgkins
Copy link
Author

rhodgkins commented Nov 23, 2017

I've managed to reproduce the duplicated delivery which happens probably 2/5 times:

const PubSub = require('@google-cloud/pubsub')

const pubsub = new PubSub(/*{
       projectId: '',
       keyFilename: ''
} */)

function log(...args) {
	console.log(`[${new Date().toISOString()}]`, ...args)
}
function errLog(...args) {
	console.error(`[${new Date().toISOString()}]`, ...args)
}

const name = 'com.test.domain-redelivery-sub'
	
log(`Creating pubsub for ${name}`)

const subOptions = {
	flowControl: {
		maxMessages: 3
	},
	// Max deadline: https://cloud.google.com/pubsub/docs/reference/rest/v1/projects.subscriptions/create
	ackDeadlineSeconds: 30
}


function handleMessage(m) {
	log(`Received message: ${m.id} / ${m.publishTime}: `, m.data.toString())
	
	const shouldAck = true
	const waiting = 600 * 1000
	
	log(`Waiting ${waiting / 1000}s to reply with ${shouldAck ? 'ACK' : 'NACK'}`)
	setTimeout(() => {
		log(`Reporting message: ${m.id} - ${shouldAck ? 'ACK' : 'NACK'}`)
		
		if (shouldAck) {
			m.ack()
		} else {
			m.nack()
		}
	}, waiting)
}
function handleError(err) {
	errLog(`Error with subscription ${name}:`, err)
	throw err
}

pubsub.topic(name).get({ autoCreate: true }, (topicErr, topic) => {
	if (topicErr) {
		errLog(`Failed to create topic - ${name}:`, topicErr)
		throw topicErr
	}
	topic.createSubscription(`${name}-subscription`, subOptions, (subErr, sub) => {
		if (subErr) return handleError(subErr)
				
		sub.on('message', handleMessage)
		sub.on('error', handleError)
		
		log(`Subscribed to ${name} with subscription ID: ${sub.name}`)
		
		const sendMessage = () => {
			
			const m = `Message @ ${new Date().toString()}`
			log('Sending message:', m)
			topic.publisher().publish(Buffer.from(m), mErr => {
				if (mErr) return errLog('Error publishing:', mErr)
			})
		}
		
		setTimeout(sendMessage, 4 * 1000)
	})
})

Console:

[2017-11-23T15:33:25.453Z] Creating pubsub for com.test.domain-redelivery-sub
[2017-11-23T15:33:30.980Z] Subscribed to projects/bookcreator-dev/topics/com.test.domain-redelivery-sub with subscription ID: projects/bookcreator-dev/subscriptions/com.test.domain-redelivery-sub-subscription
[2017-11-23T15:33:34.982Z] Sending message: Message @ Thu Nov 23 2017 15:33:34 GMT+0000 (GMT)
[2017-11-23T15:33:36.529Z] Received message: 174068690240637 / Thu Nov 23 2017 15:33:36 GMT+0000 (GMT):  Message @ Thu Nov 23 2017 15:33:34 GMT+0000 (GMT)
[2017-11-23T15:33:36.529Z] Waiting 600s to reply with ACK
[2017-11-23T15:35:09.606Z] Received message: 174068690240637 / Thu Nov 23 2017 15:33:36 GMT+0000 (GMT):  Message @ Thu Nov 23 2017 15:33:34 GMT+0000 (GMT)
[2017-11-23T15:35:09.606Z] Waiting 600s to reply with ACK
[2017-11-23T15:35:21.893Z] Received message: 174068690240637 / Thu Nov 23 2017 15:33:36 GMT+0000 (GMT):  Message @ Thu Nov 23 2017 15:33:34 GMT+0000 (GMT)
[2017-11-23T15:35:21.893Z] Waiting 600s to reply with ACK
[2017-11-23T15:35:33.567Z] Received message: 174068690240637 / Thu Nov 23 2017 15:33:36 GMT+0000 (GMT):  Message @ Thu Nov 23 2017 15:33:34 GMT+0000 (GMT)
[2017-11-23T15:35:33.568Z] Waiting 600s to reply with ACK
[2017-11-23T15:37:07.460Z] Received message: 174068690240637 / Thu Nov 23 2017 15:33:36 GMT+0000 (GMT):  Message @ Thu Nov 23 2017 15:33:34 GMT+0000 (GMT)
[2017-11-23T15:37:07.460Z] Waiting 600s to reply with ACK
[2017-11-23T15:39:08.366Z] Received message: 174068690240637 / Thu Nov 23 2017 15:33:36 GMT+0000 (GMT):  Message @ Thu Nov 23 2017 15:33:34 GMT+0000 (GMT)
[2017-11-23T15:39:08.366Z] Waiting 600s to reply with ACK
[2017-11-23T15:40:47.350Z] Received message: 174068690240637 / Thu Nov 23 2017 15:33:36 GMT+0000 (GMT):  Message @ Thu Nov 23 2017 15:33:34 GMT+0000 (GMT)
[2017-11-23T15:40:47.350Z] Waiting 600s to reply with ACK
[2017-11-23T15:42:07.097Z] Received message: 174068690240637 / Thu Nov 23 2017 15:33:36 GMT+0000 (GMT):  Message @ Thu Nov 23 2017 15:33:34 GMT+0000 (GMT)
[2017-11-23T15:42:07.097Z] Waiting 600s to reply with ACK
[2017-11-23T15:43:11.674Z] Received message: 174068690240637 / Thu Nov 23 2017 15:33:36 GMT+0000 (GMT):  Message @ Thu Nov 23 2017 15:33:34 GMT+0000 (GMT)
[2017-11-23T15:43:11.675Z] Waiting 600s to reply with ACK
[2017-11-23T15:43:36.511Z] Reporting message: 174068690240637 - ACK
[2017-11-23T15:44:42.234Z] Received message: 174068690240637 / Thu Nov 23 2017 15:33:36 GMT+0000 (GMT):  Message @ Thu Nov 23 2017 15:33:34 GMT+0000 (GMT)
[2017-11-23T15:44:42.234Z] Waiting 600s to reply with ACK
[2017-11-23T15:45:09.589Z] Reporting message: 174068690240637 - ACK
[2017-11-23T15:45:21.877Z] Reporting message: 174068690240637 - ACK
[2017-11-23T15:45:33.548Z] Reporting message: 174068690240637 - ACK

Pubsub version: 0.14.8 (I shall try 0.15 but I'm not sure it'll make a difference as it was only GAX that was updated?)

Also - I let the code run for a while after the initial message was ACKed - and you can see it was still redelivered then.

@rhodgkins rhodgkins changed the title pubsub: clarification on message acks pubsub: unasked messages being redelivery Nov 23, 2017
@rhodgkins rhodgkins changed the title pubsub: unasked messages being redelivery pubsub: unacked messages being redelivery Nov 23, 2017
@rhodgkins rhodgkins changed the title pubsub: unacked messages being redelivery pubsub: unacked messages being redelivered Nov 23, 2017
@callmehiphop
Copy link
Contributor

This issue was moved to googleapis/nodejs-pubsub#2

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants