Azure / Azure/Azure-Functions

Azure Function, either In-Process or Independent Worker, catches exception but then continues executing code after the throw reaching 200 OK.

Open
#2,484 0 comments 0 reactions 0 assignees View on GitHub
Dominant language
PowerShell
Stars
1.1k
Forks
215
Avg merge
4h 2m
Merged PRs (30d)
1

Description

# Issue Transfer

This issue has been transferred from the Azure SDK for .NET repository, [#44059](https://github.com/Azure/azure-sdk-for-net/issues/44059).

### Please be aware that @radumi is the author of the original issue and include them for any questions or replies.

## Details

Azure Function, either In-Process or Independent Worker, catches exception but then continues executing code after the throw reaching 200 OK instead of just 400 BadRequest

```csharp
[FunctionName(nameof(ChoiceInPHttpTrigger))]
public static async Task RunAsync([HttpTrigger(AuthorizationLevel.Anonymous, "get", "post", Route = null)] HttpRequest req, ILogger log)
{
Task tResp = ProcessInP.ProcessChoiceInPHttpTriggerAsync(req, log);
HttpResponseMessage resp = await tResp;
return resp;
}

public static async Task ProcessChoiceInPHttpTriggerAsync(HttpRequest req, ILogger log, Processor proc = null)
{
string signature = nameof(ProcessChoiceInPHttpTriggerAsync);

try
{
signature = GetSignature(req);
log.LogTrace($"{signature} BEGIN {req?.Method} content len={req?.ContentLength} type={req?.ContentType} isJson={req?.IsJsonContentType()}");

LocalState lst = await LocalStateFactoryInP.CreateStateAsync(req);
lst.ResultData = await Process.ApplyProcessorAsync(lst, proc ?? new Processor(log)); //Exception is just thrown from inside there from a synchronous static method

log.LogWarning($"WARN {signature} IF YOU SEE THIS OK STATUS there should NOT be an exception in the scope above!");
HttpResponseMessage resp = ResponseFactory.CreateResponse(HttpStatusCode.OK, lst.ResultData);

log.LogTrace($"{signature} END status={resp.StatusCode} success={resp.IsSuccessStatusCode}");
return resp;
}
catch (ArgumentException ex)
{
log.LogError($"ERROR {signature} status={HttpStatusCode.BadRequest} message={ex.Message}");
return ResponseFactory.CreateResponseString(HttpStatusCode.BadRequest, ex.Message);
}
catch (ApplicationException ex)
{
log.LogError($"ERROR {signature} status={HttpStatusCode.ExpectationFailed} message={ex.Message}");
return ResponseFactory.CreateResponseString(HttpStatusCode.ExpectationFailed, ex.Message);
}
catch (Exception ex)
{
log.LogError($"ERROR {signature} status={HttpStatusCode.InternalServerError} message={ex.Message} {ex.StackTrace}");
return ResponseFactory.CreateResponseString(HttpStatusCode.InternalServerError, "See log for details");
}
}

public static async Task ApplyProcessorAsync(LocalState lst = null, Processor proc = null)
{
Validator.ValidateInput(lst);

var res = new Result();

res.Data = await proc.SomeProc.HitSomeDBReadUpperCaseAsync(lst.RepresentationData.Data);

//Tests run in about 6 seconds
//res.Length = await proc.OtherProc.HitSomeStorageReadLengthAsync(res.Data);
//res.LenOverride = await proc.OtherProcInherit.HitSomeStorageReadLengthAsync(res.Data);

//Tests run in about 4.5 seconds
IOtherProcessor[] ops = new List() { proc.OtherProc, proc.OtherProcInherit }.ToArray();
int[] r = await ComputeAsync(res.Data, ops);
res.Length = r[0];
res.LenOverride = r[1];

Validator.ValidateResult(res);

return res;
}

public static bool ValidateInput(LocalState lst)
{
if (lst == null)
throw new ArgumentNullException("lst", "LocalState missing");

if (lst.RepresentationData == null)
throw new ArgumentException("lst.RepresentationData", "Representation missing");

if (string.IsNullOrEmpty(lst.RepresentationData.Data))
throw new ArgumentException("lst.RepresentationData.Data", "Representation data missing"); // IT THROWS HERE

return true;
}
```

### Expected behavior

Log from Debug in VStudio - works as expected also like in XUnit test - catches exception returning BadRequest

```text
[2024-05-15T19:08:58.029Z] Found C:\Test\Choice-AzF-SMC_C#\ChoiceAzF_InProcess\ChoiceAzF_InProcess.csproj. Using for user secrets file configuration.
Functions:
ChoiceInPHttpTrigger: [GET,POST] http://localhost:7039/api/ChoiceInPHttpTrigger
For detailed output, run func with --verbose flag.
[2024-05-15T19:09:07.099Z] Host lock lease acquired by instance ID '000000000000000000000000153F1E48'.
[2024-05-15T19:09:28.090Z] Executing 'ChoiceInPHttpTrigger' (Reason='This function was programmatically called via the host APIs.', Id=30781b89-2059-4a5c-920e-6be3610eae91)

[2024-05-15T19:09:28.188Z] ERROR 0HN3L2A5CL2DU:00000002 Process status=BadRequest message=lst.RepresentationData.Data (Parameter 'Representation data missing')

[2024-05-15T19:09:28.220Z] Executed 'ChoiceInPHttpTrigger' (Succeeded, Id=30781b89-2059-4a5c-920e-6be3610eae91, Duration=148ms)

Only works in Individual Worker model by adding [FromBody] RData representationData parameter
Still, I see the ERROR BadRequest logged twice
ProcessChoiceInWHttpTriggerAsync status=BadRequest message=lst.RepresentationData.Data (Parameter 'Representation data missing')

Connected!
2024-05-15T18:50:51Z [Information] Executing 'Functions.ChoiceInWHttpTrigger' (Reason='This function was programmatically called via the host APIs.', Id=9498f5d3-3b2d-4506-851e-a128d1f06ddc)
2024-05-15T18:50:51Z [Verbose] Sending invocation id: '9498f5d3-3b2d-4506-851e-a128d1f06ddc
2024-05-15T18:50:51Z [Verbose] Posting invocation id:9498f5d3-3b2d-4506-851e-a128d1f06ddc on workerId:1473cb2a-03a8-4bef-9aa5-3cff83557996
2024-05-15T18:50:51Z [Information] 00-92640c9328aa71d06d492cce580bf5a4-f50925cec95a7974-00 ProcessChoiceInWHttpTriggerAsync BEGIN verb=POST

2024-05-15T18:50:51Z [Error] ERROR 00-92640c9328aa71d06d492cce580bf5a4-f50925cec95a7974-00 ProcessChoiceInWHttpTriggerAsync status=BadRequest message=lst.RepresentationData.Data (Parameter 'Representation data missing')

2024-05-15T18:50:51Z [Information] Executed 'Functions.ChoiceInWHttpTrigger' (Succeeded, Id=9498f5d3-3b2d-4506-851e-a128d1f06ddc, Duration=258ms)
2024-05-15T18:50:52Z [Information] Executing 'Functions.ChoiceInWHttpTrigger' (Reason='This function was programmatically called via the host APIs.', Id=bf9dcb41-917b-4a95-b4ea-5855e9fa6c0e)
2024-05-15T18:50:52Z [Verbose] Sending invocation id: 'bf9dcb41-917b-4a95-b4ea-5855e9fa6c0e
2024-05-15T18:50:52Z [Verbose] Posting invocation id:bf9dcb41-917b-4a95-b4ea-5855e9fa6c0e on workerId:1473cb2a-03a8-4bef-9aa5-3cff83557996
2024-05-15T18:50:52Z [Information] 00-997a8f60572f4daaa1ddc4c448cf827a-f6ed3b529d0f24bc-01 ProcessChoiceInWHttpTriggerAsync BEGIN verb=POST

2024-05-15T18:50:52Z [Error] ERROR 00-997a8f60572f4daaa1ddc4c448cf827a-f6ed3b529d0f24bc-01 ProcessChoiceInWHttpTriggerAsync status=BadRequest message=lst.RepresentationData.Data (Parameter 'Representation data missing')

2024-05-15T18:50:52Z [Information] Executed 'Functions.ChoiceInWHttpTrigger' (Succeeded, Id=bf9dcb41-917b-4a95-b4ea-5855e9fa6c0e, Duration=12ms)
```

```csharp
[Function(nameof(ChoiceInWHttpTrigger))]
//public HttpResponseData Run([HttpTrigger(AuthorizationLevel.Anonymous, "get", "post", Route = null)] HttpRequestData req, [FromBody] RData representationData, FunctionContext ctx)
public async Task RunAsync(
[HttpTrigger(AuthorizationLevel.Anonymous, "get", "post", Route = null)] HttpRequestData req,
[FromBody] RData representationData,
FunctionContext ctx)
{
try
{
Task tResp = ProcessInW.ProcessChoiceInWHttpTriggerAsync(req, Log, representationData, Procs);
HttpResponseData resp = await tResp;
return resp;
}
catch (Exception ex)
{
Log.LogError($"ERROR {nameof(ChoiceInWHttpTrigger)} ex={ex.Message} {ex.StackTrace}");
return req.CreateResponse(HttpStatusCode.InternalServerError);
}
}

public static async Task ProcessChoiceInWHttpTriggerAsync(HttpRequestData req, ILogger log, IData payload, Processor proc = null)
{
string signature = nameof(ProcessChoiceInWHttpTriggerAsync);

try
{
signature = GetSignature(req, nameof(ProcessChoiceInWHttpTriggerAsync));
log.LogInformation($"{signature} BEGIN verb={req?.Method}");

LocalState lst = LocalStateFactoryInW.CreateState(req, payload);
lst.ResultData = await Process.ApplyProcessorAsync(lst, proc ?? new Processor(log)); //Exception is just thrown from inside there from a synchronous static method

log.LogWarning($"WARN {signature} IF YOU SEE THIS OK STATUS there should NOT be an exception in the scope above!");
HttpResponseData resp = ResponseFactory.Response(req.CreateResponse(HttpStatusCode.OK), lst.ResultData);

log.LogInformation($"{signature} END status={resp.StatusCode}");
return resp;
}
catch (ArgumentException ex)
{
log.LogError($"ERROR {signature} status={HttpStatusCode.BadRequest} message={ex.Message}");
return ResponseFactory.ResponseString(req.CreateResponse(HttpStatusCode.BadRequest), ex.Message);
}
catch (ApplicationException ex)
{
log.LogError($"ERROR {signature} status={HttpStatusCode.ExpectationFailed} message={ex.Message}");
return ResponseFactory.ResponseString(req.CreateResponse(HttpStatusCode.ExpectationFailed), ex.Message);
}
catch (Exception ex)
{
log.LogError($"ERROR {signature} status={HttpStatusCode.InternalServerError} message={ex.Message} {ex.StackTrace}");
return ResponseFactory.ResponseString(req.CreateResponse(HttpStatusCode.InternalServerError), "See log for details");
}
}
```

Program.cs of the Independent Worker example is :

```csharp
using Microsoft.Extensions.Hosting;
using System.Diagnostics.CodeAnalysis;

//var host = new HostBuilder().ConfigureFunctionsWorkerDefaults().Build();
//await host.RunAsync();
//host.Run();

namespace ChoiceAzFIndividualWorker
{
[ExcludeFromCodeCoverage]
static class Program
{
static async Task Main(string[] args)
{
var host = new HostBuilder().ConfigureFunctionsWorkerDefaults().Build();
await host.RunAsync();
//host.Run();
}
}
}
```

### Actual behavior

Log running in Azure - after exception caught, still executes "Process IF YOU SEE THIS OK STATUS there should NOT be an exception in the scope above!"

Connected!
2024-05-15T19:15:50Z [Information] Executing 'ChoiceInPHttpTrigger' (Reason='This function was programmatically called via the host APIs.', Id=fdef415e-1402-4943-8edf-200fd9796ba3)
2024-05-15T19:15:51Z [Verbose] 4000020e-0000-ec00-b63f-84710c7967bb Process BEGIN POST content len=0 type=application/json isJson=True

2024-05-15T19:15:51Z [Error] ERROR 4000020e-0000-ec00-b63f-84710c7967bb Process status=BadRequest message=lst.RepresentationData.Data (Parameter 'Representation data missing')

2024-05-15T19:15:51Z [Information] Executed 'ChoiceInPHttpTrigger' (Succeeded, Id=fdef415e-1402-4943-8edf-200fd9796ba3, Duration=62ms)
2024-05-15T19:15:51Z [Information] Executing 'ChoiceInPHttpTrigger' (Reason='This function was programmatically called via the host APIs.', Id=d7fb7cb6-12f7-4821-a218-925c011f0f49)
2024-05-15T19:15:51Z [Verbose] 4000020f-0000-ec00-b63f-84710c7967bb Process BEGIN POST content len=2 type=application/json isJson=True

2024-05-15T19:15:51Z [Warning] WARN 4000020f-0000-ec00-b63f-84710c7967bb Process IF YOU SEE THIS OK STATUS there should NOT be an exception in the scope above!

2024-05-15T19:15:51Z [Verbose] 4000020f-0000-ec00-b63f-84710c7967bb Process END status=OK success=True
2024-05-15T19:15:51Z [Information] Executed 'ChoiceInPHttpTrigger' (Succeeded, Id=d7fb7cb6-12f7-4821-a218-925c011f0f49, Duration=242ms)

### Reproduction Steps

Function is https://choiceaesb.azurewebsites.net/api/ChoiceInPHttpTrigger
POST with nothing in the body to see the 200 OK coming after the throw.

The one that works is https://choiceiwaesb.azurewebsites.net/api/ChoiceInWHttpTrigger
POST { "Data": "" } or { "Data": null } in the body to get the clean 400 Bad Request
POST { "Data": "test" } to get the clean 200 OK

### Environment

Runtime 4.34.1.22669, .Net 6.0 hosted on Windows, AustraliaEastPlan (Y1: 0)

Contributor guide

No contributing guide indexed for this repository

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.