Less verbose logs on func start #2139

pragnagopa · 2020-08-05T22:59:32Z

This PR:

Added --verbose flag. Running with --verbose flag will give users existing logging behavior
If running in CI environment - https://github.com/watson/ci-info/blob/master/index.js#L52-L59, --verbose flag is set.
Displays all the functions (incorporated code from @anthonychu)
Strips out date from log messages.
By default func host start will have less verbose system logs:
- Default log level for system logs is Warning
- Deafult log level for user logs is Information
If Default log level is specified in host.json - both user logs and system logs level is set to the value specified in host.json
If host.json has default loglevel set to None - Only whitelisted logs that VS Code uses will be logged
If host.json lists any category then defaults do not apply

Sample output on func host start with default host.json

func.exe host start
Azure Functions Core Tools (3.0.1 Commit hash: N/A)
Function Runtime Version: 3.0.1.0
Hosting environment: Production
Content root path: C:\pgopa\vsCode\jsDebug
Now listening on: http://0.0.0.0:7071
Application started. Press Ctrl+C to shut down.

Functions:

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

For detailed output, run func with --verbose flag.
Worker process started and initialized.
Host lock lease acquired by instance ID '00000000000000000000000022DF9FE8'.
JavaScript HTTP trigger function processed a request.

Sample output on func host start with following host.json

{
	"version": "2.0",
	"logging": {
		"LogLevel": {
			"Function.HttpTrigger": "Trace",
			"Microsoft.Azure.WebJobs.Script.Description.WorkerFunctionInvoker": "Trace",
			"Microsoft.Azure.WebJobs.Script.WebHost.Middleware.SystemTraceMiddleware": "Information"
		}
	}
}

NOTE: To see middleware tracing user explicitly needs to add that category in host.json
Output :

Azure Functions Core Tools (3.0.1 Commit hash: N/A)
Function Runtime Version: 3.0.1.0
Hosting environment: Production
Content root path: C:\pgopa\vsCode\jsDebug
Now listening on: http://0.0.0.0:7071
Application started. Press Ctrl+C to shut down.

Functions:

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

For detailed output, run func with --verbose flag.
Worker process started and initialized.
Host lock lease acquired by instance ID '00000000000000000000000022DF9FE8'.
Executing HTTP request: {
  requestId: "0b7d77b8-df93-4bb7-be6b-34e3ab2cb0f8",
  method: "GET",
  userAgent: "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/84.0.4147.105 Safari/537.36",
  uri: "/api/HttpTrigger"
}
Executing 'Functions.HttpTrigger' (Reason='This function was programmatically called via the host APIs.', Id=8c804b69-e49c-4577-8ffb-0210875b4073)
Sending invocation id:8c804b69-e49c-4577-8ffb-0210875b4073
JavaScript HTTP trigger function processed a request.
Executed 'Functions.HttpTrigger' (Succeeded, Id=8c804b69-e49c-4577-8ffb-0210875b4073, Duration=258ms)
Executed HTTP request: {
  requestId: "0b7d77b8-df93-4bb7-be6b-34e3ab2cb0f8",
  identities: "(WebJobsAuthLevel:Admin)",
  status: "200",
  duration: "454"
}

pragnagopa · 2020-08-05T23:01:58Z

This PR builds on previous PR: #2135 that forces whitelisted logs if LogLevel is set to None

Building on the same approach, running func start --quite will set Default LogLevel to None.

anthonychu · 2020-08-05T23:01:59Z

Is this related to #1131?

src/Azure.Functions.Cli/Actions/HostActions/StartHostAction.cs

pragnagopa · 2020-08-05T23:05:25Z

Is this related to #1131?

Yes, I just linked the issue to the PR!

pragnagopa · 2020-08-05T23:06:21Z

@anthonychu - Please note that sample output has following log:

[8/5/2020 10:57:06 PM] Host lock lease acquired by instance ID '00000000000000000000000022DF9FE8'. - this is a forced log that VS code debugger relies on.

src/Azure.Functions.Cli/Actions/HostActions/StartHostAction.cs

anthonychu · 2020-08-06T00:45:23Z

This is different that what we discussed in #1131 though. I think we need to discuss.

pragnagopa · 2020-08-06T03:01:41Z

Updated the PR, to turn off logs by default.

@anthonychu - what is the experience we are aiming for function invocation logs?

pragnagopa · 2020-08-06T03:41:20Z

Just looked through the details: #1131 (comment)

This PR is scoped to changing output on func start . I will open separate issues for func azure functionapp publish
Will update the PR incorporating changes mentioned: 7dd097e...anthonychu:less-verbose

anthonychu · 2020-08-06T03:51:14Z

@pragnagopa Sorry we didn't get a chance to sync up first before you started on this. @ankitkumarr and @fabiocav have more context, I can help catch you up.

It's more than just setting logs to None. Logs coming from the host and Core Tools should be at Warning, and logs from customer code should remain at Information.

I have updated this comment #1131 (comment) with the latest on what we landed on from the discussions over the past couple of months. While this covers multiple commands, let's scope this work to func start.

