Azure
Console.WriteLine output before Functions App shuts down is silently discarded (with func.exe tool)
Hello, this is in reference to the closed issue Azure/azure-functions-dotnet-worker#1450. The code snippet shown there to run custom code at shutdown does not work for me when used with the func tool at least.
I tried to use the snippet with func (azure functions core tools) version 4.0.4483 and 4.0.5198 (the newest release at the time of this writing) and also extended the code snippet to use a finally block. Full code below:
using System;
using System.Threading.Tasks;
using Microsoft.Extensions.Hosting;
namespace Examples.AzureFunctionWorkerApp
{
public class Program
{
public static async Task Main()
{
try
{
var host = new HostBuilder()
.ConfigureFunctionsWorkerDefaults()
.Build();
Console.WriteLine("Before host.Run()");
await host.RunAsync();
}
finally
{
Console.WriteLine("Finally after host.Run()");
}
}
}
}
These are the dependency versions (I just used func new to create a dotnet-isolated C# project and did not change anything):
<PropertyGroup>
<TargetFramework>net6.0</TargetFramework>
<AzureFunctionsVersion>v4</AzureFunctionsVersion>
</PropertyGroup>
<ItemGroup>
<PackageReference Include="Microsoft.Azure.Functions.Worker" Version="1.8.0" />
<PackageReference Include="Microsoft.Azure.Functions.Worker.Extensions.Http" Version="3.0.13" />
<PackageReference Include="Microsoft.Azure.Functions.Worker.Sdk" Version="1.7.0" />
</ItemGroup>
Running this with func --verbose --debug the relevant parts of the output (till the end) is this:
Azure Functions Core Tools
Core Tools Version: 4.0.5198 Commit hash: N/A (64-bit)
Function Runtime Version: 4.21.1.20667
...
[2023-07-17T13:14:38.340Z] Before host.Run()
[2023-07-17T13:14:38.523Z] {
[2023-07-17T13:14:38.526Z] "ProcessId": 25028,
[2023-07-17T13:14:38.527Z] "RuntimeIdentifier": "win10-x64",
[2023-07-17T13:14:38.528Z] "WorkerVersion": "1.6.0.0",
[2023-07-17T13:14:38.530Z] "ProductVersion": "1.6.0-local202207141250\u002Bbb7aae9c07baca52004877db452762344f0db895",
[2023-07-17T13:14:38.531Z] "FrameworkDescription": ".NET 6.0.20",
[2023-07-17T13:14:38.532Z] "OSDescription": "Microsoft Windows 10.0.22621",
[2023-07-17T13:14:38.533Z] "OSArchitecture": "X64",
[2023-07-17T13:14:38.535Z] "CommandLine": "C:\\workspaces\\func-bug-repro\\bin\\output\\func-bug-repro.dll --host 127.0.0.1 --port 60297 --workerId 637efb9b-59ae-4795-b3c0-488691c82fb9 --requestId 3fcebeab-d776-4b9f-b671-a9c561878b19 --grpcMaxMessageLength 2147483647"
[2023-07-17T13:14:38.537Z] }
[2023-07-17T13:14:38.585Z] Worker process started and initialized.
[2023-07-17T13:14:43.136Z] Host lock lease acquired by instance ID '000000000000000000000000EC47B666'.
[2023-07-17T13:14:47.322Z] Stopping host...
[2023-07-17T13:14:47.334Z] Stopping JobHost
[2023-07-17T13:14:47.340Z] Job host stopped
[2023-07-17T13:14:47.386Z] Host shutdown completed.
As you can see, the expected Console.WriteLine output BeforeStart is visible, but the Finally after host.Run() line is not there.
Full output here: output.log
Of course, I dont' know if this bug actually needs to be fixed here or in https://github.com/Azure/azure-functions-core-tools or maybe https://github.com/Azure/azure-functions-host/, nor do I know how to find out, so I'm starting here. Please transfer the issue or request more information from me if you think it belongs somewhere else.
Stdout for the worker is redirected to the host process. This may be not that the Console.WriteLine did not execute, but that the host process closed before flushing that message to stdout. I am not certain how host buffer flushing works, so would need to dig into that.
With that said - what work are you exactly wanting to do on shutdown? This is not always the best idea, as the host process managers the worker lifetime and has no insight into your shutdown work. It will force terminate a worker taking too long to shutdown. If you plan on doing a lot of work at shutdown, keep that in mind.
With that said - what work are you exactly wanting to do on shutdown?
In the real use case, we want to shut down OpenTelemetry (not actually via code in Main but just automatically by using https://github.com/open-telemetry/opentelemetry-dotnet/tree/main/src/OpenTelemetry.Extensions.Hosting) to ensure that our Activities are flushed. We have an integration test using func.exe and we currently send SIGTERM to the worker process before the host to avoid the problem where the host seems to somehow cause the shutdown to be skipped. (The problem with our integration test is reproducible both on Linux and Windows)
Based on your hint, I now tried using using var output = new StreamWriter("out.txt"); instead of Console, and indeed I see the finally line then. I will update the issue title to refer to the Console buffering issue, because IMHO that's still worth fixing as it totally led me on the wrong track here. I'll need to debug the original problem further then
@Oberon00 are you seeing issues today with OpenTelemetry not being shutdown properly? By default, I believe host shutdown will send a SIGTERM to the worker. So regular host shutdown will occur. But this does have a time limit and doesn't protect against app crashes.
I tested myself by adding an IHostedService and debugging. The StopAsync is called when I send Ctrl+C to the terminal VS opens. Stop debugging won't trigger this flow as it is not a graceful process termination.
@jviau Hi, sorry for not replying, I missed this. Your question is answered by https://github.com/Azure/azure-functions-host/issues/9866: The stop callback is indeed called, but the console output is not visible.
The root issue is that https://github.com/Azure/azure-functions-host/blob/dev/src/WebJobs.Script/Workers/WorkerConsoleLogService.cs does not flush pending logs on host shutdown.