NCAS-CMS / NCAS-CMS/cf-python

Interaction between both forms of verbosity decorator

Open
#164 0 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Dominant language
Python
Stars
150
Forks
23
Avg merge
1d 11h
Merged PRs (30d)
2

Description

There is unintended premature resetting of the effective log level to the global one when both the _manage_log_level_via_verbosity and _manage_log_level_via_verbose_attr decorator are on the call stack (reason outlined below in case it might be useful to know).

As a result, unless there is manual management to change the log level back to the correct level after one such decorator is called and terminates as implemented as a workaround as part of 830a64b5b19655d1eb62c43daf28b5811b7ab0a0 some log calls at a higher verbosity level will be:

  • hidden when they should be emerging; or
  • output when they shouldn't be;

depending on whether the specified verbosity or global one is higher.

At the moment this is not vital to solve as the only place both decorators could come into play is the aggregate module, and in 830a64b5b19655d1eb62c43daf28b5811b7ab0a0 I put in the temporary and rather hacky fix, so nothing is behaving incorrectly as a result. But going forward this would be good to manage robustly so we can pepper the codebase with those decorators as we please without needing to worry about interactions between the two. See below if interested for the way to fix.

Quick explanation

Each verbosity decorator individually tracks its own calls so that it will only reset to the global log level once the outermost function that is decorated with it completes, by our design. Namely (taking ..._via_verbose_attr as an example) it increments a calls[0] at the start of the decorator wrapper:

https://github.com/NCAS-CMS/cf-python/blob/830a64b5b19655d1eb62c43daf28b5811b7ab0a0/cf/decorators.py#L103

decrements it at the end, even if it errors rather than exits cleanly:

https://github.com/NCAS-CMS/cf-python/blob/830a64b5b19655d1eb62c43daf28b5811b7ab0a0/cf/decorators.py#L150

and then checks it is equal to zero, only resetting in that case:

https://github.com/NCAS-CMS/cf-python/blob/830a64b5b19655d1eb62c43daf28b5811b7ab0a0/cf/decorators.py#L156-L163

But each decorator only tracks when it is itself called. If one decorator is called indirectly during the call of the other, and completes by hitting calls[0], it will reset the log level to global level, when the other decorator called first is unlikely to be finished (have non-zero N for calls[N]).

Way to fix

All that should be required is to create, and instead use, some form of combined count tracking calls of both decorators, such that the resetting only occurs once both are finished. Though there are likely to be complications that need thinking through. It might not be as simple as it sounds (for one, the logic for each decorator is defined in different codebases)...

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start in cf/decorators.py at the linked wrapper and reset logic, then trace how the two decorators interact when used from the aggregate module. The fix is complete when log-level resetting waits for both decorators to finish, including error paths, without requiring the existing manual workaround.

Written by the indexing model from the issue text.

Assessment

Tech stack
python
Domain
tooling
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.