Search code examples
azure-functionsazure-storage-queues

Double queueing of messages to an Azure Queue from an Azure Function


I have an Azure Function running on a timer trigger that finds a set of records from a datasource and uses that to build up an array of messages and then sends that to a queue output.

The function reports (via context.log()) finding 4 records and then building an array of 4 messages for the queue. But the queue gets 8 messages.

I am not seeing the function triggered/invoked twice (as far as I can tell... watching logs, etc.). I'm just seeing double entries into the queue.

Basic details:

  • Node.js (v12) async function
  • Consumption plan (version ~3)
  • Runs in less than 1 second
  • Sending to queue using context.bindings.outboundQueue = outgoingMessagesArray
  • Timer trigger has "useMonitor": false set (per GitHub)

Any ideas?

UPDATE: Sigh... well now I'm seeing double function invocations. Log looks like this:

2021-08-17T14:28:00.011 [Information] Executing 'Functions.sendToQueue' (Reason='Timer fired at 2021-08-17T14:28:00.0112754+00:00', Id=f41c233f-42c9-4da6-ac8a-f354d04be0df)
2021-08-17T14:28:00.012 [Information] Executing 'Functions.sendToQueue' (Reason='Timer fired at 2021-08-17T14:28:00.0117734+00:00', Id=3b0a8941-604e-45b4-839b-33eb5e467751)
2021-08-17T14:28:00.133 [Information] Found 4 locations
2021-08-17T14:28:00.134 [Information] Built 4 messages
2021-08-17T14:28:00.220 [Information] Executed 'Functions.sendToQueue' (Succeeded, Id=f41c233f-42c9-4da6-ac8a-f354d04be0df, Duration=209ms)
2021-08-17T14:28:00.490 [Information] Found 4 locations
2021-08-17T14:28:00.490 [Information] Built 4 messages
2021-08-17T14:28:00.554 [Information] Executed 'Functions.sendToQueue' (Succeeded, Id=3b0a8941-604e-45b4-839b-33eb5e467751, Duration=542ms)

However the Portal Monitor under Invocations reports only one invocation every two minutes. Even though that log shows the timer seeming to fire twice (fracctions of a second apart).


Solution

  • Well, @bjorne got me looking in the right direction!

    Because of a deployment error, this revised function that uses a queue was indeed running in both slots and not just in the stg slot.

    What's super frustrating for me is that while I was looking at the monitor log stream for the stg slot in the portal, that log stream was showing me invocations from both slots! So it looked the whole time like this was coming from the stg slot.

    So hopefully this helps someone avoid a rabbit trail; if you are using slots and seeing double invocations or double results, check out all of your slots and don't necessarily trust an individual slot's logging.

    UPDATE: I believe that seeing logs from both slots is because both slots had an identical WEBSITE_CONTENTSHARE application setting. This is what caused my code to unexpectedly be deployed “in both places” and it also appears that the logging problem goes away when each slot has a distinct WEBSITE_CONTENTSHARE application setting.

    UPDATE 2: Unfortunately this is not yet a complete answer. Setting WEBSITE_CONTENTSHARE manually per slot does solve the problem, but then slot swapping doesn't not work as expected. See this GitHub issue with someone from Microsoft acknowledging the problem and confirming that it's still not really working correctly. So, this does work as desccribed, but you can't use slot swapping.

    UPDATE 3: Setting WEBSITE_CONTENTSHARE manually per slot works. Just make sure the slot name is random (e.g. my-function-app-0a1b2c3d). The way slots are named automatically in the portal seems to be [function-app-name]-[random-8-char-hex-value], so copying this seems good. When in doubt, I'd recommend blowing away the old slot and making a new one.