🎨 Improving servicelib.logging_utils

[pcrespov]

What do these changes do?

Addresses some issues with servicelib.logging_utils:

• 🎨 fixes log_decorator to log only in level
• ✨ new log_exceptions context manager

Motivation

The idea of log_decorator is to log inputs/outputs of a function. Inputs are the function arguments and are logged before calling the function. Outputs are either returned values or exceptions which are logged after the call.

Let's look at this example. Assume I decorate foo to log in debug mode

@log_decorator(_logger, logging.DEBUG)
def foo(x):
   if x<0:
       raise ValueError(x)
   return 2*x

and then use it inside another function where I handle the exceptions it might raise

def safe_foo(x):
   try:
      return foo(x)
    except ValueError: 
       return foo(abs(x)

Then, when I call safe_foo(-1) what would you expect in the logs. I would expect a DEBUG trace for all foo calls. Instead I was getting something like

DEBUG Begin foo(x=-1)
ERROR foo raised ValueError
 Traceback (most recent call last):
  # ...
  raise ValueError(msg)
 ValueError: -1
DEBUG Begin foo(x=1)
DEBUG End foo(x=1) -> 2 

But, didn't I handled that error? Why the function exception is logged as ERROR if I am logging my function as DEBUG.
The issues was introduced when we introduced log_catch within `log_decorator.

Thoughts

Logging should follow very rationale and the fucntions hsould have very similar signatures to builtin logging

• Direct log

logger.info("direct log")
# or
logger.log(logging.INFO, "direct log")

• Logging exceptions with a context manager

# raises
with log_exceptions(logger, logging.INFO):
    # ...
    resp.raise_for_status()
    
# does NOT raises  (NOTE: use composition of context managers)
with suppress(Exception), log_exceptions(logger, logging.INFO):
    # ...
    resp.raise_for_status()

• Logging a "section of code"

with log_context(logger, logging.INFO, "foo and perhaps bar"):
   r = foo(1)
   if r:
      bar(r, 2) 

Composition of context managers can also be implemented using contextlib.ExitStack

Proposal

This is taking too much time and effort to get it right. I think we should move to something like loguru and even get asyncio improvement for free! On lets implement https://superfastpython.com/asyncio-logging-best-practices/

Related issue/s

• Fixes small issue with logs in ♻️Mypy: webserver #6193

How to test

cd packages/service-library
make install-dev
pytest -vv tests/test_logging_utils

[codecov]

Codecov Report

Attention: Patch coverage is 90.24390% with 4 lines in your changes missing coverage. Please review.

Project coverage is 87.8%. Comparing base (cafbf96) to head (26eba64).
Report is 463 commits behind head on master.

Files	Patch %	Lines
...es/service-library/src/servicelib/logging_utils.py	90.2%	3 Missing and 1 partial ⚠️

Additional details and impacted files

@@            Coverage Diff            @@
##           master   #6224      +/-   ##
=========================================
+ Coverage    84.5%   87.8%    +3.2%     
=========================================
  Files          10    1143    +1133     
  Lines         214   50332   +50118     
  Branches       25     780     +755     
=========================================
+ Hits          181   44222   +44041     
- Misses         23    5939    +5916     
- Partials       10     171     +161     

Flag	Coverage Δ
integrationtests	64.9% <ø> (?)
unittests	85.3% <90.2%> (+0.8%)	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

Files	Coverage Δ
...es/service-library/src/servicelib/logging_utils.py	75.7% <90.2%> (ø)

... and 1152 files with indirect coverage changes

[GitHK]

Nice, please see my question below.
FYI: I would not mind us moving towards loguru.

[sanderegg]

Thanks, I don't see where loguru say they are asyncio compatible. can you point that please?

[pcrespov]

Thanks, I don't see where loguru say they are asyncio compatible. can you point that please?

@sanderegg they seem to provide support to enqueue logs asyncronously. https://loguru.readthedocs.io/en/stable/overview.html#asynchronous-thread-safe-multiprocess-safe
I would test the impact it has compared to the builtin logger and then decide

[sanderegg]

Thanks, I don't see where loguru say they are asyncio compatible. can you point that please?

@sanderegg they seem to provide support to enqueue logs asyncronously. https://loguru.readthedocs.io/en/stable/overview.html#asynchronous-thread-safe-multiprocess-safe I would test the impact it has compared to the builtin logger and then decide

@pcrespov then please also check with this:
https://superfastpython.com/asyncio-logging-best-practices/

[matusdrobuliak66]

Thanks

[sonarqubecloud]

Quality Gate passed

Issues
0 New issues
0 Accepted issues

Measures
0 Security Hotspots
0.0% Coverage on New Code
0.0% Duplication on New Code

See analysis details on SonarCloud