CLI: add verbosity control #5085
Merged
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Codecov Report
@@ Coverage Diff @@
## develop #5085 +/- ##
===========================================
- Coverage 80.55% 80.55% -0.00%
===========================================
Files 531 532 +1
Lines 36970 36999 +29
===========================================
+ Hits 29776 29799 +23
- Misses 7194 7200 +6
Flags with carried forward coverage won't be shown. Click here to find out more.
Continue to review full report at Codecov.
|
sphuber
force-pushed
the
fix/4330/cli-verbosity-control
branch
from
e1565f3 to
01030f5
Compare
|
thanks a lot @sphuber - I guess you're looking for a review from one of us three. |
|
Thanks @ltalirz . I pinged you since you have wrote the original PR and were involved in all the discussions, but I guess if the other's review it, that would be fine as well. You can always just give feedback on the higher level design and naming decisions and leave the review of the implementation to the rest. To see what it would look like and how it would work for the user, you can maybe have a quick look at the section I wrote for the docs: |
|
Thanks @sphuber. one of these is then there are three instances of directly creating an option with again they directly set certain logger levels, which are then used in the calling functions, plus there is the relationship between verbosity levels and progress bars, which would need to be adapted a bit |
|
There are 66 instances of |
Good point. I will address this, removing the
I think we should not change these to report, because that would change the current behavior. Also, under our definition of |
The built-in `logging` module comes with a number of pre-set logging levels, such as `DEBUG` and `INFO`. AiiDA adds the `REPORT` level, which sits in between `INFO` and `WARNING` and is designed to add some extra granularity of control for messages. The report level is intended to be used for messages that are purely informational, and so not a warning, yet they should probably be shown by default. Traditionally, `INFO` log messages logged by module code are often a bit too verbose to always be showing by default. That is why AiiDA sets the default loglevel to `REPORT` allowing code, such as `WorkChain`s to emit informational messages that are shown by default, without also forcing all `INFO` messages to be shown, which are typically too verbose. To make the `REPORT` level behave like a built-in level, we hot-fix the `logging.Logger` class to also have a `report` method, such that it can be called as one would call `debug()` or `info()`.
sphuber
force-pushed
the
fix/4330/cli-verbosity-control
branch
from
01030f5 to
fb49fc6
Compare
The behaviour will already being changing though won't it? i.e. If the (the archive commands have not yet been changed in this PR, so at least for now the |
The custom class used for the `verdi` command, `MostSimilarCommandGroup` is renamed to `VerdiCommandGroup`. The reason for this is that it adds new functionality, in addition to the existing functionality of suggesting command names in case the command is not found, to automatically add a `-v/--verbosity` option to all commands. This option provides a choice to set the log level for the AiiDA logger. This allows a user to control the verbosity of output that is emitted through the logging system in a way that is consistent across all `verdi` commands. Since through this method, the verbosity option is only added to sub commands, the top-level commands `verdi` itself won't inherit from this mechanism. Instead, the option is added manually and explicitly. Note that in this case the callback of the verbosity, which sets the log level on the profile, does not work, since for the top-level command the verbosity option is parsed before the profile is set on the context. That is why the processing of the verbosity is done explicitly in the command itself. By making the `-v` option available for all commands, the user can pass it at only level of the sub command stack. There is one side-effect however. Since `verdi` itself already had the `-v/--version` option, which clashes with the `-v/--verbosity`, the `-v` shorthand for the version option had to be removed. For consistency the `-h` shorthand for the help flag, which is the only other option that is also available across all commands, is also removed. Note that this change also fixes a bug that only made the command name suggestion functionality available at the top level but not for the sub commands. By overriding the ``group`` method to use the same class as the top-level `verdi` command, all subcommands should recursively have the same functionality. There is one subtlety where if the `cls` is set explicitly by one of the subcommands, that should be respected. It can't simply override it with `VerdiCommandGroup` because the subclass may have overridden the `get_command` as well with custom functionality. This puts the onus on the developer of subcommands with custom classes to make sure it inherits from `VerdiCommandGroup` if it is going to overwrite the `get_command` method and make sure it calls the super. Finally, the ``run_cli_command`` fixture, designed to help test CLI commands, needed to be updated to manually apply the ``VERBOSITY`` option. In testing, the sub command is direclty fetched from the module where it is defined, instead of getting it through the ``click`` API starting from the base ``verdi`` command. This means the functionality that applies the ``VERBOSITY`` option is not hit and so it has to be called manually.
The utility functions in the `aiida.cmdline.utils.echo` module are designed to be used in CLI commands to print output to stdout or stderr streams. This is now changed to instead log the message to the `aiida.cmdline` logger. This logger was added in the previous commit. The reason is that the verbosity of this logger can be controlled through the `--verbosity` option that was added to all commands. To match the available log levels, the `echo_report` method was added, which, as the name suggests, logs messages at the `REPORT` level. The `echo` method, which was used to simply print a message without a particular prefix, logs also at the `REPORT` level, since that is the default log level in AiiDA. This makes sense since when developers used `echo` they probably want it to show by default, but it is not a warning and so should not be shown when the log level is set to `WARNING`. The `echo_highlight` method has been removed as it was essentially a thin wrapper around functionality that is already provided by `echo`. Instead of using the different `color` argument, one can use `echo` using the `fg` argument which is more consistent with the interface from `click`'s methods which are wrapped. All remaining direct calls of `click.echo` and `click.secho` in the code have been replaced by the relevant `cmdline.utils.echo` command to make sure that they are properly piped through the logging system and respect the `--verbosity` option. Note that a few instances remain, for example, in the `verdi completioncommand` command, but this is intentional as they should not be influenced by the `--verbosity` option.
sphuber
force-pushed
the
fix/4330/cli-verbosity-control
branch
from
fb49fc6 to
a1ff72c
Compare
|
Ah yeah, I forgot that Casper and you programmed the delete and export functionality such that info messages would be shown by default. If that is the case, then they should indeed be changed to report. Looking at those messages, I feel that they are still quite verbose and it actually makes sense to not show them by default and the user should just pass |
In the previous commit, the `echo` utility functions were changed to go through the logger system, instead of directly using `click.echo` to print to stdout and stderr. Since the default log level is `REPORT` in AiiDA, messages logged with `echo_info` will no longer be shown by default, unless the log level is set to `INFO` or `DEBUG`. To return to the previous behavior, all `echo_info` instances are replaced by the new `echo_report`, unless the existing message really corresponds to info that is a bit verbose and can be hidden by default. Calls to `info` for the `MIGRATE_LOGGER`, `EXPORT_LOGGER` and the `DELETE_LOGGER` are changed to `report`. The current implementation using these loggers assumed that the default log level would be `info` and so these messages should be shown by default. This choice was made since this functionality is mostly called through the command line. With the current change where the default is now `report` these messages would no longer show up by default.
sphuber
force-pushed
the
fix/4330/cli-verbosity-control
branch
from
a1ff72c to
c003b19
Compare
aiida/cmdline/commands/cmd_code.py
Outdated
| @options.DRY_RUN() | ||
| @options.FORCE() | ||
| @with_dbenv() | ||
| def delete(codes, verbose, dry_run, force): | ||
| def delete(codes, dry_run, force): | ||
| """Delete a code. | ||
|
|
||
| Note that codes are part of the data provenance, and deleting a code will delete all calculations using it. | ||
| """ | ||
| from aiida.common.log import override_log_formatter_context |
There was a problem hiding this comment.
Do we still need to use this here?
There was a problem hiding this comment.
I don't think so no, since the logging now goes through the echo functions which essentially do this formatting. Shall I also remove the utility itself, since its only use is in the cmdline commands?
There was a problem hiding this comment.
Quite proably yeh, again it would be good to run some of these commands once you are done and print the terminal output here, so we can check they are still looking pretty 😄
There was a problem hiding this comment.
Uhm, there is still a problem. Even though the logging level of the child loggers is properly set on the AIIDA_LOGGER and they inherit it, they still have the default formatting. Removing these overrides will therefore return the "incorrectly" formatted log messages. I think we should still remove them, but like the log level, also change the formatter for the AIIDA_LOGGER and all its children, globally.
There was a problem hiding this comment.
OK, commit 6340311 implements a solution for this problem by configuring a custom formatter for all loggers when the CLI is invoked.
The `VERBOSE` option is obsolete since all commands now automatically have the `VERBOSITY` option exposed. The `VERBOSE` option was mostly used to configure a logger (most notably the `DELETE_LOGGER`) but this is no longer necessary. Since those loggers are children of the main `AIIDA_LOGGER`, whose level is controlled through the `VERBOSITY` option, the child logger will inherit its value. Some commands used the `VERBOSE` option more as a boolean switch. To reproduce this behavior, a utiltiy function `is_verbose` is added to the `cmdline` module, which will return `True` if the loglevel of the `CMDLINE_LOGGER` is equal or smaller than the `INFO` level and `False` otherwise. The `verdi archive` commands used an ad-hoc implementation of the verbosity option. This has been removed and they now also rely on the logging level that is set on the `AIIDA_LOGGER` through the global `VERBOSITY` option.
sphuber
force-pushed
the
fix/4330/cli-verbosity-control
branch
from
c003b19 to
ec81d0b
Compare
| @@ -170,11 +165,10 @@ def create( | |||
| elif archive_format == 'null': | |||
| export_format = 'null' | |||
|
|
|||
| if verbosity in ['DEBUG', 'INFO']: | |||
| set_progress_bar_tqdm(leave=(verbosity == 'DEBUG')) | |||
| if AIIDA_LOGGER.level <= logging.INFO: | |||
There was a problem hiding this comment.
should this not be <= logging.REPORT now
There was a problem hiding this comment.
(and same for other two instances below)
There was a problem hiding this comment.
Should be there now. Were a bunch of other fixes that had to go in.
So far, the utility functions of the `aiida.cmdline.utils.echo` module have been rerouted through the `CMDLINE_LOGGER` which properly formats the log message with just the message itself. However, the loggers of any other modules will inherit the formatter of the parent `AIIDA_LOGGER` which will prefix the message with verbose content such as the timestamp, name of the logger and more, which is not what we want for output generated by CLI commands. The solution is to define a custom formatter, `CliFormatter`, which is added to the new module `aiida.cmdline.utils.log`, and which is configured by default for the `CMDLINE_LOGGER`. The `configure_logging` function is updated to now take a keyword argument `cli`, which when set to `True`, will configure this new formatter for all loggers. By calling this method with `cli=True` in the callback of the `VERBOSITY` option, all loggers should be correctly configured to only print the message with the log level prefixed, when invoked through the CLI. There is one peculiarity where the `load_backend_if_not_loaded` decorator utility also needs to call the `configure_logging` function. The reason is that this function loads the database backend, which indirectly calls the `configure_logging` to add the database log handler, but this does not pass `cli=True`. This means that the CLI specific configuration is undone.
sphuber
force-pushed
the
fix/4330/cli-verbosity-control
branch
4 times, most recently
from
28edae6 to
5998152
Compare
The `override_log_formatter` and `override_log_formatter_context` utilities of the `aiida.common.log` module were used in certain CLI commands to temporarily change the formatter of the logger. This was done because they used the logging system as the way to output messages to the terminal, but the default logger prefixed messages with extensive information such as timestamps and the name of the logger, where only the message was required. These utilities are no longer needed since this custom formatting for the CLI is now done ensured by configuring the `CliFormatter` custom formatter which takes care of only including the log level as prefix.
sphuber
force-pushed
the
fix/4330/cli-verbosity-control
branch
from
5998152 to
35fe868
Compare
chrisjsewell
approved these changes
Aug 24, 2021
6 tasks
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Supersedes #3896
Fixes #4330
For those reviewing this, I recommend looking at the individual commits.
REPORTlevel and thereportmethod to theloggingbuilt-in module. This will allow it to be used just like for examplelogging.DEBUGandlogging.debug()and the other standard log levels.-v/--verbosityoption that is automatically added to allverdicommands. When specified on the CLI, this option changes the log level for theAIIDA_LOGGERby setting the corresponding option value on theProfileinstance that is loaded in memoryaiida.cmdline.utils.echomodule to log their messages to theCMDLINE_LOGGER, a direct child of theAIIDA_LOGGER, instead of directly echo'ing the messages tostdoutandstderr.echo_infoinvocations forecho_report. SinceREPORTis the default log level, after the previous changes the content ofecho_infowill no longer show up, so we change them toecho_report.