3

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)

Improve this question
3
  • Having the same issue. Any luck? Commented Sep 10, 2020 at 3:09
  • 1
    See the accepted answer (and the comments underneath). This seems to be an Azure bug wherein two slots can get mixed up. We killed a slot and the problem went away (and I have not seen this particular issue crop up again). Commented Sep 10, 2020 at 14:38
  • Thank you @Christina. I had the issue solved. I didn't have slots in my function app, but once I added RunOnStartup=false to the functions, the problem went away. Commented Sep 13, 2020 at 8:24

2 Answers 2

Reset to default
6

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.

Improve this answer
Sign up to request clarification or add additional context in comments.

1 Comment

Didn't work for me. I have a few timer functions and they are double triggering. Try deleting the function app and re-deploying it. Setting the RunOnStartup to false. Nothing so far.
4

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?

Improve this answer

7 Comments

Hi balag0, for clarifying questions, you should use a comment to the original question. Answers are meant for solutions.
I tried to. But I don't have enough reputation to add comments on other's posts.
Those logs come directly from the app's logging console. The ids are different for every run - but the combination of id and timestamp is supposed to be enough for an Azure employee to look up my app without me posting more info publicly.
Not sure if you can tell, but could one of them be from a slot? We've noticed some odd behavior around the slot on this function app recently.
Marking this as the answer but it seems to reveal a bug wherein two slots can run as if they were both production.
|

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.