search

Azure / azure-functions-core-tools

Command line tools for Azure Functions
MIT License
1.31k stars 433 forks source link

Less verbose logging option (ex: func start --silent) #1131

Closed mhoeger closed 6 months ago

mhoeger commented 5 years ago

On func start, the output logs are very verbose. It would be nice if we could have a version of func start that only shows warnings and errors.

For example:

mariehoeger$func start --silent

                  %%%%%%
                 %%%%%%
            @   %%%%%%    @
          @@   %%%%%%      @@
       @@@    %%%%%%%%%%%    @@@
     @@      %%%%%%%%%%        @@
       @@         %%%%       @@
         @@      %%%       @@
           @@    %%      @@
                %%
                %

Azure Functions Core Tools (2.4.419 Commit hash: c9c1724d002bd90b2e6b41393915ea3a26bcf0ce)
Function Runtime Version: 2.0.12332.0
Hosting environment: Production
Content root path: /Users/mariehoeger/Documents/Demos/azure-functions-typescript
Now listening on: http://0.0.0.0:7071
Application started. Press Ctrl+C to shut down.
Container is disposed and should not be used: Container is disposed.
You may include Dispose stack-trace into the message via:
container.With(rules => rules.WithCaptureContainerDisposeStackTrace())
Application is shutting down...

Instead of:

                  %%%%%%
                 %%%%%%
            @   %%%%%%    @
          @@   %%%%%%      @@
       @@@    %%%%%%%%%%%    @@@
     @@      %%%%%%%%%%        @@
       @@         %%%%       @@
         @@      %%%       @@
           @@    %%      @@
                %%
                %

