Azure Function with Timer Trigger running twice

Question

I have run into a situation similar to Azure Function timer is running twice and when I log onto the Azure portal but I the solution there hasn't worked for me so far.

My function (written in Node) runs on a timer (every 15 minutes). In Application Insights and in the Azure portal Monitor logs, I see a single invocation every 15 minutes, as expected (presumably due to sampling). However, the output is occurring twice (I'm writing a record to a Cosmos collection). When I watch the live logs for my function (in the portal, navigate to the function code and pull up Logs from the bottom of the screen) I can see that it is running twice, very close together. Sample logs below. The intervals overlap, so I don't think it's a CRON issue (but I'm no CRON expert).

I did consider runOnStartup. I'm not sure if that defaults to false so I set it to false and restarted. Same problem after restart. (I'm still suspicious of this because a similar function app on a one minute timer runs as expected).

I have also tried running the function from the portal manually. When I do this, it only runs once.

Providing the information requested on the Azure functions github wiki:

1. I am using Consumption Plan
2. Not sure how much info is needed - we use Azure DevOps pipelines and Kudu.
3. v2 (Preview) runtime
4. Not setting WEBSITE_TIME_ZONE
5. My CRON expression: 0 */15 * * * * My expectation about what it means: function should run every 15 minutes.
6. N/A

7. Providing two from the close-together starts -

   • Invocation id: 4e142315-60e3-420d-b71a-9990683ba5aa
   • Invocation datetime: 2019-04-18T17:45:00.0044464+00:00

   • Region: East US

   • Invocation id: 4c6f4e7a-1e9d-4278-b3c6-0a2b5310199c

   • Invocation datetime: 2019-04-18T17:45:00.0131739+00:00
   • Region: East US

---

Sample logging showing two overlapping invocations (actual log text edited slightly for simplicity):

2019-04-18T17:45:00.004 [Information] Executing 'Functions.unassignDriverPermits' (Reason='Timer fired at 2019-04-18T17:45:00.0044464+00:00', Id=4e142315-60e3-420d-b71a-9990683ba5aa)

2019-04-18T17:45:00.013 [Information] Executing 'Functions.unassignDriverPermits' (Reason='Timer fired at 2019-04-18T17:45:00.0131739+00:00', Id=4c6f4e7a-1e9d-4278-b3c6-0a2b5310199c)

2019-04-18T17:45:33.577 [Information] Log a thing about something

2019-04-18T17:45:33.577 [Information] Log a thing about id 0

2019-04-18T17:45:33.586 [Information] Executed 'Functions.unassignDriverPermits' (Succeeded, Id=4e142315-60e3-420d-b71a-9990683ba5aa)

2019-04-18T17:45:33.281 [Information] Log a thing about something

2019-04-18T17:45:33.282 [Information] Log a thing about id 0

2019-04-18T17:45:33.294 [Information] Executed 'Functions.unassignDriverPermits' (Succeeded, Id=4c6f4e7a-1e9d-4278-b3c6-0a2b5310199c)

Answer 1

I once had a similar issue with my function that ran daily at 12:00. RunOnStartup was set to true. The function was running on a consumption plan, and by running only daily the function deallocates and is restarted when triggered (in cold start). Perhaps this was the reason for the double invocation: once for the trigger and once because it was started). It was fixed by setting RunOnStartup to false.

Make sure the RunOnStartup is set to false.

Answer 2

Looks like the 2 invocation ids are from 2 different apps (prod/dev may be?) Are you able to filter your logs based on App name to verify if it is the same trigger firing twice?