I have a proof of concept to demonstrate what we're looking for. This diff might be useful to explain some of the changes: 7dd097e...anthonychu:less-verbose

Sample of what we're looking for is here:

anthonychu · 2020-08-06T03:55:53Z

@pragnagopa Looks like you commented while I was typing up my reply. I think we're on the same page. 😄

src/Azure.Functions.Cli/Actions/HostActions/StartHostAction.cs

pragnagopa · 2020-08-10T15:53:18Z

Updated PR description, added unit tests. Please review.

pragnagopa · 2020-08-11T20:56:47Z

ping for reviews!

anthonychu · 2020-08-11T21:07:21Z

@pragnagopa One thing discussed in #1131 that got lost in the noise is defaulting to existing logging behavior in CI environments. Can check for this using something similar to this: https://github.com/watson/ci-info/blob/master/index.js#L52-L59

Other than that, it looks great based on the description. Thanks!

pragnagopa · 2020-08-11T22:41:15Z

@anthonychu - not sure if there is a standard way to figure out CI environment. Added check for variables you pointed out: https://github.com/watson/ci-info/blob/master/index.js#L52-L59

We can expand the list in future if needed.

anthonychu · 2020-08-12T03:12:07Z

@pragnagopa Thanks! We don’t need to catch them all, those variables should detect most of them.

src/Azure.Functions.Cli/Actions/HostActions/StartHostAction.cs

src/Azure.Functions.Cli/Common/Utilities.cs

src/Azure.Functions.Cli/Diagnostics/LoggingFilterOptions.cs

src/Azure.Functions.Cli/Diagnostics/ColoredConsoleLogger.cs

src/Azure.Functions.Cli/Diagnostics/LoggingFilterOptions.cs

src/Azure.Functions.Cli/Common/Utilities.cs

src/Azure.Functions.Cli/Diagnostics/ColoredConsoleLogger.cs

src/Azure.Functions.Cli/Diagnostics/LoggingFilterHelper.cs

src/Azure.Functions.Cli/Actions/HostActions/StartHostAction.cs

src/Azure.Functions.Cli/Diagnostics/LoggingFilterHelper.cs

pragnagopa · 2020-08-24T22:11:05Z

src/Azure.Functions.Cli/Secrets/UserSecretsConfigurationBuilder.cs


-        public UserSecretsConfigurationBuilder(string scriptPath)
+        public UserSecretsConfigurationBuilder(string scriptPath, LoggingFilterHelper loggingFilterHelper)


@gzuber - can you please ACK these changes? Had to re-base and update this code so that all the logs go through default logging filters

pragnagopa · 2020-08-25T18:44:55Z

@brettsam / @ankitkumarr - Green build! Can you please take final pass?

ankitkumarr · 2020-08-25T21:04:16Z

src/Azure.Functions.Cli/Actions/HostActions/StartHostAction.cs

+                .Callback(v => VerboseLogging = v);
+
+            var parserResult = base.ParseArgs(args);
+            bool verboseLoggingArgExists = parserResult.UnMatchedOptions.Where(o => o.LongName.Equals("verbose", StringComparison.OrdinalIgnoreCase)).Any();


We can probably just do parserResult.UnMatchedOptions.Any(o => o.LongName.Equals("verbose", StringComparison.OrdinalIgnoreCase)) I think.

ankitkumarr · 2020-08-25T21:06:24Z

src/Azure.Functions.Cli/Actions/HostActions/StartHostAction.cs

+            Parser
+                .Setup<bool>("verbose")
+                .WithDescription("When false, hides system logs other than warnings and errors.")
+                .SetDefault(false)


If we remove the default value here, would we still need verboseLoggingArgExists? We can probably just check if VerboseLogging is null or not.

Parser is not binding properly to type bool? . I tried updating the nuget package same behavior.

pragnagopa · 2020-08-25T22:07:51Z

@anthonychu fyi - merging this PR. Will update the release notes to include this change.

pragnagopa requested review from anthonychu, brettsam and fabiocav August 5, 2020 22:59

pragnagopa commented Aug 5, 2020

View reviewed changes

src/Azure.Functions.Cli/Actions/HostActions/StartHostAction.cs Outdated Show resolved Hide resolved

ahmelsayed reviewed Aug 6, 2020

View reviewed changes

src/Azure.Functions.Cli/Actions/HostActions/StartHostAction.cs Show resolved Hide resolved

pragnagopa changed the title ~~Add option for quite~~ Set Default LogLevel to None Aug 6, 2020

Base automatically changed from pgopa/whiteListLogs to v3.x August 6, 2020 19:21

pragnagopa changed the base branch from v3.x to pgopa/fixForceLogs August 7, 2020 00:02

pragnagopa force-pushed the pgopa/addSilentOption branch from 7f85980 to 44886ab Compare August 7, 2020 00:32

pragnagopa changed the title ~~Set Default LogLevel to None~~ [WIP]Set Default LogLevel for user logs to Info, default log level for system logs to Warning Aug 7, 2020

pragnagopa force-pushed the pgopa/addSilentOption branch from c0a8b04 to 8146516 Compare August 10, 2020 15:30