Azure Functions Core Tools (2.4.419 Commit hash: c9c1724d002bd90b2e6b41393915ea3a26bcf0ce)
Function Runtime Version: 2.0.12332.0
[3/20/19 7:25:13 PM] Starting Rpc Initialization Service.
[3/20/19 7:25:13 PM] Initializing RpcServer
[3/20/19 7:25:13 PM] Building host: startup suppressed:False, configuration suppressed: False
[3/20/19 7:25:13 PM] A host error has occurred
[3/20/19 7:25:13 PM] Microsoft.Azure.WebJobs.Script: The host.json file is missing the required 'version' property. See https://aka.ms/functions-hostjson for steps to migrate the configuration file.
[3/20/19 7:25:13 PM] Building host: startup suppressed:False, configuration suppressed: True
[3/20/19 7:25:13 PM] Initializing Host.
[3/20/19 7:25:13 PM] Host initialization: ConsecutiveErrors=1, StartupCount=1
[3/20/19 7:25:13 PM] LoggerFilterOptions
[3/20/19 7:25:13 PM] {
[3/20/19 7:25:13 PM]   "MinLevel": "None",
[3/20/19 7:25:13 PM]   "Rules": [
[3/20/19 7:25:13 PM]     {
[3/20/19 7:25:13 PM]       "ProviderName": null,
[3/20/19 7:25:13 PM]       "CategoryName": null,
[3/20/19 7:25:13 PM]       "LogLevel": null,
[3/20/19 7:25:13 PM]       "Filter": "<AddFilter>b__0"
[3/20/19 7:25:13 PM]     },
[3/20/19 7:25:13 PM]     {
[3/20/19 7:25:13 PM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[3/20/19 7:25:13 PM]       "CategoryName": null,
[3/20/19 7:25:13 PM]       "LogLevel": "None",
[3/20/19 7:25:13 PM]       "Filter": null
[3/20/19 7:25:13 PM]     },
[3/20/19 7:25:13 PM]     {
[3/20/19 7:25:13 PM]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[3/20/19 7:25:13 PM]       "CategoryName": null,
[3/20/19 7:25:13 PM]       "LogLevel": null,
[3/20/19 7:25:13 PM]       "Filter": "<AddFilter>b__0"
[3/20/19 7:25:13 PM]     }
[3/20/19 7:25:13 PM]   ]
[3/20/19 7:25:13 PM] }
[3/20/19 7:25:13 PM] FunctionResultAggregatorOptions
[3/20/19 7:25:13 PM] {
[3/20/19 7:25:13 PM]   "BatchSize": 1000,
[3/20/19 7:25:13 PM]   "FlushTimeout": "00:00:30",
[3/20/19 7:25:13 PM]   "IsEnabled": true
[3/20/19 7:25:13 PM] }
[3/20/19 7:25:13 PM] SingletonOptions
[3/20/19 7:25:13 PM] {
[3/20/19 7:25:13 PM]   "LockPeriod": "00:00:15",
[3/20/19 7:25:13 PM]   "ListenerLockPeriod": "00:00:15",
[3/20/19 7:25:13 PM]   "LockAcquisitionTimeout": "10675199.02:48:05.4775807",
[3/20/19 7:25:13 PM]   "LockAcquisitionPollingInterval": "00:00:05",
[3/20/19 7:25:13 PM]   "ListenerLockRecoveryPollingInterval": "00:01:00"
[3/20/19 7:25:13 PM] }
[3/20/19 7:25:13 PM] Starting JobHost
[3/20/19 7:25:13 PM] Starting Host (HostId=mattsmacbookpro-1657537975, InstanceId=3e52acc5-e897-4c54-bb0e-a3bf6f919fdc, Version=2.0.12332.0, ProcessId=17266, AppDomainId=1, InDebugMode=False, InDiagnosticMode=False, FunctionsExtensionVersion=)
[3/20/19 7:25:13 PM] Loading functions metadata
[3/20/19 7:25:13 PM] 3 functions loaded
[3/20/19 7:25:13 PM] Loading proxies metadata
[3/20/19 7:25:13 PM] Initializing Azure Function proxies
[3/20/19 7:25:14 PM] 0 proxies loaded
[3/20/19 7:25:14 PM] WorkerRuntime: node. Will shutdown other standby channels
[3/20/19 7:25:14 PM] Starting language worker process:node  "/Users/mariehoeger/.nvm/versions/node/v8.11.1/lib/node_modules/azure-functions-core-tools/bin/workers/node/dist/src/nodejsWorker.js" --host 127.0.0.1 --port 61387 --workerId c18c7ff9-a4b3-46be-97c8-251258de7447 --requestId 4b002d1e-3e67-4701-89e7-063854ae13b7 --grpcMaxMessageLength 134217728
[3/20/19 7:25:14 PM] node process with Id=17271 started
[3/20/19 7:25:14 PM] A host error has occurred
[3/20/19 7:25:14 PM] Microsoft.Azure.WebJobs.Script: Object reference not set to an instance of an object.
[3/20/19 7:25:14 PM] Stopping JobHost
Hosting environment: Production
Content root path: /Users/mariehoeger/Documents/Demos/azure-functions-typescript
Now listening on: http://0.0.0.0:7071
Application started. Press Ctrl+C to shut down.
Container is disposed and should not be used: Container is disposed.
You may include Dispose stack-trace into the message via:
container.With(rules => rules.WithCaptureContainerDisposeStackTrace())
Application is shutting down...
[3/20/19 7:25:14 PM] Shuttingdown Rpc Channels Manager
[3/20/19 7:25:14 PM] Stopping host...
[3/20/19 7:25:14 PM] Host shutdown completed.
mhoeger commented 5 years ago

cc: @johnpapa

ahmedelnably commented 5 years ago

I would say that this should be the default option, and have a --verbose flag for the full logs

johnpapa commented 5 years ago

I like that too @ahmedelnably - but I wasn't sure if it would be too braking of a change of behavior.

i do think that less is better by default.

johnpapa commented 5 years ago

One additional comment ... I love love love seeing the APIs listed in the output. That should be on by default, IMO

mariomeyrelles commented 5 years ago

To be very honest, the output proves that all the functions were loaded when applicable. I think I like this verbosity.

JustinGrote commented 4 years ago

This can be done with environment variables as a workaround https://github.com/Azure/azure-functions-core-tools/issues/1440

anthonychu commented 4 years ago

@mhoeger @johnpapa Let's restart this discussion and see if we can make any improvements here. /cc @bnb @aaronpowell @ankitkumarr

Thanks to @brettsam and @JustinGrote in #1440, I think we've identified a way to suppress almost any log related to function execution, and some logs at startup.

Based on that conversation, I've put together some of the settings in a repo with examples and a readme: https://github.com/anthonychu/functions-log-suppression

The configuration is complex and error-prone. Agree that there should be a way to only show user-initiated logs, and perhaps do this by default.

Some things to think about:

anthonychu commented 4 years ago

Here's a proposal. Please provide feedback, but would like to start making these changes soon.

Goals

func start

$ func start

Azure Functions Core Tools (3.0.2534 Commit hash: bc1e9efa8fa78dd1a138dd1ac1ebef97aac8d78e)
Function Runtime Version: 3.0.13353.0

Functions:

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

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

        MyTimerTrigger: TimerTrigger (maybe list out the next 5 invocation times?)

        SomeOtherTrigger: QueueTrigger

Host started. For detailed output, run func with the --verbose flag.

Refer to sample here: https://github.com/Azure/azure-functions-core-tools/issues/1131#issuecomment-653171101

Proof of concept can be found here: https://github.com/Azure/azure-functions-core-tools/compare/7dd097e...anthonychu:less-verbose

Function invocation

Executing 'Functions.HttpTrigger' (Reason='This function was programmatically called via the host APIs.', Id=b7b32e4f-4c9f-4a48-b160-5d445644f182)
JavaScript HTTP trigger function processed a request.
Executed 'Functions.HttpTrigger' (Succeeded, Id=b7b32e4f-4c9f-4a48-b160-5d445644f182)

func azure functionapp publish

In general, the deployment output needs to be cleaned up a bit. We might not want to hide them by default as we don't want folks to have to re-deploy with --verbose to see errors.

Display a summary after deployment that outlines important things such as:

Considerations

VS Code debugging

VS Code currently looks for the output Host lock lease acquired by instance ID to determine when to attach the debugger.

Update: This will be addressed by https://github.com/Azure/azure-functions-host/issues/6252

Backward compatibility?

Will this break anything that currently depends on func output? It might. To prevent breakage in CI/CD scenarios, check [these variables] to detect CI environments and automatically use verbose output.

anthonychu commented 4 years ago

@EricJizbaMSFT @fiveisprime Any concerns here for VS Code?

@vijayrkn Would this cause any issues for VS?

bnb commented 4 years ago

The proposed silent output is better, but I'd still like to see more removed plus more whitespace that visually helps separate the different bits of context 😬 

mariehoeger$func start --silent

Starting Azure Functions Core Tools (2.4.419)
Hosting environment: Production

Content root path: /Users/mariehoeger/Documents/Demos/azure-functions-typescript
Now listening on: http://0.0.0.0:7071

Application started. Press Ctrl+C to shut down.

Container is disposed and should not be used: Container is disposed.
You may include Dispose stack-trace into the message via:
container.With(rules => rules.WithCaptureContainerDisposeStackTrace())

Application is shutting down...

I would say that this should be the default option, and have a --verbose flag for the full logs

Strongly agree with this.

Should there be a way to set the log level?

I do generally like this approach, yes. I've typically seen -v, -vv, -vvv, -vvvv, and -vvvvv used for the different log levels at least in the JavaScript world. npm has documented levels here - silent, error, warn, notice, HTTP, timing, info, verbose, and silly. I think a few of these could potentially apply here.

Should it just be configurable via flag? Should we support something else like an environment variable as well?

Environment variables as a way to define this would be a base expectation for me.

Should silent be the default?

Yes.

Change default to a less verbose output that @mhoeger suggested, hiding almost everything that is Information or Debug

Sounds like you've identified two other log levels here 😛

func start

see my feedback about log output at the beginning of this comment. I think at the bare minimum chunking the information would be extremely helpful in the same way it would be on the web - helps improve scanning for most important information.

Function Invocation

Is the Id=b7b32e4f-4c9f-4a48-b160-5d445644f182 information actually useful for something? I've never seen a direct need for it myself.

Not sure if this is a good time for this discussion, but Reason='This function was programmatically called via the host APIs.' could hopefully be converted to Reason: This function was programmatically called via the host APIs. for a slightly more human-readable output.

vijayrkn commented 4 years ago

VS does not rely on the output. So I am not expecting any impact. The only question would be - Is it required to surface this option in the VS UI somewhere to trigger the verbose option.

btholt commented 4 years ago

I like this a lot better. I'd still like to see a brief output of "this function was called" of some variety or at least have that option.

Hey @antempus do you have any thoughts on this?

anthonychu commented 4 years ago

Thanks @bnb. We can definitely clean up the initial output more. Currently planning to leave the ASCII art in, as I think some Azure Functions fans would miss it (I mean, it has its own T-shirt 😄). Perhaps we can add a --silent flag in the future that limits output to the absolute minimum.

I thought about taking out the id from the function executing/executed messages, but if there are multiple functions executing at once and/or the functions are long running, they could be useful for correlation.

@btholt We're still planning to output function executing/executed messages.

Thanks @vijayrkn. I don't think we need a UI to turn this on. Is the text of the command currently configurable in VS?

vijayrkn commented 4 years ago

normally msbuild output is configurable but custom exe output is not configurable in VS.

ejizba commented 4 years ago

The only thing that affects VS Code has been mentioned already. We look for "Host lock lease acquired by instance ID" to know when to start debugging, but @pragnagopa is changing that in this issue. Assuming we can coordinate timing, it might make it easier if we remove the "host lock" message at the same time we add Pragna's new message. That way I can keep looking for "host lock" for users on an older version of the func cli, but it won't trigger debugging for users on the latest func cli (which has the new message).

antempus commented 4 years ago

I believe that @bnb covered most of my concerns pretty succinctly, although the ASCII should stay 😄.

Is the Id=b7b32e4f-4c9f-4a48-b160-5d445644f182 information actually useful for something? I've never seen a direct need for it myself.

This is important from my experience in debugging durable functions but once it's deployed, it can be done via App Insights logs traces.

Change default to a less verbose output that @mhoeger suggested, hiding almost everything that is Information or Debug'

I agree, but there was discussion about suppressing the logs from the function runtime, but I noticed that this was also suppressing any logs from code instrumented, though that may have been an error on my part; I'd like so see only the function logs and not the runtime logs.

From @anthonychu's proposal

Add a --verbose flag

I like the idea, but if we're adding in a flag for a single log level to the function runtime, would it make sense to instead have a log level param rather than specifically verbose?

func azure functionapp publish

  • how long the deployment took

Please add this; for larger function apps this gives us actionable information for refinement.

ejizba commented 4 years ago

Fwiw, I'd give a big +1 for removing the ASCII art. It takes up a lot of real estate, which comes at a premium in most CLI windows. I think it's common to prioritize utility over being "cool/fun/tshirt-worthy" for a CLI, which is why I'm not aware of any other popular cli that does something like this (e.g. git, node, npm, docker, dotnet, az). The ascii art was cool the first time I saw it, but every time after that it was just annoying. Finally, removing the art fits squarely under the top two goals mentioned:

anthonychu commented 4 years ago

@EricJizbaMSFT Good point and makes sense. We can remove the logo from func start.

JustinGrote commented 4 years ago

I mean, I kinda like it, helps me know what I'm doing sometimes, how about func start -nologo? :)

mhoeger commented 4 years ago

+1 for keeping ascii! It helps me visually distinguish runs with func host start and I think it's pretty clearly not obscuring any other important information.

Although I do have to admit I just like it too! And I hate reading so I'll take all the visual cues I can get :P

antempus commented 4 years ago

Finally, removing the art fits squarely under the top two goals mentioned:

  • Minimize noise
  • By default, display only information that is necessary

Now I am conflicted, I think @JustinGrote's solution fits here.

ejizba commented 4 years ago

@EricJizbaMSFT Good point and makes sense. We can remove the logo from func start.

Lol @anthonychu might be a bit quick to "pick a side" - I fully realize the ascii stuff could have strong opinions both ways and will probably need more deliberation 😂 Might even be worth it's own issue haha

JustinGrote commented 4 years ago

It works for PowerShell. Powershell vs powershell -nologo

johnpapa commented 4 years ago

How about a mini version of the ascii art for default. And the big one for verbose!

Also - I think the functions would be super readable if they are laid out and using chalk to color the types and endpoints

aaronpowell commented 4 years ago

+1 on the colourisation idea from @johnpapa, it can help find the different "level" messages, and also if developers are able to control their colours, that helps find messages easily.

trallard commented 4 years ago

Thanks for looping me in! Here are some thoughts:

Definitely! Also enabling the use of env variables for default preferences would be a great addition. I always appreciate when this can be done once and almost forget about it unless I need a special debugging mode.

Display key info in a summary view after long operations

From the competitive analysis I conducted a while ago:

image

The displayed output is concise, readable and allows for easy identification of important information regarding the function deployment. A similar output could be massively helpful in such contexts

Finally regarding ASCII art - maybe a smaller version would be nice as well as allowing to "hide" using again an env or config file?

bnb commented 4 years ago

Finally regarding ASCII art - maybe a smaller version would be nice as well as allowing to "hide" using again an env or config file?

Huge +1 to this. It consumes a lot of space for little utility other than being nice branding. Perhaps add in the env var now with the plan to eventually flip it so that you need an env var to show it if you'd like it there 👍

robconery commented 4 years ago

A downside to the ASCII art is logging and instrumentation - if it gets written to a file we're not doing anyone any good :) and we end up bloating their logs which can cost people $$. I know we dig our branding at MS but it's entirely unnecessary and I agree if we have a -v we can show it :).

