Azure Function is calling itself twice on App service plan

Question

I have the following code in my azure function with 10 minutes manual timeout.

using System.Net;

public static async Task<HttpResponseMessage> Run(HttpRequestMessage req, TraceWriter log)
{
    log.Info("C# HTTP trigger function processed a request.");
    try
    {
        TimeSpan ts = TimeSpan.FromMinutes(1);
        for(int i=0;i<10;i++)
        {
            await Task.Delay(ts);
            log.Info(String.Format("After 1 Min Delay {0}",i));
        }
        log.Info(String.Format("After 10 Min Delay "));
        return req.CreateResponse(HttpStatusCode.OK);
    }
    catch (Exception e)
    {
        log.Info(String.Format("exception: {0}", e));
        return req.CreateResponse(HttpStatusCode.BadRequest);
    }
}

when I run the above function in Azure, I see the function creates a new instance after 3 minutes. (check the below log)

2018-05-15T11:12:42  Welcome, you are now connected to log-streaming service.
2018-05-15T11:12:55.826 [Info] Function started (Id=f25e0bbd-7103-4823-b8f1-ef28888f7007)
2018-05-15T11:12:55.826 [Info] C# HTTP trigger function processed a request.
2018-05-15T11:13:55.844 [Info] After 1 Min Delay 0
2018-05-15T11:14:55.857 [Info] After 1 Min Delay 1
2018-05-15T11:15:55.862 [Info] After 1 Min Delay 2
2018-05-15T11:16:47.385 [Info] Function started (Id=7371ed94-9b62-40cc-bec0-00b8d5e0a250)
2018-05-15T11:16:47.385 [Info] C# HTTP trigger function processed a request.
2018-05-15T11:16:55.879 [Info] After 1 Min Delay 3
2018-05-15T11:17:47.395 [Info] After 1 Min Delay 0
2018-05-15T11:17:55.883 [Info] After 1 Min Delay 4
2018-05-15T11:18:47.400 [Info] After 1 Min Delay 1
2018-05-15T11:18:55.899 [Info] After 1 Min Delay 5
2018-05-15T11:19:47.411 [Info] After 1 Min Delay 2
2018-05-15T11:19:55.914 [Info] After 1 Min Delay 6
2018-05-15T11:20:47.413 [Info] After 1 Min Delay 3
2018-05-15T11:20:55.920 [Info] After 1 Min Delay 7
2018-05-15T11:21:47.416 [Info] After 1 Min Delay 4
2018-05-15T11:21:55.930 [Info] After 1 Min Delay 8
2018-05-15T11:22:47.436 [Info] After 1 Min Delay 5
2018-05-15T11:22:55.936 [Info] After 1 Min Delay 9
2018-05-15T11:22:55.936 [Info] After 10 Min Delay
2018-05-15T11:22:55.936 [Info] Function completed (Success, Id=f25e0bbd-7103-4823-b8f1-ef28888f7007, Duration=600105ms)
2018-05-15T11:23:47.447 [Info] After 1 Min Delay 6
2018-05-15T11:24:47.452 [Info] After 1 Min Delay 7
2018-05-15T11:25:47.467 [Info] After 1 Min Delay 8
2018-05-15T11:26:47.478 [Info] After 1 Min Delay 9
2018-05-15T11:26:47.478 [Info] After 10 Min Delay
2018-05-15T11:26:47.478 [Info] Function completed (Success, Id=7371ed94-9b62-40cc-bec0-00b8d5e0a250, Duration=600086ms)

In above log, you can see that azure function is calling twice and also it gives the error (500: internal server error) and after it completes its execution.

