Azure
Azure Function, either In-Process or Independent Worker, catches exception but then continues executing code after the throw reaching 200 OK.
Issue Transfer
This issue has been transferred from the Azure SDK for .NET repository, #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
[FunctionName(nameof(ChoiceInPHttpTrigger))]
public static async Task<HttpResponseMessage> RunAsync([HttpTrigger(AuthorizationLevel.Anonymous, "get", "post", Route = null)] HttpRequest req, ILogger log)
{
Task<HttpResponseMessage> tResp = ProcessInP.ProcessChoiceInPHttpTriggerAsync(req, log);
HttpResponseMessage resp = await tResp;
return resp;
}
public static async Task<HttpResponseMessage> 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<Result> 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<IOtherProcessor>() { 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
[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)
[Function(nameof(ChoiceInWHttpTrigger))]
//public HttpResponseData Run([HttpTrigger(AuthorizationLevel.Anonymous, "get", "post", Route = null)] HttpRequestData req, [FromBody] RData representationData, FunctionContext ctx)
public async Task<HttpResponseData> RunAsync(
[HttpTrigger(AuthorizationLevel.Anonymous, "get", "post", Route = null)] HttpRequestData req,
[FromBody] RData representationData,
FunctionContext ctx)
{
try
{
Task<HttpResponseData> 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<HttpResponseData> 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 :
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)
