Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
mhoeger opened this issue Mar 20, 2019 · 57 comments
Open

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

mhoeger opened this issue Mar 20, 2019 · 57 comments
Assignees
Labels
Milestone

Comments

@mhoeger
Copy link
Contributor

mhoeger commented Mar 20, 2019

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
Copy link
Contributor Author

mhoeger commented Mar 20, 2019

cc: @johnpapa

@ahmedelnably
Copy link
Contributor

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

@johnpapa
Copy link

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
Copy link

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

@mariomeyrelles
Copy link

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

@ahmedelnably ahmedelnably added this to the Backlog milestone Dec 11, 2019
@JustinGrote
Copy link

This can be done with environment variables as a workaround
#1440

@anthonychu
Copy link
Member

@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:

  • Should the options just be verbose (all logs) and silent (only user initiated logs)?
  • Should there be a way to set the log level?
  • Should it just be configurable via flag? Should we support something else like an environment variable as well?
  • Should silent be the default?

@anthonychu
Copy link
Member

anthonychu commented Jun 13, 2020

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

Goals

  • Minimize noise
  • By default, display only information that is necessary
  • Use formatting and coloring to emphasize/de-emphasize output based on importance
  • Display key info in a summary view after long operations

func start

  • Change default to a less verbose output, hiding almost everything coming from host or Core Tools that is Information or Debug
  • Add a --verbose flag that outputs the current (original) log levels
  • Remove timestamps from output when not verbose
  • Display a summary of all functions, not just HTTP
  • Output a message to indicate host is ready (required by VS Code to attach debugger)
  • Update: Remove logo 😱
$ 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: #1131 (comment)

Proof of concept can be found here:
7dd097e...anthonychu:less-verbose

Function invocation

  • Remove the HTTP response JSON output
  • Would be great if we could de-emphasize the executing/executed messages to make it easy to pick out logs from user code
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:

  • What function app it was deployed to
  • How long the deployment took
  • Deployment method and info relevant to the method: e.g., run from package with the location of the package
  • List out functions (both HTTP and non-HTTP)

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.

  • Need to output something to indicate host is up
  • Need to modify the func-watch problem matcher in the VS Code extension to support this new message

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
Copy link
Member

@EricJizbaMSFT @fiveisprime Any concerns here for VS Code?

@vijayrkn Would this cause any issues for VS?

@bnb
Copy link

bnb commented Jun 16, 2020

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
Copy link

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
Copy link

btholt commented Jun 16, 2020

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
Copy link
Member

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
Copy link

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

@ejizba
Copy link
Contributor

ejizba commented Jun 16, 2020

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
Copy link

antempus commented Jun 16, 2020

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
Copy link
Contributor

ejizba commented Jun 16, 2020

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:

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

@anthonychu
Copy link
Member

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

@JustinGrote
Copy link

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

@mhoeger
Copy link
Contributor Author

mhoeger commented Jun 16, 2020

+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
Copy link

antempus commented Jun 16, 2020

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
Copy link
Contributor

ejizba commented Jun 16, 2020

@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
Copy link

It works for PowerShell. Powershell vs powershell -nologo

@johnpapa
Copy link

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
Copy link
Contributor

+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
Copy link

trallard commented Jun 18, 2020

Thanks for looping me in! Here are some thoughts:

  • +1 on using colourization to allow for easier identification of log levels, endpoints and other relevant features (this can also help identify different logging levels i.e. error, info)
  • I am all for being able to have the silent output as the default and the --verbose as a flag that folks can use as needed.

Should there be a way to set the log level?

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
Copy link

bnb commented Jun 18, 2020

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
Copy link

robconery commented Jun 18, 2020

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

@bnb
Copy link

bnb commented Jul 6, 2020

@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
Copy link

@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 fabiocav modified the milestones: Backlog, Functions Sprint 81 Jul 16, 2020
@fabiocav
Copy link
Member

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

@fabiocav
Copy link
Member

This is assigned to sprint 81 as a stretch goal.

@pragnagopa
Copy link
Member

pragnagopa commented Aug 6, 2020

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

@jeffhollan
Copy link

jeffhollan commented Sep 11, 2020

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

#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
Copy link
Member

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

Baby functions asciiart

@fabiocav
Copy link
Member

#teamAsciiArt

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

@jeffhollan
Copy link

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.

@fabiocav
Copy link
Member

Yeah, I was on the fence about some of the changes, but it's a nice experience.

@anthonychu
Copy link
Member

ASCII art discussion: #2222

@CraftyFella
Copy link

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

I'd also say if you could add all functions and their triggers to the output. Like a servicebus trigger, eventgrid, etc.. they are listed in the azure portal so assume it's possible.

@anthonychu
Copy link
Member

@CraftyFella That's one of the things we added. Let us know if you're not seeing it.

image

@vikalpjain91
Copy link

do anyone have any idea how we can see the all the detailed output while debugging it. I am unable to find it anywhere!

@anthonychu
Copy link
Member

@vikalpjain91 Set the default log level in host.json to Information. Example:

{
  "version": "2.0",
  "logging": {
    "applicationInsights": {
      "samplingSettings": {
        "isEnabled": true,
        "excludedTypes": "Request"
      }
    },
    "logLevel": {
      "default": "Information"
    }
  },
  "extensionBundle": {
    "id": "Microsoft.Azure.Functions.ExtensionBundle",
    "version": "[1.*, 2.0.0)"
  }
}

@pragnagopa
Copy link
Member

@vikalpjain91 - You can also add --verbose flag to func start command in VS Code tasks.json . If you are using VS, add start --verbose in application debug arguments

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests