Azure Function, either In-Process or Independent Worker, catches exception but then continues executing code after the throw reaching 200 OK.
- 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.