Why do you think it's calling itself? Is that reproducible every time? — Mikhail Shilkov, May 15 '18 at 12:09
Isn't that the maximum execution time on a Consumption plan? The runtime probably restarts your function once it reaches the timeout threshold. — evilSnobu, May 15 '18 at 19:58
@Mikhail you can check the log in which you see the function is starting two times with different instances — Sumit Garg, May 16 '18 at 02:55
@evilSnobuI mentioned in the title I am using the app service plan in which maximum execution time can be more than 10 minutes — Sumit Garg, May 16 '18 at 02:58
@SumitGarg which means somebody called it 2 times, not that it calls itself. You didn't answer if it's reproducible. — Mikhail Shilkov, May 16 '18 at 07:11
@SumitGarg could you share the exception details ? Also how are you calling your function ? What are you trying to show here ? — Thomas, May 16 '18 at 09:23
@ThomasI am not getting any exception. my question why the azure function is calling itself after 3 minutes — Sumit Garg, May 16 '18 at 13:15
@Mikhail it is reproducible every time when you run a function after 3 minutes it will call itself. — Sumit Garg, May 16 '18 at 13:18

Jerry Liu · Accepted Answer · 2018-06-06T08:18:00.613

2

It is about http request timeout and retry.

When I run the function directly in portal, it will be called again after nearly 4m like @Sumit and @Joey have seen. I decrease the Delay to 10s, and the function is only triggered once and returns 200.

Try to use postman to post request, this time the function is triggered only once with response message below.

As we can see in the code, no response sent back until 10m process finished. It is beyond the timeout setting and it seems by design that request posted by portal will be retried after timeout.

Update

Azure function is one kind of Azure Web App, see Azure Web App time out 230s setting.

There is a 230 second (i.e. a little less than 4 mins) timeout for requests that are not sending any data back. After that, the client gets the 500 you saw, even though in reality the request is allowed to continue server side

edited Jun 06 '18 at 08:18

answered May 17 '18 at 04:02

Jerry Liu

17,282
4
40
61

yup this approach I tried I got the same. A big thanks to you but It does not make sense that we can run the function more than 10 minutes but in Azure front-end, we can't run more than 4 minutes – Sumit Garg May 17 '18 at 04:29
@SumitGarg Right, function can run for more than 10m on app service plan. But for httptrigger, we send a http request to server and it's required to send response back within timeout, it's a basic requirement for webserver. It seems the 10m+ is for us to run triggers other than httptrigger as the response has to be sent in nearly 4m by default. Could you describe what you want to achieve with `10m manual timeout`? – Jerry Liu May 17 '18 at 04:54
Ques: Could you describe what you want to achieve with 10m manual timeout? ans: I want to process the full tabular model. – Sumit Garg May 17 '18 at 05:10
@SumitGarg Not familiar with tabular model, is it acceptable to leverage timeout settings in ssas? See whether this thread [ssas-tabular-model-timeout](https://stackoverflow.com/questions/49011023/ssas-tabular-model-timeout-raised-during-processing) is useful. – Jerry Liu May 17 '18 at 08:31
I think u didn't notice one thing function will complete after an exception in the background and it will process the full tabular model. The only need I want web server timeout – Sumit Garg May 17 '18 at 09:02
@SumitGarg Sorry for my misinterpretation. Basically httptrigger can't achieve your goal, if it's not necessary to get an immediate feedback like httpresponse, you can use [queue trigger](https://learn.microsoft.com/en-us/azure/azure-functions/functions-bindings-storage-queue) to do your job. If you have to get a httpresponse, you can have a look at [Durable function](https://learn.microsoft.com/en-us/azure/azure-functions/durable-functions-overview). – Jerry Liu May 18 '18 at 05:58

score 0 · Answer 2 · answered May 16 '18 at 08:25

0

I reproduce your problem and found that it seems to be an issue.

the fix is now deployed in version 1.0.11015.0 (visible in the 'Settings' page of the Functions portal). If you are not running this version, manually restart your app and it will pick up the latest version.

Also, as you have said, you use the app service plan. You could run longer than the maximum execution time allowed on the Consumption plan (of 10 minutes).

answered May 16 '18 at 08:25

Joey Cai

18,968
1
20
30

The issue you mentioned is related to `queuetrigger` not `httptrigger`. – Thomas May 16 '18 at 09:19
It almost the same. Because OP run the function but not trigger it and it also get the log. I think it is no related to queuetrigger. – Joey Cai May 16 '18 at 09:25
1

@JoeyCai Thomas is saying correctly that issue was for queuetrigger, not httptrigger. – Sumit Garg May 16 '18 at 12:46

Azure Function is calling itself twice on App service plan

2 Answers2

Linked