All Functions within a Function App Running on CRON Change - Duplicated Transaction Logs

Matthew Hughes 0 Reputation points
2024-03-30T18:49:46.57+00:00

Unexpected Behaviors:

  1. Any change to the CRON expression in either timer trigger will trigger both functions
    1. I added a third function (testtimer) to run every hour at the 50th minute (0 50 * * * *) and that initiated all three functions for some reason.
    2. The logs appear to be duplicated, a transaction search shows each and every transaction is listed twice when viewing from Application insights transaction log

 

Is it possible that’s just a naming issue, where each function should have a difference sciptFile name? I’m very new, appreciate the help

 

Details:

 

FunctionApp: GracePremiumFunctions

Location: East US (even though I’m in south central us)

Function A: GraceWeekly_PC

Function B: GraceWeekly1400

Consumption Plan (Premium)

Zip Deploy Lenox

Runtime version ~4

WEBSITE_TIME_ZONE= Central Standard Time set via Azure Portal Environment Variables. This was just updated this morning and shouldn't be related

 

Sample Invocation ID:

  • This shows it only executed the one function, but it ran my primary two functions in addition to this test function
  • I know this because of logging statements throughout each of the scripts
  • Executing 'Functions.TestTimer' (Reason='Timer fired at 2024-03-29T23:50:00.0040219+00:00', Id=40d05618-9e5a-4d5e-b215-ab496cc0c472)

Example Trace logs (EVERY log item is listed twice at the exact same time)

SingletonOptions

{

  "LockPeriod": "00:00:15",

  "ListenerLockPeriod": "00:01:00",

  "LockAcquisitionTimeout": "10675199.02:48:05.4775807",

  "LockAcquisitionPollingInterval": "00:00:05",

  "ListenerLockRecoveryPollingInterval": "00:01:00"

}

#Triggers
	#GraceWeekly1400
{
    "data": {
        "scriptFile": "__init__.py",
        "bindings": [
            {
                "name": "churchmetricstimer",
                "type": "timerTrigger",
                "direction": "in",
                "schedule": "0 0 20 * * 1"
            }
        ]
    }
}
	#GraceWeekly_PC
{
    "data": {
        "scriptFile": "__init__.py",
        "bindings": [
            {
                "name": "planningcentertimer",
                "type": "timerTrigger",
                "direction": "in",
                "schedule": "0 0 20 * * 1"
            }
        ]
    }
}

#
	#GraceWeekly1400
def main(churchmetricstimer: func.TimerRequest) -> None:
    utc_timestamp = datetime.datetime.utcnow().replace(
        tzinfo=datetime.timezone.utc).isoformat()
 
    if churchmetricstimer.past_due:
        logging.info('The timer is past due!')
 
    logging.info('Python timer trigger function ran at %s', utc_timestamp)
	
	#GraceWeekly_PC
def main(planningcentertimer: func.TimerRequest) -> None:
    utc_timestamp = datetime.datetime.utcnow().replace(
        tzinfo=datetime.timezone.utc).isoformat()
 
    if planningcentertimer.past_due:
        logging.info('The timer is past due!')
 
    logging.info('Python timer trigger function ran at %s', utc_timestamp)
Azure Functions
Azure Functions
An Azure service that provides an event-driven serverless compute platform.
5,937 questions
{count} votes

3 answers

