Open jomalsan opened 1 week ago
Hi @jomalsan, thanks for reporting.
Could you please try setting run_on_startup=False
? run_on_startup
should not be set to True
in production, especially with the Consumption plan. When enabled, the function will invoke whenever the runtime starts, so the execution times can be unpredictable. It is more useful for local testing.
More information on this can be found here: Timer trigger for Azure Functions
In the templates, we've already made the change to set run_on_startup=False
. It looks like VSCode is using an older version of the templates, which doesn't have this change. Using CoreTools to create a new template should work as expected, though (func new
).
Thank you for calling that out. I did try the func new
method and do see that the run_on_startup
flag is set to False
. Is the update to VS Code templates in progress?
Yes, we're in contact with the VS Code team, and this work is in progress. I don't have an ETA yet for when this will be completed, but I'll post an update when I have more information!
Expected Behavior
When creating a python azure function with a timer trigger, I suspect that it will run on schedule.
VS Code extension version: 1.15.4 Local azure-functions version: 1.21.3
Actual Behavior
Using the CRON string "0 *", I have seen it run on the 30 s mark in addition to on the 0 s mark, and seen it miss long periods of time on execution. I included a large chunk of the log outputs around the missed timer trigger and eventual double run that looks to be a function of the scheduler.
The gaps were more frequent in a different deployment that contains private code. The simple repro is more likely to double run
Steps to Reproduce
Relevant code being tried
import logging import azure.functions as func
app = func.FunctionApp()
@app.schedule( schedule="0 *", arg_name="myTimer", run_on_startup=True, use_monitor=False ) def timer_trigger(myTimer: func.TimerRequest) -> None: if myTimer.past_due: logging.info("The timer is past due!")
Relevant log output
2024-10-11T00:30:00Z [Information] Executing 'Functions.timer_trigger' (Reason='Timer fired at 2024-10-11T00:29:59.9996506+00:00', Id=d9efab72-a8a4-4d5f-82c8-aa94f294128b) 2024-10-11T00:30:00Z [Verbose] Sending invocation id: 'd9efab72-a8a4-4d5f-82c8-aa94f294128b 2024-10-11T00:30:00Z [Verbose] Posting invocation id:d9efab72-a8a4-4d5f-82c8-aa94f294128b on workerId:821a2c1e-19a0-4815-b30a-194b05d6666b 2024-10-11T00:30:00Z [Information] Python timer trigger function executed. 2024-10-11T00:30:00Z [Information] Executed 'Functions.timer_trigger' (Succeeded, Id=d9efab72-a8a4-4d5f-82c8-aa94f294128b, Duration=8ms) 2024-10-11T00:30:00Z [Verbose] Timer for 'timer_trigger' started with interval '00:00:59.9917892'. 2024-10-11T00:30:08Z [Verbose] [HostMonitor] Checking worker statuses (Count=1) 2024-10-11T00:30:08Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=1ms 2024-10-11T00:30:08Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,0,0,0,0), AvgCpuLoad=0, MaxCpuLoad=0 2024-10-11T00:30:08Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(2,0,0,1,1), AvgCpuLoad=1, MaxCpuLoad=2 2024-10-11T00:30:08Z [Verbose] [HostMonitor] Host aggregate CPU load 1 2024-10-11T00:30:08Z [Information] Executing StatusCodeResult, setting HTTP status code 200 2024-10-11T00:30:18Z [Verbose] [HostMonitor] Checking worker statuses (Count=1) 2024-10-11T00:30:18Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=1ms 2024-10-11T00:30:18Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,0,0,0,0), AvgCpuLoad=0, MaxCpuLoad=0 2024-10-11T00:30:18Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(0,0,2,0,1), AvgCpuLoad=1, MaxCpuLoad=2 2024-10-11T00:30:18Z [Verbose] [HostMonitor] Host aggregate CPU load 1 2024-10-11T00:30:18Z [Information] Executing StatusCodeResult, setting HTTP status code 200 2024-10-11T00:30:28Z [Verbose] [HostMonitor] Checking worker statuses (Count=1) 2024-10-11T00:30:28Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=1ms 2024-10-11T00:30:28Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,1,0,0,0), AvgCpuLoad=0.2, MaxCpuLoad=1 2024-10-11T00:30:28Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(1,0,1,0,1), AvgCpuLoad=1, MaxCpuLoad=1 2024-10-11T00:30:28Z [Verbose] [HostMonitor] Host aggregate CPU load 1 2024-10-11T00:30:28Z [Information] Executing StatusCodeResult, setting HTTP status code 200 2024-10-11T00:30:38Z [Verbose] [HostMonitor] Checking worker statuses (Count=1) 2024-10-11T00:30:38Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=1ms 2024-10-11T00:30:38Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,0,0,1,0), AvgCpuLoad=0.2, MaxCpuLoad=1 2024-10-11T00:30:38Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(0,1,0,1,1), AvgCpuLoad=1, MaxCpuLoad=1 2024-10-11T00:30:38Z [Verbose] [HostMonitor] Host aggregate CPU load 1 2024-10-11T00:30:38Z [Information] Executing StatusCodeResult, setting HTTP status code 200 2024-10-11T00:30:48Z [Verbose] [HostMonitor] Checking worker statuses (Count=1) 2024-10-11T00:30:48Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=4ms 2024-10-11T00:30:48Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,0,0,0,0), AvgCpuLoad=0, MaxCpuLoad=0 2024-10-11T00:30:48Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(2,0,1,0,1), AvgCpuLoad=1, MaxCpuLoad=2 2024-10-11T00:30:48Z [Verbose] [HostMonitor] Host aggregate CPU load 1 2024-10-11T00:30:48Z [Information] Executing StatusCodeResult, setting HTTP status code 200 2024-10-11T00:30:52Z [Verbose] Received request to drain the host 2024-10-11T00:30:52Z [Information] DrainMode mode enabled 2024-10-11T00:30:52Z [Information] Calling StopAsync on the registered listeners 2024-10-11T00:30:52Z [Information] Stopping the listener 'Microsoft.Azure.WebJobs.Host.Listeners.SingletonListener' for function 'timer_trigger' 2024-10-11T00:30:52Z [Information] Stopped the listener 'Microsoft.Azure.WebJobs.Host.Listeners.SingletonListener' for function 'timer_trigger' 2024-10-11T00:30:52Z [Information] Call to StopAsync complete, registered listeners are now stopped 2024-10-11T00:30:52Z [Verbose] Received request to drain the host 2024-10-11T00:30:52Z [Information] DrainMode mode enabled 2024-10-11T00:30:52Z [Information] Calling StopAsync on the registered listeners 2024-10-11T00:30:52Z [Information] Stopping the listener 'Microsoft.Azure.WebJobs.Host.Listeners.SingletonListener' for function 'timer_trigger' 2024-10-11T00:30:52Z [Verbose] Timer listener stopped (timer_trigger) 2024-10-11T00:30:52Z [Verbose] Singleton lock released (/Host.Functions.timer_trigger.Listener)
2024-10-11T00:30:52Z [Information] Stopped the listener 'Microsoft.Azure.WebJobs.Host.Listeners.SingletonListener' for function 'timer_trigger'
2024-10-11T00:30:52Z [Information] Call to StopAsync complete, registered listeners are now stopped
2024-10-11T00:30:58Z [Verbose] [HostMonitor] Checking worker statuses (Count=1)
2024-10-11T00:30:58Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=1ms
2024-10-11T00:30:58Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,0,0,0,0), AvgCpuLoad=0, MaxCpuLoad=0
2024-10-11T00:30:58Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(2,0,0,1,1), AvgCpuLoad=1, MaxCpuLoad=2
2024-10-11T00:30:58Z [Verbose] [HostMonitor] Host aggregate CPU load 1
2024-10-11T00:30:58Z [Information] Executing StatusCodeResult, setting HTTP status code 200
2024-10-11T00:31:06Z [Information] Host lock lease acquired by instance ID '000000000000000000000000DB0BFFAF'.
2024-10-11T00:31:08Z [Verbose] [HostMonitor] Checking worker statuses (Count=1)
2024-10-11T00:31:08Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=2ms
2024-10-11T00:31:08Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,0,0,0,0), AvgCpuLoad=0, MaxCpuLoad=0
2024-10-11T00:31:08Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(0,1,1,2,0), AvgCpuLoad=1, MaxCpuLoad=2
2024-10-11T00:31:08Z [Verbose] [HostMonitor] Host aggregate CPU load 1
2024-10-11T00:31:08Z [Information] Executing StatusCodeResult, setting HTTP status code 200
2024-10-11T00:31:18Z [Verbose] [HostMonitor] Checking worker statuses (Count=1)
2024-10-11T00:31:18Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=2ms
2024-10-11T00:31:18Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,0,0,0,0), AvgCpuLoad=0, MaxCpuLoad=0
2024-10-11T00:31:18Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(1,1,1,0,1), AvgCpuLoad=1, MaxCpuLoad=1
2024-10-11T00:31:18Z [Verbose] [HostMonitor] Host aggregate CPU load 1
2024-10-11T00:31:18Z [Information] Executing StatusCodeResult, setting HTTP status code 200
2024-10-11T00:31:28Z [Verbose] [HostMonitor] Checking worker statuses (Count=1)
2024-10-11T00:31:28Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=1ms
2024-10-11T00:31:28Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,1,0,0,0), AvgCpuLoad=0.2, MaxCpuLoad=1
2024-10-11T00:31:28Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(1,0,1,0,0), AvgCpuLoad=0, MaxCpuLoad=1
2024-10-11T00:31:28Z [Verbose] [HostMonitor] Host aggregate CPU load 1
2024-10-11T00:31:28Z [Information] Executing StatusCodeResult, setting HTTP status code 200
2024-10-11T00:31:38Z [Verbose] [HostMonitor] Checking worker statuses (Count=1)
2024-10-11T00:31:38Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=4ms
2024-10-11T00:31:38Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,0,0,0,0), AvgCpuLoad=0, MaxCpuLoad=0
2024-10-11T00:31:38Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(1,0,0,2,0), AvgCpuLoad=1, MaxCpuLoad=2
2024-10-11T00:31:38Z [Verbose] [HostMonitor] Host aggregate CPU load 1
2024-10-11T00:31:38Z [Information] Executing StatusCodeResult, setting HTTP status code 200
2024-10-11T00:31:46Z [Verbose] Singleton lock acquired (/Host.Functions.timer_trigger.Listener)
2024-10-11T00:31:46Z [Verbose] The 'timer_trigger' timer is using the schedule 'Cron: '0 '' and the local time zone: '(UTC) Coordinated Universal Time'
2024-10-11T00:31:46Z [Information] The next 5 occurrences of the 'timer_trigger' schedule (Cron: '0 ') will be:
10/11/2024 00:32:00+00:00 (10/11/2024 00:32:00Z)
10/11/2024 00:33:00+00:00 (10/11/2024 00:33:00Z)
10/11/2024 00:34:00+00:00 (10/11/2024 00:34:00Z)
10/11/2024 00:35:00+00:00 (10/11/2024 00:35:00Z)
10/11/2024 00:36:00+00:00 (10/11/2024 00:36:00Z)
2024-10-11T00:31:46Z [Verbose] Function 'timer_trigger' is configured to run on startup. Executing now.
2024-10-11T00:31:46Z [Information] Executing 'Functions.timer_trigger' (Reason='Timer fired at 2024-10-11T00:31:45.7119706+00:00', Id=9ff51f9c-7ec6-4478-bb87-ada133bcdf45)
2024-10-11T00:31:46Z [Information] Trigger Details: UnscheduledInvocationReason: RunOnStartup
2024-10-11T00:31:46Z [Verbose] Timer for 'timer_trigger' started with interval '00:00:00.0010000'.
2024-10-11T00:31:46Z [Verbose] Sending invocation id: '9ff51f9c-7ec6-4478-bb87-ada133bcdf45
2024-10-11T00:31:46Z [Verbose] Posting invocation id:9ff51f9c-7ec6-4478-bb87-ada133bcdf45 on workerId:024c53f7-c016-4292-a52f-52dee6f2eadf
2024-10-11T00:31:46Z [Information] Python timer trigger function executed.
2024-10-11T00:31:46Z [Information] Executed 'Functions.timer_trigger' (Succeeded, Id=9ff51f9c-7ec6-4478-bb87-ada133bcdf45, Duration=22ms)
2024-10-11T00:31:46Z [Verbose] Timer listener started (timer_trigger)
2024-10-11T00:31:46Z [Verbose] Timer for 'timer_trigger' started with interval '00:00:14.2579564'.
2024-10-11T00:31:48Z [Verbose] [HostMonitor] Checking worker statuses (Count=1)
2024-10-11T00:31:48Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=1ms
2024-10-11T00:31:48Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,0,0,2,0), AvgCpuLoad=0.4, MaxCpuLoad=2
2024-10-11T00:31:48Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(0,0,2,4,2), AvgCpuLoad=2, MaxCpuLoad=4
2024-10-11T00:31:48Z [Verbose] [HostMonitor] Host aggregate CPU load 2
2024-10-11T00:31:48Z [Information] Executing StatusCodeResult, setting HTTP status code 200
2024-10-11T00:31:58Z [Verbose] [HostMonitor] Checking worker statuses (Count=1)
2024-10-11T00:31:58Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=1ms
2024-10-11T00:31:58Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,0,0,0,0), AvgCpuLoad=0, MaxCpuLoad=0
2024-10-11T00:31:58Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(0,2,0,0,2), AvgCpuLoad=1, MaxCpuLoad=2
2024-10-11T00:31:58Z [Verbose] [HostMonitor] Host aggregate CPU load 1
2024-10-11T00:31:58Z [Information] Executing StatusCodeResult, setting HTTP status code 200
2024-10-11T00:32:00Z [Information] Executing 'Functions.timer_trigger' (Reason='Timer fired at 2024-10-11T00:31:59.9989449+00:00', Id=b29abc14-8365-4eb3-983e-c133e0937ad3)
2024-10-11T00:32:00Z [Verbose] Sending invocation id: 'b29abc14-8365-4eb3-983e-c133e0937ad3
2024-10-11T00:32:00Z [Verbose] Posting invocation id:b29abc14-8365-4eb3-983e-c133e0937ad3 on workerId:024c53f7-c016-4292-a52f-52dee6f2eadf
2024-10-11T00:32:00Z [Information] Python timer trigger function executed.
2024-10-11T00:32:00Z [Information] Executed 'Functions.timer_trigger' (Succeeded, Id=b29abc14-8365-4eb3-983e-c133e0937ad3, Duration=7ms)
2024-10-11T00:32:00Z [Verbose] Timer for 'timer_trigger' started with interval '00:00:59.9897925'.
2024-10-11T00:32:08Z [Verbose] [HostMonitor] Checking worker statuses (Count=1)
2024-10-11T00:32:08Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=1ms
2024-10-11T00:32:08Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,0,0,0,0), AvgCpuLoad=0, MaxCpuLoad=0
2024-10-11T00:32:08Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(1,0,2,0,0), AvgCpuLoad=1, MaxCpuLoad=2
2024-10-11T00:32:08Z [Verbose] [HostMonitor] Host aggregate CPU load 1
2024-10-11T00:32:08Z [Information] Executing StatusCodeResult, setting HTTP status code 200
2024-10-11T00:32:18Z [Verbose] [HostMonitor] Checking worker statuses (Count=1)
2024-10-11T00:32:18Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=1ms
2024-10-11T00:32:18Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,0,0,0,0), AvgCpuLoad=0, MaxCpuLoad=0
2024-10-11T00:32:18Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(1,0,2,0,1), AvgCpuLoad=1, MaxCpuLoad=2
2024-10-11T00:32:18Z [Verbose] [HostMonitor] Host aggregate CPU load 1
2024-10-11T00:32:18Z [Information] Executing StatusCodeResult, setting HTTP status code 200
2024-10-11T00:32:28Z [Verbose] [HostMonitor] Checking worker statuses (Count=1)
2024-10-11T00:32:28Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=1ms
2024-10-11T00:32:28Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,0,0,0,0), AvgCpuLoad=0, MaxCpuLoad=0
2024-10-11T00:32:28Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(1,0,0,1,1), AvgCpuLoad=1, MaxCpuLoad=1
2024-10-11T00:32:28Z [Verbose] [HostMonitor] Host aggregate CPU load 1
2024-10-11T00:32:28Z [Information] Executing StatusCodeResult, setting HTTP status code 200
2024-10-11T00:32:38Z [Verbose] [HostMonitor] Checking worker statuses (Count=1)
2024-10-11T00:32:38Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=1ms
2024-10-11T00:32:38Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,0,0,1,0), AvgCpuLoad=0.2, MaxCpuLoad=1
2024-10-11T00:32:38Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(0,2,0,0,1), AvgCpuLoad=1, MaxCpuLoad=2
2024-10-11T00:32:38Z [Verbose] [HostMonitor] Host aggregate CPU load 1
2024-10-11T00:32:38Z [Information] Executing StatusCodeResult, setting HTTP status code 200
2024-10-11T00:32:48Z [Verbose] [HostMonitor] Checking worker statuses (Count=1)
2024-10-11T00:32:48Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=2ms
2024-10-11T00:32:48Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,0,0,0,0), AvgCpuLoad=0, MaxCpuLoad=0
2024-10-11T00:32:48Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(2,0,0,5,1), AvgCpuLoad=2, MaxCpuLoad=5
2024-10-11T00:32:48Z [Verbose] [HostMonitor] Host aggregate CPU load 2
2024-10-11T00:32:48Z [Information] Executing StatusCodeResult, setting HTTP status code 200
2024-10-11T00:32:58Z [Verbose] [HostMonitor] Checking worker statuses (Count=1)
2024-10-11T00:32:58Z [Verbose] [HostMonitor] Worker status: ID=024c53f7-c016-4292-a52f-52dee6f2eadf, Latency=1ms
2024-10-11T00:32:58Z [Verbose] [HostMonitor] Host process CPU stats (PID 94): History=(0,0,0,1,0), AvgCpuLoad=0.2, MaxCpuLoad=1
2024-10-11T00:32:58Z [Verbose] [HostMonitor] Host process CPU stats (PID 61): History=(0,2,0,0,1), AvgCpuLoad=1, MaxCpuLoad=2
2024-10-11T00:32:58Z [Verbose] [HostMonitor] Host aggregate CPU load 1
2024-10-11T00:32:58Z [Information] Executing StatusCodeResult, setting HTTP status code 200
2024-10-11T00:33:00Z [Information] Executing 'Functions.timer_trigger' (Reason='Timer fired at 2024-10-11T00:33:00.0012363+00:00', Id=5f7f93b6-e54c-4e1b-85f5-5d789349f284)
2024-10-11T00:33:00Z [Verbose] Sending invocation id: '5f7f93b6-e54c-4e1b-85f5-5d789349f284
2024-10-11T00:33:00Z [Verbose] Posting invocation id:5f7f93b6-e54c-4e1b-85f5-5d789349f284 on workerId:024c53f7-c016-4292-a52f-52dee6f2eadf
2024-10-11T00:33:00Z [Information] Python timer trigger function executed.
2024-10-11T00:33:00Z [Information] Executed 'Functions.timer_trigger' (Succeeded, Id=5f7f93b6-e54c-4e1b-85f5-5d789349f284, Duration=3ms)
requirements.txt file
DO NOT include azure-functions-worker in this file
The Python Worker is managed by Azure Functions platform
Manually managing azure-functions-worker may cause unexpected issues
azure-functions
Where are you facing this problem?
Production Environment (explain below)
Function app name
No response
Additional Information
This may be something where running every minute (used for easier debugging), in which case that should be documented