pragnagopa mentioned this pull request Aug 10, 2020

Force logs only when Default LogLevel is None #2145

Closed

pragnagopa requested a review from ankitkumarr August 10, 2020 15:37

pragnagopa commented Aug 10, 2020

View reviewed changes

src/Azure.Functions.Cli/Actions/HostActions/StartHostAction.cs Show resolved Hide resolved

pragnagopa commented Aug 10, 2020

View reviewed changes

src/Azure.Functions.Cli/Actions/HostActions/StartHostAction.cs Show resolved Hide resolved

pragnagopa changed the title ~~[WIP]Set Default LogLevel for user logs to Info, default log level for system logs to Warning~~ Less verbose logs on func start Aug 10, 2020

pragnagopa changed the base branch from pgopa/fixForceLogs to v3.x August 10, 2020 15:52

pragnagopa requested a review from mhoeger August 10, 2020 15:55

pragnagopa force-pushed the pgopa/addSilentOption branch from f903a34 to 5ee3738 Compare August 11, 2020 22:38

pragnagopa mentioned this pull request Aug 12, 2020

Add Host.Always log category Azure/azure-functions-host#6299

Closed

brettsam reviewed Aug 13, 2020

View reviewed changes

brettsam reviewed Aug 24, 2020

View reviewed changes

pragnagopa force-pushed the pgopa/addSilentOption branch from 8fb72a4 to 1330607 Compare August 24, 2020 21:45

pragnagopa commented Aug 24, 2020

View reviewed changes

Less verbose system logging on func start

46ecbd1

pragnagopa force-pushed the pgopa/addSilentOption branch from 4a80c5a to 46ecbd1 Compare August 25, 2020 00:18

Fix E2E tests

6bcc1cd

brettsam approved these changes Aug 25, 2020

View reviewed changes

ankitkumarr approved these changes Aug 25, 2020

View reviewed changes

Addressing Ankit's CR

3beffeb

pragnagopa merged commit 1050abb into v3.x Aug 25, 2020

pragnagopa deleted the pgopa/addSilentOption branch August 25, 2020 22:08

This was referenced Aug 25, 2020

Less verbose logs on func start #2141

Closed

Less verbose logs on function invocation #2143

Closed

Force Log when host/worker is ready for VS Code debugger to attach when loglevel is set to None #2110

Closed

pragnagopa added a commit that referenced this pull request Aug 26, 2020

Less verbose logs on func start (#2139)

260e514

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Less verbose logs on func start #2139

Less verbose logs on func start #2139

pragnagopa commented Aug 5, 2020 •

edited

pragnagopa commented Aug 5, 2020

anthonychu commented Aug 5, 2020

pragnagopa commented Aug 5, 2020

pragnagopa commented Aug 5, 2020

anthonychu commented Aug 6, 2020

pragnagopa commented Aug 6, 2020

pragnagopa commented Aug 6, 2020

anthonychu commented Aug 6, 2020

anthonychu commented Aug 6, 2020

pragnagopa commented Aug 10, 2020

pragnagopa commented Aug 11, 2020

anthonychu commented Aug 11, 2020

pragnagopa commented Aug 11, 2020

anthonychu commented Aug 12, 2020

pragnagopa Aug 24, 2020

pragnagopa commented Aug 25, 2020 •

edited

ankitkumarr Aug 25, 2020

pragnagopa Aug 25, 2020

ankitkumarr Aug 25, 2020

pragnagopa Aug 25, 2020

pragnagopa commented Aug 25, 2020


		public UserSecretsConfigurationBuilder(string scriptPath)
		public UserSecretsConfigurationBuilder(string scriptPath, LoggingFilterHelper loggingFilterHelper)

Less verbose logs on func start #2139

Less verbose logs on func start #2139

Conversation

pragnagopa commented Aug 5, 2020 • edited

pragnagopa commented Aug 5, 2020

anthonychu commented Aug 5, 2020

pragnagopa commented Aug 5, 2020

pragnagopa commented Aug 5, 2020

anthonychu commented Aug 6, 2020

pragnagopa commented Aug 6, 2020

pragnagopa commented Aug 6, 2020

anthonychu commented Aug 6, 2020

anthonychu commented Aug 6, 2020

pragnagopa commented Aug 10, 2020

pragnagopa commented Aug 11, 2020

anthonychu commented Aug 11, 2020

pragnagopa commented Aug 11, 2020

anthonychu commented Aug 12, 2020

pragnagopa Aug 24, 2020

Choose a reason for hiding this comment

pragnagopa commented Aug 25, 2020 • edited

ankitkumarr Aug 25, 2020

Choose a reason for hiding this comment

pragnagopa Aug 25, 2020

Choose a reason for hiding this comment

ankitkumarr Aug 25, 2020

Choose a reason for hiding this comment

pragnagopa Aug 25, 2020

Choose a reason for hiding this comment

pragnagopa commented Aug 25, 2020

pragnagopa commented Aug 5, 2020 •

edited

pragnagopa commented Aug 25, 2020 •

edited