Azure-functions-core-tools: Disable verbose logging from the runtime when running locally

[jyn514]

What problem would the feature you're requesting solve? Please describe.

I'm running func host start locally. When I get a request, I get verbose logging to the console that looks like this:

[6/21/2019 1:18:58 PM] Executed HTTP request: {
[6/21/2019 1:18:58 PM]   "requestId": "80f6b471-babd-42f7-9cc7-70053a22d6a5",
[6/21/2019 1:18:58 PM]   "method": "GET",
[6/21/2019 1:18:58 PM]   "uri": "/api/authentication/signin",
[6/21/2019 1:18:58 PM]   "identities": [],
[6/21/2019 1:18:58 PM]   "status": 404,
[6/21/2019 1:18:58 PM]   "duration": 318
[6/21/2019 1:18:58 PM] }

This is a lot of output and it drowns out the errors that I'm logging to the console, so I'd like to disable it. I know that I'm not outputting this information, so I think it's coming from the runtime.

Describe the solution you'd like

I would like for the application logging settings in host.json to be considered. My current host.json looks like this:

{
  "version": "2.0",
  "extensions": {
    "http": {
      "routePrefix": ""
    }
  },
  "logging": {
    "logLevel": {
      "default": "Error",
      "Function": "Error"
    }
  }
}

Describe alternatives you've considered

As an alternative, there could be a CLI flag that disables logging from the runtime (maybe func host start --quiet?)

Additional context

Using func host start > nul does not work because all output is to stdout, not stderr, it gets rid of the output I'm interested in as well.

I've looked in the following places, none of them have disabled logging:

• https://stackoverflow.com/questions/53484337/ (doesn't work)
• https://github.com/Azure/azure-functions-host/issues/4474 (I think this was logging from the application, not from the runtime)
• https://docs.microsoft.com/en-us/azure/azure-functions/functions-monitoring#disable-built-in-logging (only applies to deployed apps, not local ones)
• https://stackoverflow.com/questions/46188052/azure-function-verbose-trace-logging-to-application-insights (only applies to version 1)
• https://docs.microsoft.com/en-us/azure/azure-functions/functions-run-local#local-settings-file (doesn't have a setting addressing logging)

[brettsam]

Some of this will be fixed with #4554, where this specific log will be reduced down to Debug level, but at the moment there is no way to reduce the logging at the level that this log is being emitted. I'm going to transfer this into the CLI repo to make sure that I take a look at this specific scenario once the above-mentioned PR is merged.

[ahmedelnably]

@brettsam can this be closed now?

[chesteryang]

Mark it for notifying me when it is resolved. It is indeed an annoying issue.

[Burnett2k]

I'm running into this issue as well. It is really difficult to follow what is happening in the console because there is a huge amount of info being logged. Most of the time, I just want to see my own logging statements and not the debug stuff, so it would be great to add that as some type of configuration.

[francky-powerfactors]

I too got this issue, I get lots of:

End processing HTTP request after xxx - OK
Received HTTP response after xxx - OK
Sending HTTP request "GET"

logged as information even though I got the host.json file setup pretty much like @jyn514.

It should be quit easy to disable those logs.

[JustinGrote]

Even with loglevel none set, I still get a lot of this in the core tools host:

[3/2/2020 10:45:40 PM] System Log: { Log-Level: Trace; Log-Message: Profile invocation completed in 44 ms. }
[3/2/2020 10:45:40 PM] System Log: { Invocation-Id: df122934-95e9-4e06-893e-f8ca0690c708; Log-Level: Trace; Log-Message: Invoking function 'messages' code 183 ms after receiving request. Invocation performance details: DependenciesAvailable: 0 ms; RunspaceAvailable: 48 ms; MetadataAndTraceContextReady: 58 ms; FunctionCodeReady: 181 ms; InputBindingValuesReady: 182 ms; InvokingFunctionCode: 182 ms;  }
[3/2/2020 10:45:40 PM] Executed HTTP request: {
[3/2/2020 10:45:40 PM]   "requestId": "438b2b5e-169a-4171-8208-f2e1655059ea",
[3/2/2020 10:45:40 PM]   "method": "POST",
[3/2/2020 10:45:40 PM]   "uri": "/api/messages",
[3/2/2020 10:45:40 PM]   "identities": [
[3/2/2020 10:45:40 PM]     {
[3/2/2020 10:45:40 PM]       "type": "WebJobsAuthLevel",
[3/2/2020 10:45:40 PM]       "level": "Admin"
[3/2/2020 10:45:40 PM]     }
[3/2/2020 10:45:40 PM]   ],
[3/2/2020 10:45:40 PM]   "status": 202,
[3/2/2020 10:45:40 PM]   "duration": 289
[3/2/2020 10:45:40 PM] }

[Duchynko]

Same issue here. Would be great to get rid of Executed HTTP request logs in some cases. It makes it difficult to trace down errors.

[dzejsien]

It would be great to have possibility to disable it totally. During tracing Colors.Net.ColoredConsoleWriter.Write tooks more than 50% of load.

