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

[jsquire]

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)