Log entries from function code is not appearing in console when running locally

[kshyju]

Function App name:

N/A. Local testing.

Tools used:

VS 2022 Preview 6.0

New V4 app or existing V3 app migrated to V4:

New V4 In-proc app.

Runtime info:

Azure Functions Core Tools Core Tools Version: 4.0.3893 Commit hash: ef87e297a75893d676c3dea0eb01fbd1a3db5446 (64-bit) Function Runtime Version: 4.0.0.16714

Issue:

The console logging provider does not appear to work. Logs emitted from my function app code is not shown on the console window, impacting local development flow.

Repro steps:

Create a V3 in-proc app and V4 in-proc app with an Http trigger function. Execute the http trigger function and compare logs emitted in the console.

V3 LOGS from console

Functions:

        Function1: [GET,POST] http://localhost:7071/api/Function1

For detailed output, run func with --verbose flag.
[2021-10-21T18:37:25.900Z] Host lock lease acquired by instance ID '0000000000000000000000006DBDAA09'.
[2021-10-21T18:37:35.380Z] Executing 'Function1' (Reason='This function was programmatically called via the host APIs.', Id=ea3e074c-1ed2-4e15-9291-71b45197e02f)
[2021-10-21T18:37:35.402Z] C# HTTP trigger function processed a request.
[2021-10-21T18:37:35.468Z] Executed 'Function1' (Succeeded, Id=ea3e074c-1ed2-4e15-9291-71b45197e02f, Duration=112ms)

V4 LOGS from console

Functions:

        Function1: [GET,POST] http://localhost:7071/api/Function1

For detailed output, run func with --verbose flag.
[2021-10-21T18:38:32.467Z] Executing 'Function1' (Reason='This function was programmatically called via the host APIs.', Id=2767e974-f68b-43fc-888d-9ae105ba8fb8)
[2021-10-21T18:38:32.580Z] Executed 'Function1' (Succeeded, Id=2767e974-f68b-43fc-888d-9ae105ba8fb8, Duration=138ms)
[2021-10-21T18:38:34.786Z] Host lock lease acquired by instance ID '0000000000000000000000006DBDAA09'.

Both functions are using the LogInformation extension method.

If I update the V4 function code to inject ILogger as a parameter (similar to what the V3 template produces) and use that instance, logging to console works fine.

[FunctionName("Function1")]
public async Task<IActionResult> Run(
    [HttpTrigger(AuthorizationLevel.Anonymous, "get", "post", Route = null)] HttpRequest req, ILogger _logger)

[anthonychu]

@fabiocav @brettsam What's the fix here? Is it an expected breaking change? Do we need to update templates and docs?

[anirudhgarg]

We are going to fix the template and revert the move.

[liliankasem]

Might be worth mentioning that this new pattern works in the isolated dotnet v4 app

    public class HttpTrigger1
    {
        private readonly ILogger _logger;

        public HttpTrigger1(ILoggerFactory loggerFactory)
        {
            _logger = loggerFactory.CreateLogger<HttpTrigger1>();
        }

        [Function("HttpTrigger1")]
        public HttpResponseData Run([HttpTrigger(AuthorizationLevel.Anonymous, "get", "post")] HttpRequestData req)
        {
            _logger.LogInformation("C# HTTP trigger function processed a request.");

            var response = req.CreateResponse(HttpStatusCode.OK);
            response.Headers.Add("Content-Type", "text/plain; charset=utf-8");

            response.WriteString("Welcome to Azure Functions!");

            return response;
        }
    }

[2021-10-22T22:41:33.859Z] Worker process started and initialized.
[2021-10-22T22:41:36.428Z] Executing 'Functions.HttpTrigger1' (Reason='This function was programmatically called via the host APIs.', Id=de7724b4-af23-4e49-9d22-6af4eb821db7)
[2021-10-22T22:41:36.542Z] C# HTTP trigger function processed a request.
[2021-10-22T22:41:36.639Z] Executed 'Functions.HttpTrigger1' (Succeeded, Id=de7724b4-af23-4e49-9d22-6af4eb821db7, Duration=240ms)
[2021-10-22T22:41:38.247Z] Host lock lease acquired by instance ID '000000000000000000000000CD51D200'.

[fabiocav]

We should change the templates back at this point.

This is not a breaking change if using the same pattern, but there is indeed a change in behavior with the template changes (same would happen in 3.0)

[KholofeloMoyaba]

I struggled with this a bit too. As it turns out if you are going for the ILogger<T> approach you need to add log level entries in host.json

e.g.

{
    "version": "2.0",
    "logging": {
        "applicationInsights": {
            "samplingSettings": {
                "isEnabled": true,
                "excludedTypes": "Request"
            }
        },
        "logLevel": {
            "MyNamespace.HttpTrigger": "Information"
        }
    }
}

Where MyNamespace.HttpTrigger is the location of your function (or any other class for that matter)

More details: https://docs.microsoft.com/en-us/azure/azure-functions/functions-dotnet-dependency-injection

[liliankasem]

That's right, we do cover this new pattern in the docs:

"The host injects ILogger<T> and ILoggerFactory services into constructors. However, by default these new logging filters are filtered out of the function logs. You need to modify the host.json file to opt-in to additional filters and categories."

So for the templates, we either need to revert back to injecting ILogger as a parameter or we just need to update the host.json file so that it works as it currently is