0
votes

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

Action Execution Graph

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

Logic App Suspend? Logs

2

2 Answers

0
votes

Logic Apps will not be idle once its triggered. In your case, the Logic App would have retried few action for certain period. The retry policy is configurable upto 1 day. You can inspect and check the Logic App run if it has under gone some retries.

0
votes

It seems there is something wrong in your "if condition". Your screenshot shows the "condition" took 0 millisecond, but it should be cancelled because of some error in the second "if condition". The run history of logic app shows 0s and misleading us.

I did a test in my side, please refer to my logic app below: enter image description here In my logic, I created a "delay" action to delay 10 minutes, then I run this logic app manually. The logic app ran the steps before the "delay" action quickly and then stayed at the "delay" action. Before 10 minutes, I use this api to cancel this logic app, we can see it was cancelled in "Run history"(shown as below screenshot). enter image description here Then I click this item in "Run history"(I clicked it after 10 minutes, if click it before 10 minutes, the condition will show x minutes and "running" status), the "condition" shows 0s(same to yours) but not 10 minutes or longer. enter image description here

According to my test, the logic app run a few minutes but the "condition" just show 0s, so I think the "condition" in your logic app also took most of the time in 38 minutes, please check the two "if condition" in your logic app. I think it should be something wrong in your second condition and it result in the cancel of your first condition.