Skip to content

Conversation

@sadielbartholomew
Copy link
Member

@sadielbartholomew sadielbartholomew commented May 7, 2020

Resolves #31. This sets up minimal logging to delegate all applicable library messages to the logging module, such that they emerge as before by default, but there is new functionality in that they can be filtered out by severity level via a configurable global log severity level addressing the root logger, however the verbose keyword argument in a method will behave as before by overriding the log level.

Implementation

The main code changes here to achieve the above are:

  • loggers, which are instantiated on a modular basis, as is recommended practice, with all inheriting from the root logger initiated in the __init__.py (if we add further logging configuration, we should move this to a dedicated module e.g. logging-config.py);
  • a new function cfdm.LOG_SEVERITY_LEVEL [now renamed simply cfdm.LOG_LEVEL for clarity to reflect that the levels are a mixture of verbosity- & severity- based] to change the minimal level at which log messages emerge, being WARNING by default:
    • I have written it so it accepts either the named (case insensitive) words for the levels, e.g. WARNING, INFO, or instead an integer from 1 through to 5 [now -1 to 3 in a revised schema - see later comment] mapped to those, which is easier for users to recall, though less explicit;
  • a new decorator _manage_log_level_via_verbosity which provides the interface with decorated methods' verbose keyword argument, such that, as agreed, if verbose is:
    • True: will display all log messages from that method & any method it calls;
    • None, as is now the default for all such methods: will use the global log severity level to determine which messages to display so some at lower levels can be filtered out if configured as such;
    • False: will not display any log messages from that method or any method it calls.
    • [Edit:] verbose now takes integer levels consistent with those supported by cfdm.LOG_LEVEL for increased granularity of per-function verbosity control, see Basic logging w/ interface to methods' verbose kwarg #34 (comment) though note we decided on a different schema, as above
  • all previous if verbose: print(<message>) statements being changed to log.<level>(<message>) messages, where the conditional on verbose is no longer required as the decorator handles the equivalent logic (& more).

Work still TODO for this PR

If I have missed anything, let me know! But at the least I still want to:

  • set the levels of calls appropriately, since I have started by setting them all to info;
  • document the configurability of the logging & the overriding verbose keyword argument in a new sub-section of the docs;
  • amend the docstrings of methods with verbose kwargs to indicate the interface with the log severity level;
  • add some testing of the emerging log levels, & of the new function & decorator.

Post-PR work

  1. With this PR, log messages go, as before, to STDOUT as pure messages i.e. no extra metadata such as datetime stamps or module names are included, however such extensions can now be trivially set up in new handlers e.g. file handlers with full detail to dedicated log files for user support purposes etc., if we wish.
  2. This PR does not add new logging calls, it simply replaces current print calls, and now the basis is in place we should add meaningful messages across the codebase at applicable levels.
  3. Improved display of objects for readability. I have added a few pretty-print calls already to do this in some cases (e.g. see pprint.pformat in netcdfread.py).

@sadielbartholomew sadielbartholomew added the enhancement New feature or request label May 7, 2020
@sadielbartholomew sadielbartholomew self-assigned this May 7, 2020
@sadielbartholomew
Copy link
Member Author

(Expecting the Mac OS Actions test jobs to fail, as there are issues in the dependency setup on master I need to sort out. Test suite does pass locally at this stage.)

@sadielbartholomew sadielbartholomew marked this pull request as draft May 7, 2020 16:05
@sadielbartholomew
Copy link
Member Author

@davidhassell: (for after the long weekend if you have started yours) I thought I'd let you see this at this nearly-done stage in case you have any comments on the implementation & approach, etc., & so you can become familiar with how the logging will work in code terms. If you want to do a formal code review, that's fine too, in which case just assign yourself.

Note: levels are being chosen leniently, because there will often
be data quality or CF-compliance issues that do not prevent
successful operations, & we don't want to spam users with these
messages unless they specify the highest log severity levels.
This is to avoid excess output from warnings and errors set up
deliberately for testing.
@davidhassell
Copy link
Contributor

Hi Sadie, I wonder if the verbose keyword should either be None or an int (rather than a bool), so that the control can be fine-tuned at the function level. I.e. verbose can be one of None, 0, 1, 2, 3, 4, 5, where None, the default, means "use the setting of cfdm.LOG_SEVERITY_LEVEL, 0 means "disable logging" and a +ve integer sets that log level. For backwards compatibility (and not documented), the old setting of False would map to 0;andTrue` could map to the most appropiate +ve int.

What do you think?

@davidhassell
Copy link
Contributor

Should we take this opportunity to rename the package level functions to lower case: ATOL, RTOL, LOG_SEVERITY_LEVEL (but not cfdm.CF)? The upper case versions of ATOL, RTOL would remain as aliases.

That said, these functions do have something in common, which the other package level functions don't have, in that they are all about the setting of global constants.