[phantom2017-Nov]

Yes, please - same here .. it is quite difficult to find our own custom "logs" & differentiate them from what potentially MS developers added for their own debugging ...

[anthonychu]

@brettsam Looking for an update on this. Can you help identify the work that needs to be done (in Core Tools, host, or both) to suppress the logs in @JustinGrote's comment?

Related: https://github.com/Azure/Azure-Functions/issues/1407

[brettsam]

Add this to your Values in local.settings.json -- this should mute that category completely:

"logging:logLevel:Microsoft.Azure.WebJobs.Script.WebHost.Middleware.SystemTraceMiddleware": "None"

[JustinGrote]

@brettsam this helps! There's one more message to suppress and I will have it where I want it, can you identify where this one comes from?

4/29/2020 11:37:51 PM] System Log: { Invocation-Id: 88228d18-6cc5-431b-8dfd-7bbc1bd28d9a; Log-Level: Trace; Log-Message: Invoking function 'HttpTrigger1' code 3 ms after receiving request. Invocation performance details: DependenciesAvailable: 0 ms; RunspaceAvailable: 0 ms; MetadataAndTraceContextReady: 2 ms; FunctionCodeReady: 2 ms; InputBindingValuesReady: 2 ms; InvokingFunctionCode: 2 ms; }

EDIT: Nevermind this comes from the powershell worker
https://github.com/Azure/azure-functions-powershell-worker/blob/339025c2a19fae4c8a96eb4094f0e2ae53b684b5/src/resources/PowerShellWorkerStrings.resx#L299

Should I close the issue with the workaround or is a "nicer" interface via host.json logging or something planned?

[JustinGrote]

@brettsam After investigation I found that the powershell worker emits these messages to stdout
https://github.com/Azure/azure-functions-powershell-worker/issues/461

And that the core tools will pick up stdout from the worker. Is there any way to suppress the received stdout messages at the core tools/host level?

[JustinGrote]

I found where it arrives on the host side, but all the inversion of control makes it really difficult to find out what category the messages are being logged that I could possible suppress with the environment variable.

https://github.com/Azure/azure-functions-host/blob/aead204f7a7ace3c9bede9f7928249933d18d777/src/WebJobs.Script/Workers/ProcessManagement/WorkerProcess.cs#L103-L111

Also, is there a reason the host.json logging doesn't work to suppress these and environment variables have to be used? I thought it all was merged via Microsoft.Extensions.Configuration.

[brettsam]

It's all .NET but Functions uses nested hosts to run. The parent host is an ASP.NET host that runs all the admin queries, watches for file changes, etc, and it runs an inner child host that actually loads and runs your functions. The host.json only applies to the inner child host but these logs are all coming from the outer host. In production these aren't typically visible as they're wired up to our backend logs only -- but they show up here when running locally.

I don't have a repro set up but can you try:
"logging:logLevel:Worker.rpcWorkerProcess": "None"

[JustinGrote]

@brettsam that worked! I found the category in the rpcWorkerProcess section shortly after you mentioned that. Adding these lines to my local.settings.json achieved the desired result. Thanks for your quick response.

    "logging:logLevel:Microsoft.Azure.WebJobs.Script.WebHost.Middleware.SystemTraceMiddleware": "Warning",
    "logging:logLevel:Worker.rpcWorkerProcess": "Warning"

[brettsam]

Great! So I think with this technique you can selectively turn off whatever lines you want that aren't controlled by host.json.

I know that can be tricky to figure out though. I'm going to close this issue, but if you come across it and need guidance, please let me know and I can help you find the right category to use in your setting to turn off a particular line.

[JustinGrote]

@brettsam sounds good, I'll also file a documentation note into the docs.

[jleck]

Hi,

I've just put these couple of lines in, and it's helped. However, I still get:

Executing 'Functions.graphql' (Reason='This function was programmatically called via the host APIs.', Id=ed009943-057b-4953-8a68-95362bd8feb7)

The API is being called continously, so I'm getting a lot of them! Is there anyway to disable that?

[JustinGrote]

@jleck you have to find what "category" the log is coming from in order to suppress it. If it shows up in Application Insights that's easy to find, otherwise you have to trace the code.

There's a lot of examples that @anthonychu put together here:
https://github.com/anthonychu/functions-log-suppression

[jleck]

Hmm, will have a hunt. I've looked for the string in the azure-functions-core-tools and azure-functions-nodejs-worker to no avail!

[anthonychu]

This should be the category Function.<function_name> (or just Function to do this to all functions). However, the main issue with this is it affects user generated logs too. You need to set the log level for Function.<function_name>.User for every function to see logs you create from inside the function.

[jleck]

thanks @anthonychu, managed to disable it with:

"AzureFunctionsJobHost:logging:logLevel:Function.graphql": "Warning",

Also put:

"logging:logLevel:Microsoft": "Warning",
"logging:logLevel:Worker": "Warning"

Nice and clean now! Thanks both :)