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
Isn't that the maximum execution time on a Consumption plan? The runtime probably restarts your function once it reaches the timeout threshold. — evilSnobu
@Mikhail you can check the log in which you see the function is starting two times with different instances — Sumit Garg
@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
@SumitGarg which means somebody called it 2 times, not that it calls itself. You didn't answer if it's reproducible. — Mikhail Shilkov

Jerry Liu Jerry Liu · Accepted Answer · 2018-05-17T04:02:06

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

Azure Function is calling itself twice on App service plan

2 Answers