Here's the output from the Firebase emulator, which I find nice and clean and well laid out. The prompt at the end (Issues?...) is especially helpful. Note that this is for all the emulators - not just functions:

screenshot_265

robconery commented 4 years ago

Also - here's another CLI bomb from AWS Amplify. This is their error screen telling me that I just screwed up a command. I see ASCII art shouting at me as I try to parse what went wrong:

screenshot_274

If you can't tell I think ASCII Art is fun in the eyes of the tooling team, maybe not with the end user who's seen it 100 times and just wants to get on with life.

anthonychu commented 4 years ago

Thanks everyone for your comments.

Here's the current plan for the first iteration of this.

Addressing some of the other comments:

Once the first set of changes are made, we can continue iterating on this to further improve the output. For more drastic changes, we should address them in the next major release.

aaronpowell commented 4 years ago

@anthonychu I've spent some time in the logging code of the host tool if you need another pair of eyes.

fabiocav commented 4 years ago

@anthonychu thank you for the summary. Can you please also add the logo change to the original issue comment so that contains all of the requirements?

Honestly, as we've discussed in the past, the only concern remains the change in the default behavior. Just as VS Code has a dependency on some of the output we emit today, other users may have similar logic and that would be broken by that (e.g. a CI flow that installs the Core Tools and parses some of the output). This is not an argument as to whether doing that is right or wrong, but about that being a possibility and the output change qualifying as a breaking change.