I don't mind either way - what do you think?

@sadielbartholomew
Copy link
Member Author

sadielbartholomew commented May 13, 2020

Thanks for your feedback comments @davidhassell. In response:

I wonder if the verbose keyword should either be None or an int (rather than a bool), so that the control can be fine-tuned at the function level.

Ah yes, that's a very good idea!

There were a few methods you mentioned &/or I noticed have some levelling aspect already (e.g. construct_verbose = (verbose > 1) in constructs._equals_coordinate_reference()) where I was at this point relying on the value equivalence of True & 1 (1 == True) until allowing such levels by subsuming any such kwargs (I forgot to add that to the TODO checklist), but it is definitely better as you suggest to allow full configurability for all methods having the verbose kwarg. For:

the old setting of False would map to 0; and True could map to the most appropiate +ve int.

I can change from value to identity check so True is distinguished, & False has value 0 anyway so a value comparison can manage that equivalency.

I'll implement it as you suggest in your comment.

Should we take this opportunity to rename the package level functions to lower case: ATOL, RTOL, LOG_SEVERITY_LEVEL (but not cfdm.CF)? The upper case versions of ATOL, RTOL would remain as aliases.

It would be good to do this, & I am happy to here, but maybe to avoid cluttering this PR I can do this as follow-on work? I was thinking of the cf-python Issue NCAS-CMS/cf-python#70 which would be an ideal place to do the renaming for cf-python, but best do that after the logging is in so that can be included. And best do the renaming on cfdm & cf-python together. Either way, I think I can get all that in for the next release set.

Now I am back from leave I will prioritise getting this PR done including to extend it according to your feedback, but that shouldn't be too difficult or time-consuming since the bulk of the code is there & just needs tweaking.

Also looking at my changes afresh after my break, I am thinking maybe I should create a test case (unittest.TestCase) subclass to manage setting the logging in the test classes, instead of adding in the configuration to each setUp (see 792d2fd). However, that would make it more cumbersome to change it on a per-test-module basis, & hide away the comment about how to change it for given lines. Not sure what to do there, so if you have thoughts or a preference please let me know.

This is in response to discussion yesterday on the status of
the logging in practice, where it was agreed that error cases
are handled adequately by standard exceptions but that it would
be useful to have a further informational level.

Note: the API ref docs & possibly some other aspects of the
PR NCAS-CMS#34 still need to be amended to reflect these level changes.
This will be addressed in the next commit.
This is because it now configures a mix of severity & verbosity,
so the old name may be misleading or confusing. Plus, the new
name is shorter so easier to type.
@sadielbartholomew
Copy link
Member Author

sadielbartholomew commented May 15, 2020

Reviewing aids:

Note: this includes a name change for the old
'_reset_log_severity_level' function, to the above, since (despite
being intended as private) it was no longer accurately described,
either resetting the level which is in fact a mixture of severity &
verbosity, or disabling the logging which doesn't influence the level.
The term 'emergence' covers the various levels and disable capability.
@sadielbartholomew sadielbartholomew marked this pull request as ready for review May 19, 2020 10:40
@sadielbartholomew
Copy link
Member Author

Tests added & including these the local test suite passes, both when running the relevant tests individually & as part of the full test suite, which is notable because I had to make a few tweaks mainly to the assertLogs setup for test_decorators as otherwise with naive setup one but not the other would pass (mainly relating to logger naming by __name__ which of course varies according to the origin executable).

I want to check the GH Actions suite results. The Mac OS jobs may fail due to platform-specific unrelated issues that have been cropping up and I need to look into, so just looking for an Ubuntu job pass. The Actions workflow would have triggered itself as far as I know, not sure why it isn't running the checks. I'll try a close & re-open to force the triggering.

One conflict present has been resolved, so ready to merge once the Actions test suite job passes.

@sadielbartholomew
Copy link
Member Author

All test jobs passed 🎉! It looks like the previously-observed Mac OS job issues are intermittent. I will investigate them in due course, but I'm glad they haven't cropped up here so I can be confident everything does as it should on that platform.

@davidhassell I am merging this now. Thanks for your comments. As you suggest, levels attached to certain messages may not be the most appropriate but we can easily tweak the levels of any message as we attune to the logging system & outputs. It is just a case of changing a call from, e.g, logging.info(...) to logging.detail(...) now.

I will move the noted follow-in work (see 'Post-PR work' in the opening comment) to its own Issue, but it should wait at least until the equivalent basic logging has been added to cf-python, which may be a few weeks at least due to other priorities.

@sadielbartholomew sadielbartholomew merged commit 0d07783 into NCAS-CMS:master May 19, 2020
@davidhassell
Copy link
Contributor

Great - thank you! I shall update my my fork.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

enhancement New feature or request

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Add logging to manage & configure verbose flag logic

2 participants