Azure Function timer is running twice and when I log onto the Azure portal

Question

I have a Timed Function App in Azure that is scheduled to run at 22:00 daily. However, it appears to run at 21:59 and also at 22:00, consistently every day. It also appears to run at random when I am logged into the Azure portal checking the logs.

Here's an example of the timestamps of the duplicate entries I am getting:

I have searched the web but have found no working solution.

Here's the signature of the app, which takes about 20s to complete:

[FunctionName("Function1")]
public static void Run([TimerTrigger("0 0 22 * * *", RunOnStartup = false)]TimerInfo myTimer, TraceWriter log)
{
   // My code
}

And here's my local.settings.json:

{
  "IsEncrypted": false,
  "Values": {
    "AzureWebJobsStorage": "DefaultEndpointsProtocol=https;AccountName=XXX;AccountKey=XXX",
    "AzureWebJobsDashboard": "DefaultEndpointsProtocol=https;AccountName=XXX;AccountKey=XXX",
    "type": "timerTrigger",
    "schedule": "0 0 22 * * *",
    "useMonitor": false,
    "SQLConn": "Server=tcp:XXX.database.windows.net,1433;Initial Catalog=XXX;Persist Security Info=False;User ID=XXX;Password=XXX;MultipleActiveResultSets=False;Encrypt=True;TrustServerCertificate=False;Connection Timeout=30;"
  },
  "disabled": false
}

Can anyone help me out?

Also, the "Monitor" section in Azure's functions show nothing unusual.

Can you share the app name using [these steps](https://github.com/Azure/azure-functions-host/wiki/Sharing-Your-Function-App-name-privately)? Thanks — David Ebbo, Mar 06 '18 at 01:29

score 4 · Accepted Answer · answered Mar 06 '18 at 18:17

4

I took a look at our internal logs for your function app (thanks for sharing the name!), and I see the following:

2018-03-02 14:43:50.4977179: Function 'DemoAzureFunction.Function1.Run' is configured to run on startup. Executing now.
2018-03-02 14:44:01.7856855: Function 'DemoAzureFunction.Function1.Run' updated status: Last='2018-03-02T14:43:48.6103583+00:00', Next='2018-03-02T22:00:00.0000000+00:00', LastUpdated='3/2/2018 2:43:48 PM'

So it looks to me that at one point you had RunOnStartup = true in your function configuration. When configured this way, accessing the portal can trigger the timer to run immediately (separate from the configured schedule) since the portal interaction will wake up your function app.

answered Mar 06 '18 at 18:17

Chris Gillum

14,526
5
48
61

Thanks for responding, Chris. Very interesting that RunOnStartup has that effect. Any idea why it was triggering at 21:59 as well as at 22:00? – MSOACC Mar 06 '18 at 20:08
@MSOACC looks like a very similar reason. In the consumption plan, our scale controller will wake up the function app about a minute before the scheduled expiration time to make sure it is warmed up an ready to execute. It looks like RunOnStartup was true here too, so it ran one minute early when the app woke up, and one more time at the scheduled time. :-/ Apologies for the confusion this is creating - the RunOnStartup is a bit of a confusing feature and I'm not sure why we thought it was useful... – Chris Gillum Mar 06 '18 at 20:59

Janley Zhang · Answer 2 · 2018-03-06T09:21:25.817

3

Here's an example of the timestamps of the duplicate entries I am getting:

According to your screenshot, I suppose the result belongs to started and completed status function logs in azure function. These status logs are created by system automatically.

I have tested TimeTrigger on my side. When TimeTrigger runs every time, there are always two(started, completed) status Function logs. The logs of them are packaged together and output nearly at the same time. If the schedule is long, the timestamp between different status logs will be a delay. If the schedule is short(every 4 seconds),the timestamp between different status are always the same. You could also see two status function logs in this article.

Two status Function logs(started, completed):

edited Mar 06 '18 at 09:21

answered Mar 06 '18 at 02:39

Janley Zhang

1,567
7
11

Thanks for the response but the screenshot I posted wasn't actually from any log file or database, it was from the database entries created by the function itself. There should only be one per day. – MSOACC Mar 06 '18 at 17:21
How you use database entries? Please provide your code. – Janley Zhang Mar 06 '18 at 17:24
Answer has been provided by @ChrisGillum :) – MSOACC Mar 06 '18 at 20:05

score 2 · Answer 3 · answered Nov 11 '19 at 10:16

The issue still exists and seems to only affect Consumption plan functions.

I have lots of app service planned functions which have never had this issue, but my first two consumption planned functions are having the reported issue. Both have RunAtStartUp set to true, so will try it with that turned off as recommended earlier.

Surely this should be regarded as a bug by MS? Obviously not since the bug still exists over a year later.

Azure Function timer is running twice and when I log onto the Azure portal

3 Answers3

Linked