none
Timer not triggerd RRS feed

  • Question

  • Hello

    I have timer function scheduled to trigger every hour. But when in look in the log files it's not happening every hour. You can see that in the monitor tab. This is very annoying because this is a stock update system and we need to count on this.

    Can someone from Microsoft help me out on this?

    regards

    Dieter

    Wednesday, June 20, 2018 6:06 AM

All replies

  • The built-in logging is useful for testing with light workloads but is not intended for high-load production use. For production monitoring, Application Insights is recommended.
    Built-in logging:

    If you have configured Application Insights along with the Azure Functions, you can monitor complete details like:

    For more details, refer "Monitor Azure Functions".

    -----------------------------------------------------------------------------------------------

    If this answer was helpful, click “Mark as Answer” or “Up-Vote”. To provide additional feedback on your forum experience, click here

    Wednesday, June 20, 2018 1:36 PM
    Moderator
  • Hi Dieter,

    Please read through this page for more info on investigating and reporting this type of issues.

    thanks,
    David

    Wednesday, June 20, 2018 6:13 PM
  • App Service Plan

    Deployment using publishing profile

    Runtime version: 1.0.11820.0 (~1)

    WEBSITE_TIME_ZONE = W. Europe Standard Time

    Cron Expression = 

            [FunctionName("WMS_Process_Stock_Timer_60Min")]
           public static void Run([TimerTrigger("0 */60 * * * *")]TimerInfo myTimer, TraceWriter log)

     Function started (Id=0223f046-e511-457a-b484-d9a2acc5620b)  ==> first time
     Function started (Id=59f59e65-2f8b-4b22-8d83-ce34e60162ef)  ==> again in less then a minute
    Function started (Id=7e53b28a-366c-4311-8d35-4c5d79420540) ==> again...

    normally this function only exeutes every hour


    Wednesday, June 20, 2018 6:52 PM
  • Please see this page for instructions on reporting your execution. You are missing the time. You need to paste exactly what you see in the output window.
    Wednesday, June 20, 2018 6:57 PM
  • 2018-06-20T19:03:55.488 [Info] Update stock 8535/14871 FFFine from WMS:8001851001149    ==> not finished
    2018-06-20T19:04:40.795 [Info] Function started (Id=d4b5dc3e-4dad-41cc-b5e1-f674536b0227) ==> starts again
    2018-06-20T19:04:40.795 [Info] Timer hour starts
    2018-06-20T19:04:40.810 [Info] Accessing FTP ftp://91.183.46.62/OUT/Stock/EXP_STOCK_FFFINE.XML
    2018-06-20T19:04:43.388 [Info] Download Complete, status 226 Successfully transferred "/OUT/Stock/EXP_STOCK_FFFINE.XML"
    2018-06-20T19:04:43.388 [Info] Exiting FTP
    2018-06-20T19:04:43.482 [Info] Update stock 1/14871 FFFine from WMS:7297476062806



    2018-06-20T19:04:48.763 [Info] Update stock 118/14871 FFFine from WMS:078257312306
    2018-06-20T19:04:48.810 [Info] Update stock 119/14871 FFFine from WMS:078257312313 ==> not finished
    2018-06-20T19:05:40.396 [Info] Function started (Id=ee22d2b5-3942-4645-941d-f16ae8d2b12b)  ==> starts again
    2018-06-20T19:05:40.396 [Info] Timer hour starts
    2018-06-20T19:05:40.411 [Info] Accessing FTP ftp://91.183.46.62/OUT/Stock/EXP_STOCK_FFFINE.XML
    Wednesday, June 20, 2018 7:06 PM
  • I found the time. The first is 2018-06-20 18:49:33.

    Looking at your logs, your app has a lot of errors that look like this:

    System.Data.SqlClient.SqlException : Execution Timeout Expired.  The timeout period elapsed prior to completion of the operation or the server is not responding. ---> System.ComponentModel.Win32Exception : The wait operation timed out 
       End of inner exception
       at System.Data.SqlClient.SqlConnection.OnError(SqlException exception,Boolean breakConnection,Action`1 wrapCloseInAction)
       at System.Data.SqlClient.SqlInternalConnection.OnError(SqlException exception,Boolean breakConnection,Action`1 wrapCloseInAction)
       at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning(TdsParserStateObject stateObj,Boolean callerHasConnectionLock,Boolean asyncClose)
       at System.Data.SqlClient.TdsParser.TryRun(RunBehavior runBehavior,SqlCommand cmdHandler,SqlDataReader dataStream,BulkCopySimpleResultSet bulkCopyHandler,TdsParserStateObject stateObj,Boolean& dataReady)
       at System.Data.SqlClient.SqlCommand.FinishExecuteReader(SqlDataReader ds,RunBehavior runBehavior,String resetOptionsString,Boolean isInternal,Boolean forDescribeParameterEncryption)
       at System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(CommandBehavior cmdBehavior,RunBehavior runBehavior,Boolean returnStream,Boolean async,Int32 timeout,Task& task,Boolean asyncWrite,Boolean inRetry,SqlDataReader ds,Boolean describeParameterEncryptionRequest)
       at System.Data.SqlClient.SqlCommand.RunExecuteReader(CommandBehavior cmdBehavior,RunBehavior runBehavior,Boolean returnStream,String method,TaskCompletionSource`1 completion,Int32 timeout,Task& task,Boolean& usedCache,Boolean asyncWrite,Boolean inRetry)
       at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion,String methodName,Boolean sendToPipe,Int32 timeout,Boolean& usedCache,Boolean asyncWrite,Boolean inRetry)
       at System.Data.SqlClient.SqlCommand.ExecuteNonQuery()
    

    This is likely the cause of your issues. Are you seeing those errors in your logs? Start by dealing with this situation, and we'll then see whether you still have time trigger issues.

    Wednesday, June 20, 2018 7:07 PM
  • this can happen indeed, but normally the function stops an triggers again in 1 hour, now it triggers again almost immediately.

      

    Wednesday, June 20, 2018 7:19 PM
  • That could be because the error is causing it to retry running the function, which is by design. You need to deal with this exception first. If you don't want it to be retried, you can catch when you call ExecuteNonQuery() from UpdateStock().
    Wednesday, June 20, 2018 7:22 PM
  • Note that you also have this error: "Function 'Run' is async but does not return a Task. Your function may not run correctly." You will also want to tackle this.
    Wednesday, June 20, 2018 7:23 PM
  •  this is a new log, no errors, but still a restart, i will look into the async but if i create a new timer function it's not async by default

    2018-06-20T19:33:12.176 [Info] Function started (Id=bde49e2d-bf87-4698-9d69-35e672cc2a28)
    2018-06-20T19:33:12.192 [Info] Timer hour starts
    2018-06-20T19:33:12.192 [Info] Accessing FTP ftp://91.183.46.62/OUT/Stock/EXP_STOCK_FFFINE.XML
    2018-06-20T19:33:41.441 [Info] Accessing FTP ftp://91.183.46.62/OUT/Stock/EXP_STOCK_FFFINE.XML
    2018-06-20T19:33:43.535 [Info] Download Complete, status 226 Successfully transferred "/OUT/Stock/EXP_STOCK_FFFINE.XML"
    2018-06-20T19:33:43.535 [Info] Exiting FTP
    2018-06-20T19:33:43.598 [Info] Update stock 1/14871 FFFine from WMS:7297476062806
    2018-06-20T19:33:43.613 [Info] Update stock 2/14871 FFFine from WMS:3760125260501
    2018-06-20T19:33:43.644 [Info] Update stock 3/14871 FFFine from WMS:5704744014110
     .....
    2018-06-20T19:33:46.550 [Info] Update stock 71/14871 FFFine from WMS:6941057400600
    2018-06-20T19:34:29.232 [Info] Function started (Id=31ed4956-f6f1-4b85-ad11-2db91a200158)
    2018-06-20T19:34:29.248 [Info] Timer hour starts
    2018-06-20T19:34:29.248 [Info] Accessing FTP ftp://91.183.46.62/OUT/Stock/EXP_STOCK_FFFINE.XML
    2018-06-20T19:34:58.435 [Info] Accessing FTP ftp://91.183.46.62/OUT/Stock/EXP_STOCK_FFFINE.XM

    Wednesday, June 20, 2018 7:39 PM
  • it's getting even worse

    this is a other function that normally fires every 5 min it fires much faster...

    2018-06-20T20:08:19.287 [Info] Function started (Id=65fe45fe-9922-4a9c-9a7c-9c3f8f6fbd9e)
    2018-06-20T20:08:19.491 [Info] ProductUploadTimer started
    2018-06-20T20:09:06.196 [Info] Assembly reference changes detected. Restarting host...
    2018-06-20T20:10:56  No new trace in the past 1 min(s).
    2018-06-20T20:11:50.008 [Info] Function started (Id=cf805829-96f8-478a-91cb-e4d9160662ff)
    2018-06-20T20:11:50.430 [Info] Function started (Id=752b9090-e7e3-484f-a5d5-2f7fd1da9437)
    2018-06-20T20:11:50.493 [Info] ProductUploadTimer started
    2018-06-20T20:11:50.586 [Info] ProductUploadTimer started
    2018-06-20T20:12:58  No new trace in the past 1 min(s).
    2018-06-20T20:13:55.033 [Info] Function started (Id=ce1dda9a-88c1-4267-b759-8af3391b0d45)
    2018-06-20T20:13:55.065 [Info] ProductUploadTimer started
    2018-06-20T20:14:58  No new trace in the past 1 min(s).
    2018-06-20T20:15:43.119 [Info] Function started (Id=29405382-3082-47d4-8ce4-2369e62945f6)
    2018-06-20T20:15:43.119 [Info] ProductUploadTimer started
    2018-06-20T20:16:59  No new trace in the past 1 min(s).
    2018-06-20T20:17:13.693 [Info] Function started (Id=5cb34a6a-0755-4899-8926-962adf6652ba)
    2018-06-20T20:17:13.912 [Info] ProductUploadTimer started

    Wednesday, June 20, 2018 8:18 PM
  • Still seeing a lot of exceptions around that time. e.g.

    System.InvalidOperationException : BeginExecuteNonQuery requires an open and available Connection. The connection's current state is closed.
       at System.Data.SqlClient.SqlCommand.ValidateCommand(String method,Boolean async)
       at System.Data.SqlClient.SqlCommand.InternalExecuteNonQuery(TaskCompletionSource`1 completion,String methodName,Boolean sendToPipe,Int32 timeout,Boolean& usedCache,Boolean asyncWrite,Boolean inRetry)
    

    So this makes me curious: are you not seeing these exceptions when you run the function? If so, there must be some logging bug somewhere. 

    Wednesday, June 20, 2018 10:15 PM
  • i have a other example, there are no exceptions visible in the monitor and no exceptions in AppInsigts.

    The function start at 2:59:59, that is the correct time (cron expresssion is "0 */60 * * * *"), the name of the function is WMS_Process_Stock_Timer_60Min.

    The function stops at 3:20:06 without a error

    The function id is 614a9337-870f-420d-b9af-27d73d867d05 . The same happens between 01:59:00 and 02:59:00, the function starts correct but stops at 02:23:48 for no reason

    and between 04:59:59 and 05:40:46 everything went well, no exceptions and the function executed completely without problems

    • Edited by FFFine Thursday, June 21, 2018 3:53 AM
    Thursday, June 21, 2018 3:29 AM
  • You had SQL exceptions initially, and then different SQL exceptions on the second attempt. Before we go further, I would like to settle one important point: when you are getting those exceptions, do you see them in the output and in the App Insights logs? If not, then you may be getting more of them that you don't know about, causing further issues.
    Thursday, June 21, 2018 4:11 AM
  • Also, same question goes for the async issue. Are you getting this message? Please make sure it is addressed as it can cause issues.

    thanks,
    David

    Thursday, June 21, 2018 4:28 AM
  • there a no exceptions in the output and the app insights logs, the function just stops,
    Thursday, June 21, 2018 6:14 AM
  • i have implemented the async keyword and the await for the complete function including the database access
    Thursday, June 21, 2018 6:14 AM
  • I still see the async warning as of 2018-06-21 11:36:41 UTC. In addition, you may be running into the default 5 minute timeout. Try increasing it, per documentation.

    If you need to share any new invocations for investigation, please make sure to specify the UTC time and not your local time.

    David

    Thursday, June 21, 2018 2:21 PM
  • Hello

    I still have a lot of problems with this. I have 1 function that has to update 10.000 records in a database.

    First i was using a timer, now i have changed this to a blob trigger. The trigger is fired but the funtions just ends without any error (that i can i see). I catch exceptions but i can't see anything, not even in app insights. This was the functions

    2018-06-26T12:32:24.277 [Info] Function started (Id=2df977c2-2383-49d0-abc2-c29dec80f737)2018-06-26T12:32:24.965 [Info]

    2018-06-26T14:42:42.470 [Info] Function started (Id=0fe11520-4895-47ce-b17d-aa73e1a034d9)
    2018-06-26T14:42:42.957 [Info] C# Blob trigger function Processed blob
     Name:prev-plastinox.csv 
     Size: 2337973 Bytes
    2018-06-26T14:42:43.736 [Info] Checking new brands
    2018-06-26T14:42:43.736 [Info] Updating database...

    When i run this local, this works perfect, very very strange

    I don't know what to do anymore...

    regards

    Dieter


    • Edited by FFFine Tuesday, June 26, 2018 2:45 PM
    Tuesday, June 26, 2018 12:35 PM
  • Based on our logs, it appears that this function is making a system call that is getting blocked by the App Service Sandbox. The specific system API is NtSetInformationProcess.

    Do you know what the code is doing for this function. Is it doing anything unusual that could be triggering this call?

    David

    Tuesday, June 26, 2018 5:46 PM
  • i am iterating a list with 10K objects and i have to update the database item for every object in the list.

    Everything is async, i can send you the code privately trough twitter if you want

    Tuesday, June 26, 2018 6:30 PM
  • Does it only repro when iterating through a large list, or does it happen regardless of the number of items being processed? Also, does the issue happen 100%, or randomly? It would be great to try to isolate it to help get to the bottom of it.

    If needed, you can email me at david.ebbo (at) microsoft.com to share sources, etc...

    thanks,
    David

    Tuesday, June 26, 2018 7:09 PM
  • Also, please take a look at d:\home\LogFiles\EventLog.xml (using Kudu Console), and check whether it has interesting events that match the time where you see the issue.

    David

    Wednesday, June 27, 2018 4:51 PM
  • Any update on this thread? 
    Monday, July 2, 2018 7:59 PM
    Moderator
  • To follow up, we identified the issue offline. It was caused by App Insights sampling behavior, which is on by default but can be disabled (per documentation).

    David

    • Proposed as answer by David Ebbo Wednesday, July 4, 2018 5:30 PM
    Wednesday, July 4, 2018 5:30 PM