getgauge / gauge

Light weight cross-platform test automation
https://gauge.org
Apache License 2.0
2.99k stars 344 forks source link

Documentation plugins should be able to respect log level and machine readable command line flags. #2001

Open johnboyes opened 3 years ago

johnboyes commented 3 years ago

Is your feature request related to a problem? Please describe. Documentation plugins should be able to respect the log-level and machine-readable command-line flags, e.g. if a user runs a documentation plugin with --log-level debug then the documentation plugin should be able to respect that by logging at that level (and sending debug messages to stdout, if it wishes to).

Describe the solution you'd like Gauge core to set environment variables e.g. GAUGE_LOG_LEVEL and GAUGE_MACHINE_READABLE for documentation plugins to be able to pick up, in the same way that the GAUGE_SPEC_DIRS and GAUGE_PROJECT_ROOT env vars are set.

Describe alternatives you've considered I can't think of any other decent alternative solutions other than environment variables. It wouldn't be viable to have a breaking change for this in the protobuf API between Gauge core and documentation plugins, for instance.

Additional context I'm happy to submit a PR if this feature request is accepted.
Also one other thing I noticed is that Gauge core always sets the log level to debug for the log file logging, rather than respecting the log level set in the command-line flag (whereas the output sent to stdout does respect the flag). Is that intentional?

zabil commented 3 years ago

Gauge core to set environment variables e.g. GAUGE_LOG_LEVEL and GAUGE_MACHINE_READABLE for documentation plugins to be able to pick up, in the same way that the GAUGE_SPEC_DIRS and GAUGE_PROJECT_ROOT env vars are set.

This works, PR welcome.

Also one other thing I noticed is that Gauge core always sets the log level to debug for the log file logging, rather than respecting the log level set in the command-line flag (whereas the output sent to stdout does respect the flag). Is that intentional?

I assume this was done to make sure that files had enough info in case someone runs into issues. @sriv might have more context.

sriv commented 3 years ago

I don't recollect this being intentional, need to dig notes/conversations. However I think gauge should respect the log level and set it according to the flags passed. The default could be verbose, but it should honour the values passed both via env variable and the --log-level flag.

johnboyes commented 3 years ago

Thanks @sriv, makes sense. I think we should treat that as a separate GitHub issue to this one in that case, if you agree? If so, would you like to create that issue, or shall I?

Also, one other small thing I've noticed is that Gauge core does not handle critical as a logging level input, even though the log-level command line flag lists critical as one of the valid options.

sriv commented 3 years ago

Yes - that's inconsistent. We've never had the need for critical but I suppose that got added as an option.

sriv commented 3 years ago

I think we should treat that as a separate GitHub issue to this one in that case, if you agree?

yes, please!

johnboyes commented 3 years ago

it should honour the values passed both via env variable and the --log-level flag

Are you referring to the new GAUGE_LOG_LEVEL env variable which we're introducing via the PR I'm working on now for this current issue? This raises the question of whether the new env var should only exist if a documentation plugin is running (which was my initial assumption), or whether it should always be settable, as an alternative to the command line flag. Thoughts?

sriv commented 3 years ago

GAUGE_LOG_LEVEL is used by other plugins as well, but it's not set by Gauge, rather it's passed as env to the plugin. ex: https://github.com/getgauge/gauge-dotnet/blob/87491ecb29daff07c30c9040b43451db5682f30a/src/GaugeProjectBuilder.cs#L37

The theme is that GAUGE_LOG_LEVEL is set before invoking gauge and that gets passed on to the plugins. --log-level is parsed and set by gauge as log level when invoking the plugin. I won't be surprised if this is inconsistent though!

johnboyes commented 3 years ago

How about the following rules, going forward?

Thoughts on this proposal, @sriv and @zabil?