I think we need to consider that and make this opt-in with an argument. Our tools (VS Code and others) could pass that argument by default.

Also, I like the idea of a smaller version of the ASCII art :)

anthonychu commented 4 years ago

This might break folks who are using Core Tools in a CI pipeline.

Is anyone currently running func start in a pipeline and depending on the output? @pragnagopa @Hazhzeng do you have any experience running Core Tools in a CI pipeline?

I think this can be mitigated by checking the environment for most of the popular CI platforms. @fabiocav Do you think this is acceptable? Can check if there's a port of this library for .NET (or we can port it): https://github.com/watson/ci-info

anthonychu commented 4 years ago

Proposed changes to func start:

core-tools-less-verbose

johnpapa commented 4 years ago

I love it !!! Thank you for this!

pragnagopa commented 4 years ago

Is anyone currently running func start in a pipeline and depending on the output?

I am not aware of any . Tagging rest of the team for awareness. @soninaren , @yojagad , @ankitkumarr , @gzuber

soninaren commented 4 years ago

Core tools e2e test framework uses output to verify the test success of failure. Every test is looking for specific thing from output. Not specifically aware of the test for func start.

trallard commented 4 years ago

Neat! Wil the output with --verbose be the same as the old default? Or will it be improved for legibility / be sanitised?