Sort by: Most helpful
  1. Sina Salam 22,031 Reputation points Volunteer Moderator
    2024-03-30T20:16:07.4266667+00:00

    Hello Matthew Hughes,

    Welcome to the Microsoft Q&A and thank you for posting your questions here.

    Problem

    Based on the provided information, I understand that within a Function App named GracePremiumFunctions, multiple timer-triggered functions (GraceWeekly_PC and GraceWeekly1400) are exhibiting unexpected behavior after changes to their CRON expressions. These behaviors include:

    Changes to the CRON expressions triggering both functions.

    Addition of a third function (testtimer) causing all functions to initiate unexpectedly.

    Duplication of transaction logs in Application Insights.

    Solution

    To solve the problems and address the questions regarding the unexpected behavior of timer-triggered functions within the Function App, you will have to follow these steps:

    1. Double-check the CRON expressions defined for each timer-triggered function in the function app's configuration. Ensure that each CRON expression is correctly formatted and represents the intended schedule for the respective function.
    2. Review the function app's configuration to ensure that each function is properly associated with its designated trigger (i.e., the correct CRON expression). Verify that there are no overlapping triggers or conflicting configurations that could cause unintended function invocations.
    3. After you have done with the above. Consider separating the implementation of each function into its own script file. Create separate Python files for each function (e.g., GraceWeekly_PC.py, GraceWeekly1400.py, TestTimer.py) and specify the corresponding script file names in the function app's configuration. This is how you can separate the implementation of each function into its own Python script file:
      1. GraceWeekly_PC.py:
              import logging
              import datetime
              import azure.functions as func
              def main(planningcentertimer: func.TimerRequest) -> None:
                  utc_timestamp = datetime.datetime.utcnow().replace(
                      tzinfo=datetime.timezone.utc).isoformat()
                  if planningcentertimer.past_due:
                      logging.info('The timer is past due!')
                  logging.info('GraceWeekly_PC timer trigger function ran at %s', utc_timestamp)
              
        
      2. GraceWeekly1400.py:
              import logging
              import datetime
              import azure.functions as func
              def main(churchmetricstimer: func.TimerRequest) -> None:
                  utc_timestamp = datetime.datetime.utcnow().replace(
                      tzinfo=datetime.timezone.utc).isoformat()
                  if churchmetricstimer.past_due:
                      logging.info('The timer is past due!')
                  logging.info('GraceWeekly1400 timer trigger function ran at %s', utc_timestamp)
              
        
      3. TestTimer.py:
              import logging
              import datetime
              import azure.functions as func
              def main(testtimer: func.TimerRequest) -> None:
                  utc_timestamp = datetime.datetime.utcnow().replace(
                      tzinfo=datetime.timezone.utc).isoformat()
                  if testtimer.past_due:
                      logging.info('The timer is past due!')
                  logging.info('TestTimer timer trigger function ran at %s', utc_timestamp)
              
        
        Ensure that the scriptFile configuration in the function app's function.json file points to the respective script file for each function.
    4. Then, utilize dependency injection to ensure that each function's dependencies are correctly scoped and isolated. Inject any shared dependencies required by multiple functions to avoid conflicts or unintended interactions.
    5. So, after all perform routing to test, debugging, monitor and review Application Insights configuration.

    Finally

    By following these steps and organizing the functions into separate script files, you can mitigate the issues related to CRON expression changes triggering multiple functions, unexpected function invocations, and duplication of transaction logs. Additionally, thorough testing and monitoring will help ensure the stability and reliability of the Function App. If issues persist, use logging statements within the function code to debug and trace the execution flow.

    I hope this is helpful! Do not hesitate to let me know if you have any other questions.

    Please remember to "Accept Answer" if answer helped, so that others in the community facing similar issues can easily find the solution.

    Best Regards,

    Sina Salam


  2. Matthew Hughes 0 Reputation points
    2024-04-01T03:10:16.0666667+00:00

    It shows they are separate with separate times, but when one kicks off, they both run. User's image

    Notice live telemetry is showing details from the other function: GraceWeekly_PC

    User's image

    Both will run for about 45 minutes and all the logging from within the script will show successful completion and both scripts ran and loaded my database tables.

    0 comments No comments

  3. Pinaki Ghatak 5,600 Reputation points Microsoft Employee Volunteer Moderator
    2024-05-07T14:29:42.6133333+00:00

    Hello Matthew Hughes

    It seems like there might be an issue with the CRON expressions used in your timer triggers. It's possible that the expressions are overlapping and causing both functions to be triggered when only one is expected to run. Regarding the issue with the test function initiating all three functions, it's possible that there is an issue with the naming of the functions or the scriptFile names.

    It's important to ensure that each function has a unique name and scriptFile name to avoid any confusion or unexpected behavior.

    As for the duplicated logs, it's possible that there is an issue with the logging framework being used. You may want to check the configuration of the logging framework and ensure that it's set up correctly to avoid any duplication of logs.

    I hope this helps!

    0 comments No comments

Your answer

Answers can be marked as Accepted Answers by the question author, which helps users to know the answer solved the author's problem.