The other thing to work out is whether the logging level should also control what is displayed to the user on the console. At the moment the log level does control what is displayed on the console, but doesn't control the log level on the logs themselves (which is counterintuitive, I think). Options:

  1. apply the log level to console output as well as to the log files. While this has the advantage of being consistent and easily understandable, it means that (with debug being the new proposed default), the console default will effectively have changed from info to debug, meaning much more console output by default.

  2. only apply the log level to the log files, and use another mechanism to set what is output on the console. This would be a breaking change as it is the opposite of what happens now. NB in terms of other mechanisms, the verbose command line flag is not currently used for this purpose, rather it is used just as a gauge run flag to: Enable step level reporting on console, default being scenario level.

Neither of these options seems ideal, so I'm unclear about what would be best. Thoughts?

johnboyes commented 3 years ago

Thinking about it more, I think that 2. in my last comment could be a decent option, as to me it is the one which satisfies the principle of least astonishment.

Proposed rules for option 2:

Examples:

an individual message with log level gauge log level (set by user) verbose (set by user) logged console output
debug info no no
debug info yes no yes
debug debug yes no
debug debug yes yes yes
debug yes no

Thoughts? Obviously you have more intimate knowledge of the history and design ideas, so these are just tentative proposals.

sriv commented 3 years ago

Rules for log level

How about the following rules, going forward?

Thanks for thinking through this. Logging in gauge definitely needs more love!

The command line flag takes precedence if both the environment variable and the command line flag are set by the user.

I am inclined towards the opposite, i.e. env var takes precedence for two reasons:

The default logging level is debug

This will be a breaking change, and I'd be worried about the console log. If we decide that the log level flag will affect only the log files, I'd be a bit more relaxed. But nevertheless this will be a breaking change. @zabil - what do you feel about this?

Rest of the rules seem quite reasonable.

whether the logging level should also control what is displayed to the user on the console

Historically, we intended the console log to be as terse as possible, highlighting the key things. gauge.log is supposed to have all the details.

This has pros and cons. i.e. in a CI system, the console out is the best resource. Downloading a log file, and analyzing it is quite a chore.

the --verbose and --log-level=debug seem similar but serve different purposes. I think this adds to the cognitive burden for the user. Looking back, I think these should carry the same meaning, i.e. --verbose should be a shortcut to --log-level=debug. And in this verbose mode, gauge should print specs,scenarios, steps as well as other debug information.

What's also worth thinking about is should the debug log entries be prefixed with something like [debug] in the console? @zabil ?

johnboyes commented 3 years ago

I am inclined towards the opposite, i.e. env var takes precedence

Your reasoning makes sense, agree

This (default logging level of debug) will be a breaking change, and I'd be worried about the console log. If we decide that the log level flag will affect only the log files, I'd be a bit more relaxed.

Yes, I see your point. Reason for proposing debug as default earlier in the thread is that it already is the default (and indeed only option currently allowed - though it's not explicit) for log files. It's not the only option we have, as I see it we have the following 3 options for the default logging level:

  1. debug (for both console and log files): has the pros and cons you have mentioned
  2. handle the logging level for the console and the log files differently, and make this explicit (they are currently handled differently, but it's not explicit and is currently counter-intuitive as outlined earlier in the thread). One way of doing this would be to use the verbose flag for the console, and log-level for the log files. NB this option is the same as the option 2. in my earlier post in this thread. This does have a greater cognitive load as you say than the other options, but also provides more flexibility and arguable better defaults (i.e. terse console output and verbose log file output by default)
  3. info (for both console and log files): this would be a breaking change for the log files, as they are currently always set to debug

Thoughts? Would be great to get your thoughts too, @zabil?

zabil commented 3 years ago

Thanks for being thorough in this. Logging definitely needs a lot more thought.

As already mentioned. The original design is to make the console logs as silent as possible. The console for test reporting critical errors.

There is also a bit of confusion around log level debug and --verbose output. IMHO the verbose output is all info related to execution and reports, while log levels are program level info mostly for developers or tracing the calls, plugin messages etc.

So I think option 2 is the best approach.