Adding lazy logging along critical path

[MattCatz]

Description

f-strings are evaluated before passing them down to the logging functions (even if they are not used). By using boring (and IMO harder to read) %s or %r we can delay or elude that work depending on the logging settings.

With debug level logging disabled, this won't necessarily save a noticeable amount of run time on one individual run but will save CPU cycles none the less.

This also does not change all the instances of passing f-strings to logging functions. My goal was only to change the ones that would have the biggest impact (i.e. evaluating f"read: {buf!r}" every read even with debug logging disabled)

Type of change

Please delete options that are not relevant.

• [x] New feature (non-breaking change which adds functionality)

How Has This Been Tested?

I've run a handful of scripts with and without logging enabled and everything seems to be working the same. I've used py-spy to approximate that there is less work happening with debugging disabled.

Checklist:

• [ ] My code follows the style guidelines of this project (no GitHub actions complaints! run make lint before committing!)
• [x] I have commented my code, pydocstyle and darglint are happy, docstrings are in google docstring format, and all docstrings include a summary, args, returns and raises fields (even if N/A)
• [x] I have added tests that prove my fix is effective or that my feature works, if adding "functional" tests please note if there are any considerations for the vrnetlab setup
• [x] New and existing unit tests pass locally with my changes

[carlmontanari]

hey @MattCatz dope, sounds smart to me :D ill try to take a peak at why the tests failed this weekend if ya dont beat me to it... guessing its cuz I have some wonky stuff in there. then we can get it merged! thanks a bunch!

[MattCatz]

(truthfully I did not run the unit tests because I wasn't aware of them lol)

I believe it's a bug in the testcase. It checks log_record.msg which is the un-evaluated log message. Pytest and the official docs give different info but I believe it should be something like:

# Official docs
assert "read: b'read_data'" == log_record.message

# Pytest docs
assert "read: b'read_data'" == log_record.text

https://docs.pytest.org/en/7.1.x/how-to/logging.html

https://docs.python.org/3/library/logging.html#logging.LogRecord

[carlmontanari]

boom LGTM! thanks a bunch, this is a cool improvement!