Azure Function HttpClient doesn't give any response and keeps retrying

Question

I have a Function App running in Azure. It is a HttpTrigger, and it is triggered by a Stream Analytics, with a Retry Policy set to Drop. It is coded in C#, and deployed from DevOps through CI/CD. Here are some of the configs.

FUNCTIONS_EXTENSION_VERSION: ~4
FUNCTIONS_WORKER_RUNTIME: dotnet-isolated
WEBSITE_RUN_FROM_PACKAGE: 1

The purpose of the function is to get some data and forward it using a HttpClient (created through a HttpClientFactory, and with a timeout of 15 sec) to various other endpoints on different servers. Everything have worked so far, until recently where a new endpoint on a new server was added. The problem is somehow related to this new server, but I am having a hard time getting any useful logs from my end, and also the whole Function is acting weird when sending data. Here is the end of the code:

        log.LogInformation($"Preparing to send...");
        var content = new StringContent(jsonContent, Encoding.UTF8, "application/json");
        var httpRequestMessage = new HttpRequestMessage
        {
            Method = HttpMethod.Post,
            RequestUri = new Uri(uri),
            Headers = {
                { "Authorization", $"Bearer {token}" },
                { "Accept", "*/*" },
            },
            Content = content
        };
        var response = await _httpClient.SendAsync(httpRequestMessage);
        var responseString = await response.Content.ReadAsStringAsync();
        log.LogInformation($"Returned content: {responseString}.");

I use Application Insights to monitor. The uri parameter is different based on where to send the data, and it is working for everywhere except 1 endpoint. When I try to send to this "faulty" endpoint, this is what I see in Application Insights:

01:27:37 PM Trace: Preparing to send...
01:27:37 PM Trace: Start processing HTTP request POST https://... (URI parameter)
01:27:37 PM Trace: Sending HTTP request POST https://... (URI Parameter)
01:27:37 PM Trace: End processing HTTP request after 188.05ms - OK
01:27:37 PM Trace: Received HTTP response after 187.92ms - OK
01:29:17 PM Exception: Exception while executing function: Functions.MyFunction
01:29:17 PM Trace:Executed 'Functions.MyFunction' (Failed, Id=3d9afe5b-c58a-470d-8f54-0d98ca60deb7, Duration=100005ms
01:29:17 PM Exception: Exception while executing function: Functions.MyFunction

When I inspect the exception, it says:

    Exception while executing function: Functions.MyFunction Result: Failure
Exception: System.AggregateException: One or more errors occurred. (A task was canceled.)
 ---> System.Threading.Tasks.TaskCanceledException: A task was canceled.
   at System.Threading.Tasks.Task.GetExceptions(Boolean includeTaskCanceledExceptions)
   at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
   at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
   at Microsoft.Azure.Functions.Worker.Invocation.DefaultFunctionInvoker`2.<>c.<InvokeAsync>b__6_0(Task`1 t) in D:\a\1\s\src\DotNetWorker.Core\Invocation\DefaultFunctionInvoker.cs:line 32
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.Tasks.Task.<>c.<.cctor>b__272_0(Object obj)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
   at System.Threading.Tasks.Task.ExecuteFromThreadPool(Thread threadPoolThread)
   at System.Threading.ThreadPoolWorkQueue.Dispatch()
   at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
   at System.Threading.Thread.StartCallback()
