One of our Azure Logic Apps is experiencing a bizarre gap in timing from time of invocation to the time it actually begins executing. This is resulting in extremely long and erroneous run lengths. Here is an example of a problematic run:
Start date: Friday, December 13, 2019, 1:45:42 PM
End date: Friday, December 13, 2019, 2:24:30 PM
Run Duration: 38.79 minutes
Check_if_journal_file 0 Milliseconds
Condition 0 Milliseconds
Delay 1.52 Seconds
Get_Blob_Metadata 15 Milliseconds
HTTP 281 Milliseconds
ImportBreakpointJournalFile 406 Milliseconds
Initialize_JobHttpStatusCode 110 Milliseconds
Journal_file_failed_to_process 0 Milliseconds
Journal_file_successfully_processed 31 Milliseconds
Not_a_journal_file 0 Milliseconds
Set_variable 157 Milliseconds
Until 4.69 Seconds
Actual Action Execution Duration: 7.21 seconds
Since the execution itself only took ~7 seconds, that means the logic app was just sitting there idling doing nothing for almost 38 minutes! Runs previous to this one show no timing problems.
Has anyone else seen behavior like this?
What would cause a logic app to idle for 38 minutes before beginning execution?
UPDATE:
Turned on detailed diagnostics for the logic app and got the following results which show that it really is idling or suspended. You can see that job 08586252374669322278104928528CU37 begins at 12:23 then almost immediately suspends? before taking any action and then resumes at 12:58 for no apparent reason. After resuming you can see it begins executing normally as Initialize_JobHttpStatusCode is the first action in the app.
TimeGenerated [UTC] startTime_t [UTC] waitEndTime_t [UTC] resource_runId_s resource_originRunId_s resource_actionName_s endTime_t [UTC]
12/15/2019, 12:58:57.627 AM 12/15/2019, 12:58:57.471 AM Invalid Date 08586252374669322278104928528CU37 Initialize_JobHttpStatusCode 12/15/2019, 12:58:57.549 AM
12/15/2019, 12:58:57.540 AM 12/15/2019, 12:58:57.471 AM Invalid Date 08586252374669322278104928528CU37 Initialize_JobHttpStatusCode Invalid Date
12/15/2019, 12:58:57.405 AM 12/15/2019, 12:23:38.550 AM 12/15/2019, 12:58:57.330 AM 08586252374669322278104928528CU37 08586252374669322278104928528CU37 Invalid Date
12/15/2019, 12:58:57.282 AM 12/15/2019, 12:58:56.901 AM Invalid Date 08586252353485738359883907091CU99 12/15/2019, 12:58:56.980 AM
12/15/2019, 12:58:57.258 AM 12/15/2019, 12:58:56.901 AM Invalid Date 08586252353485738359883907091CU99 Invalid Date
12/15/2019, 12:58:57.247 AM 12/15/2019, 12:58:56.909 AM Invalid Date 08586252353485738359883907091CU99 08586252353485738359883907091CU99 Invalid Date
12/15/2019, 12:23:39.275 AM 12/15/2019, 12:23:38.534 AM Invalid Date 08586252374669322278104928528CU37 12/15/2019, 12:23:39.034 AM
12/15/2019, 12:23:39.172 AM 12/15/2019, 12:23:38.534 AM Invalid Date 08586252374669322278104928528CU37 Invalid Date
12/15/2019, 12:23:39.143 AM 12/15/2019, 12:23:38.550 AM Invalid Date 08586252374669322278104928528CU37 08586252374669322278104928528CU37 Invalid Date