[Bug] Default python timer trigger function doesn't run on schedule

[jomalsan]

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

1. Generate a new function in VS Code extension

• Select python
• V2
• Timer trigger
• Cron string ("0 * * * * *") <- every minute for quick understanding

2. Deploy to a function app (I'm using a linux consumption app)
3. In the portal navigate to invocations
4. Expectation is that they run every minute, in reality there are times that it runs twice as fast and other times that it misses spaces

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!")

logging.info("Python timer trigger function executed.")

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 (<function_app_name>/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 (<function_app_name>/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