Azure / Azure/Azure-Functions

Is debug level logging meant to be like this or have I missed something?

Open
#2,388 14 comments 5 reactions 1 assignee Claimed by @bhagyshricompany View on GitHub
bug Needs: Attention :wave:
Dominant language
PowerShell
Stars
1.1k
Forks
215
Avg merge
4h 2m
Merged PRs (30d)
1

Description

This is a plea to whoever is responsible for the mess that is logging in Azure Functions applications.
I am at my wits end just trying to get simple things to behave in a simple consistent manner with Azure functions and my last ditch attempt was to rely on debug level logging calls which led to this fiasco.

Expecting nothing less than the obvious question "what's my MVP here to reproduce the issue",
here we go ...

1. Create a new console app
2. modify the project file to this ...
```


net7.0
v4
Exe
enable




```
3. Modify the Progam.cs to this ...
```
var host = new HostBuilder()
.ConfigureServices((builder, services) =>
{
services.AddLogging(loggingBuilder => {
loggingBuilder.AddSimpleConsole(options =>
{
options.SingleLine = true;
options.TimestampFormat = "hh:mm:ss ";
});
});

}).Build();

ILogger log = host.Services.GetService>();

log.LogInformation("Hello World!");
log.LogDebug("This is a debug message");

host.Run();
```
4. Run and note the debug message does not appear
5. Modify to this ...

```
var host = new HostBuilder()
.ConfigureServices((builder, services) =>
{
services.AddLogging(loggingBuilder => {
loggingBuilder.AddSimpleConsole(options =>
{
options.SingleLine = true;
options.TimestampFormat = "hh:mm:ss ";
});

loggingBuilder.AddFilter(level => level >= LogLevel.Debug);
});

}).Build();

ILogger log = host.Services.GetService>();

log.LogInformation("Hello World!");
log.LogDebug("This is a debug message");

host.Run();
```
6. marvel at the wonder of simple logging in dotnet.

...
Now lets repeat this process but with azure functions ...
1. Create a new functions app with a timer run function
- I don't think the timer isn't specifically required it's just how I came across this
2. Modify the function Run method code to this ...

```
[Function("Function1")]
public void Run([TimerTrigger("0 */1 * * * *")] MyInfo myTimer)
{
log.LogInformation("Hello World!");
log.LogDebug("This is a debug message");
}
```
You'll also need to inject a logger in to the constructor like this ...
```
public Function1(ILoggerFactory loggerFactory) =>
log = loggerFactory.CreateLogger();
```

or like this ...
```
public Function1(ILogger log) =>
this.log = log;
```

but definitely not like this ...
```
[Function("Function1")]
public void Run([TimerTrigger("0 */1 * * * *")] MyInfo myTimer, ILogger log)
{
log.LogInformation("Hello World!");
log.LogDebug("This is a debug message");
}
```
... because apparently there's documentation out there that even confuses ChatGPT suggesting this works.
From whati've seen at the very least you'd need to some additional DI setup, but I have no idea what it is.

3. Run the app, note the lack of any debug output when the function is called
4. Modify the host builder in the program.cs file to this ...

```
var host = new HostBuilder()
.ConfigureFunctionsWorkerDefaults()
.ConfigureServices((builder, services) =>
{
services.AddLogging(loggingBuilder => {
loggingBuilder.AddSimpleConsole(options =>
{
options.SingleLine = true;
options.TimestampFormat = "hh:mm:ss ";
});

loggingBuilder.AddFilter(level => level >= LogLevel.Debug);
});

})
.Build();
```
5. Note that the console app and the function app are now the same
6. Run the function app

When the function is called we can see a few weird things ...
- Double timestamps (only the second is formatted)
- Double logging calls (formatted differently too)

This is where it gets particularly annoying ...
As documented the way we are supposed to handle our logging in functions apps is by configuring this in the host.json file.
So as our logging is going to hit the console anyway out the box for functions apps we can strip the above code back to ...
```
var host = new HostBuilder()
.ConfigureFunctionsWorkerDefaults()
.Build();
```
... then according to the documentation here ...
https://learn.microsoft.com/en-us/azure/azure-functions/configure-monitoring?tabs=v2
... we should just be able to add this to our host.json "logging" element ...
```
"fileLoggingMode": "always",
"logLevel": {
"default": "Debug",
"Host": "Error",
"Function": "Error",
"Host.Aggregator": "Information"
}
```
... and achieve the same result ... right?
Apparently not.
From what I can tell, no amount of messing about with this section fo the configuration makes any kind of difference to the log output.

It gets even more confusing ...
After explaining that you can do the above, the same documentation goes on to say:
```
Azure Functions integrates with Application Insights by storing telemetry events in Application Insights tables. Setting a category log level to any value different from Information will prevent the telemetry to flow to those tables. As outcome, you won't be able to see the related data in Application Insights or Function Monitor tab.
```
So I can configure logging, but if I do, it won't work on the cloud inside a framework that is designed to work in a serverless "cloud environment".

It gets even more crazy when we take the "full example" shown here ...
https://learn.microsoft.com/en-us/azure/azure-functions/functions-host-json#sample-hostjson-file

Which is pre-fixed with this ...
```
Other function app configuration options are managed depending on where the function app runs:

Deployed to Azure: in your [application settings](https://learn.microsoft.com/en-us/azure/azure-functions/functions-app-settings)
On your local computer: in the [local.settings.json](https://learn.microsoft.com/en-us/azure/azure-functions/functions-develop-local#local-settings-file) file.
Configurations in host.json related to bindings are applied equally to each function in the function app.

You can also [override or apply settings per environment](https://learn.microsoft.com/en-us/azure/azure-functions/functions-host-json#override-hostjson-values) using application settings.
```
... A vague statement that says "oh you can / might want to put all of this one of 3 files", but given that the above behaves the way it does I'm confused ...
Why configure logging at all if you're forced to then put it in code anyway?

Generally speaking I'd argue that from logging most of us want the same thing which boils down to ...
- formatting so we can output key information like ...
- timestamp (formatted)
- logging level used
- The source type in the code
- some message
- The ability to configure / specify logging levels we want to see in the logs
- Optionally with an ability to configure for different "scopes" different levels of logging
- Consistency from it
- If grpc logging calls ignore our config entirely both config or coded that's not helpful
- If my business logic and the functions framework log in different formats, that's not helpful
- If I make calls using 2 different logging levels and they behave differently that's not helpful

Am I missing something about how to correctly configure logging in functions apps or am I just seeing bugs that no one else seems to think are an issue?

I find with logging that it usually doesn't matter until you have a problem, then they are crucial to the entire process of solving a problem, particularly in complex production environments.

And Finally ...
I'm in the wild, working on this stuff and I hit some issue in my functions app,
I think the platform isn't playing ball ...
what does Azure Functions Support staff do, they look at the App Insights stuff in the cloud and are inundated with basically a swamp of garbage that I can't control or filter, it's injected by the framework and adds no value to me but the support staff ultimately are seeing whats on the end of the logging that ultimately doesn't give them consistent results.

So to summarize ...
- Logging either logs nothing at all or double logs "out of the box"
- It behaves differently depending on the logging level used
- Formatting seems to be a general issue / not configurable at all
- Configuration of logging as documented is confusing and simply doesn't appear to work
- The base logging behavior of a console app and a functions app should be consistent it's all dotnet
- App Insights seems to be this magic that's forced on us as developers, it's huge and doesn't solve any day to day problem I have
- Support staff at Azure Functions support are lost and make generic statements like "oh that's an sdk issue all we can do is escalate"

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.