anthonychu commented 4 years ago

@trallard It’ll stay the same for now, as we need to be careful about processes that may be depending on the output. We can do a bigger cleanup next time we ship a new major version.

fabiocav commented 4 years ago

Core tools e2e test framework uses output to verify the test success of failure. Every test is looking for specific thing from output. Not specifically aware of the test for func start.

@anthonychu this is what I was referring to. And it's possible we have customers doing the same thing, hence the concern about the change to the defaults.

Thanks for sharing the animation!

anthonychu commented 4 years ago

@fabiocav I think if we can detect that func start is running in a CI environment and show the current output in those cases (looks like we can easily detect all of the known environments), I can’t imagine too many automation scenarios that would break. If someone is running tests manually on their desktop, they would notice the break and can fix.

The publish command is where I’d worry about processes depending on the output, and we’re not touching that output for now.

bnb commented 4 years ago

@anthonychu just wanted to say that the new output is amazing and honestly what I've wanted since my first day at Microsoft. Thank you for working on this ❤️

TroyWitthoeft commented 4 years ago

@anthonychu Aww, but we've grown so fond of the lightning bolt ascii art! ⚡ Vote to keep it. If it has to go, then can we at least have some starting and ready timestamps? Measuring that startup time is important. Especially, considering the root cause of some of the debugger attach issues.

fabiocav commented 4 years ago

Assigning the issue to sprint 81 so we can define the tasks and scope the work.

fabiocav commented 4 years ago

This is assigned to sprint 81 as a stretch goal.

pragnagopa commented 4 years ago

Moving this issue to epics as this issue captures multiple improvements. Following issues track improvements identified

jeffhollan commented 4 years ago 
              %%%%%%
             %%%%%%
        @   %%%%%%    @
      @@   %%%%%%      @@
   @@@    %%%%%%%%%%%    @@@
 @@      %%%%%%%%%%        @@
   @@         %%%%       @@
     @@      %%%       @@
       @@    %%      @@
            %%
            %

teamAsciiArt

All the other changes are fantastic tho 👍 (we can explore ways to make traditionalists like myself happy in issue #2222 - we gotta keep some personality in the stuff we build)

nzthiago commented 4 years ago 
     %%%%
 @    %%  @
@@  %%%%  @@
 @   %%   @
    %

Baby functions asciiart

fabiocav commented 4 years ago

teamAsciiArt

If this trends, I guess we can think about it :)

jeffhollan commented 4 years ago

Hahah good to have you back @fabiocav. I will admit I had to build some functions today and the console output being so minimal is something I could get used to.