--- End of stack trace from previous location ---

   --- End of inner exception stack trace ---
   at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
   at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
   at Microsoft.Azure.Functions.Worker.Invocation.DefaultFunctionInvoker`2.<>c.<InvokeAsync>b__6_0(Task`1 t) in D:\a\1\s\src\DotNetWorker.Core\Invocation\DefaultFunctionInvoker.cs:line 32
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.Tasks.Task.<>c.<.cctor>b__272_0(Object obj)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
   at Microsoft.Azure.Functions.Worker.Invocation.DefaultFunctionExecutor.ExecuteAsync(FunctionContext context) in D:\a\1\s\src\DotNetWorker.Core\Invocation\DefaultFunctionExecutor.cs:line 45
   at Microsoft.Azure.Functions.Worker.OutputBindings.OutputBindingsMiddleware.Invoke(FunctionContext context, FunctionExecutionDelegate next) in D:\a\1\s\src\DotNetWorker.Core\OutputBindings\OutputBindingsMiddleware.cs:line 16
   at Microsoft.Azure.Functions.Worker.GrpcWorker.InvocationRequestHandlerAsync(InvocationRequest request, IFunctionsApplication application, IInvocationFeaturesFactory invocationFeaturesFactory, ObjectSerializer serializer, IOutputBindingsInfoProvider outputBindingsInfoProvider) in D:\a\1\s\src\DotNetWorker.Grpc\GrpcWorker.cs:line 167
Stack:    at System.Threading.Tasks.Task.ThrowIfExceptional(Boolean includeTaskCanceledExceptions)
   at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
   at Microsoft.Azure.Functions.Worker.Invocation.DefaultFunctionInvoker`2.<>c.<InvokeAsync>b__6_0(Task`1 t) in D:\a\1\s\src\DotNetWorker.Core\Invocation\DefaultFunctionInvoker.cs:line 32
   at System.Threading.Tasks.ContinuationResultTaskFromResultTask`2.InnerInvoke()
   at System.Threading.Tasks.Task.<>c.<.cctor>b__272_0(Object obj)
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
   at Microsoft.Azure.Functions.Worker.Invocation.DefaultFunctionExecutor.ExecuteAsync(FunctionContext context) in D:\a\1\s\src\DotNetWorker.Core\Invocation\DefaultFunctionExecutor.cs:line 45
   at Microsoft.Azure.Functions.Worker.OutputBindings.OutputBindingsMiddleware.Invoke(FunctionContext context, FunctionExecutionDelegate next) in D:\a\1\s\src\DotNetWorker.Core\OutputBindings\OutputBindingsMiddleware.cs:line 16
   at Microsoft.Azure.Functions.Worker.GrpcWorker.InvocationRequestHandlerAsync(InvocationRequest request, IFunctionsApplication application, IInvocationFeaturesFactory invocationFeaturesFactory, ObjectSerializer serializer, IOutputBindingsInfoProvider outputBindingsInfoProvider) in D:\a\1\s\src\DotNetWorker.Grpc\GrpcWorker.cs:line 167 

And then it seems the function retries the Http request, which I don't understand why. The "Preparing to send" log is not present, but the "Start processing" logs appears and fails every ~2 minutes. Since my custom log message is not here, I take it that it is the HttpClient that is retrying somehow and not the entire Function.

Does anyone have a clue what is going on? Why does my code seem to get stuck trying to read the response.Content? How can I further investigate what is going wrong, and why is the HttpClient retrying itself like this? I would expect the Function to crash/stop if the HttpClient fails.

EDIT: Corrected timestamps on log to match duration. There are multiple logs appearing at the same time, and I picked wrong ones.

Answer 1

With tip from Thiago of changing from async, I have received a proper exception, which helped me put the pieces together.

The new error:

The request was canceled due to the configured HttpClient.Timeout of 100 seconds elapsing.

I am using 2 different HttpClients, one for my error and another for a timed Token updater. It seems my first issue was me adding the 15 sec Timeout to the wrong client (doh). With this new info, the duration of 100005ms makes much more sense.

Next, the timeout exception from the HttpClient were not caught, and caused the whole function to crash producing the "A task was cancelled" error.

Finally, the reason it keeps restarting seems to be caused by Azure Stream Analytics after all. On a closer look at the error policy docs, it seems despite being set to "Drop", it will still retry in some cases based on the error.

I still have a problem as to why my request times out, but my original question as to what was going on is answered :)

Answer 2

Hard to help as we don't have access to your environment, but here's what I would try:

It seems to me that the issue with the log is because it's an async operation, this log doesn't represent the inner/real exception. I recommend you switch to a sync operation and send to this faulty endpoint. Once you get the real exception / proper fix, you switch back to async operation.