txaio.aio logging bug example

txaio-test.py

'''
To run:
$ python3.7 -m venv txaio-test
$ . txaio-test/bin/activate
(txaio-test) $ pip install txaio
Collecting txaio
  Downloading https://files.pythonhosted.org/packages/4f/82/0cd8d81d57e55a598cd4cef10c6e971dbcaf437e4f138dc1624cf7c1388e/txaio-20.4.1-py2.py3-none-any.whl
Installing collected packages: txaio
Successfully installed txaio-20.4.1
(txaio-test) $ python txaio-test.py
'''

import logging
import txaio

txaio.use_asyncio()
log = txaio.make_logger()

print("A logger's log level can't be changed after txaio.start_logging() is called. "
      "If you start in info mode, you can't change to debug. "
      "So if framework code calls start_logging('info') for you, you can't change it "
      "to 'debug' later. ")
# txaio.start_logging(level='debug')
txaio.start_logging()

print("By default, the log level is 'info'")
print("log.debug is", log.debug)
log.debug("Test debug") # doesn't log
log.info("Test info")   # logs
log.warn("Test warn")   # logs

print("Set the global log level to 'warn'")
txaio.set_global_log_level('warn')

print("log.debug is", log.debug)
log.debug("Test debug") # doesn't log
log.info("Test info")   # doesn't log
log.warn("Test warn")   # logs


print("Set the global log level to 'debug'")
txaio.set_global_log_level('debug')

print("log.debug is", log.debug)
log.debug("Test debug") # doesn't log
log.info("Test info")   # logs
log.warn("Test warn")   # logs

print("txaio.set_global_log_level calls _set_log_level, but _set_log_level "
      "doesn't call setLogLevel on log._logger.")
print("log._logger.isEnabledFor(logging.DEBUG)", log._logger.isEnabledFor(logging.DEBUG)) # False
# Directly setting the log level on the embedded logger solves the problem
# log._logger.setLevel(logging.DEBUG)
# print("log.debug is", log.debug)
# log.debug("Debug")

from txaio.aio import log_levels, _no_op, _log, functools

level_to_stdlib = {
    'critical': logging.CRITICAL,
    'error': logging.ERROR,
    'warn': logging.WARNING,
    'info': logging.INFO,
    'debug': logging.DEBUG,
    'trace': logging.DEBUG,
}

print("One fix is to update _set_log_level so that it calls _logger.setLevel")
def patched_set_log_level(self, level):
    target_level = log_levels.index(level)
    # this binds either _log or _no_op above to this instance,
    # depending on the desired level.
    for (idx, name) in enumerate(log_levels):
        if idx <= target_level:
            log_method = functools.partial(_log, self, name)
        else:
            log_method = _no_op
        setattr(self, name, log_method)
    self._log_level = level
    self._logger.setLevel(level_to_stdlib[level])

# bind patched_set_log_level to our log instance
log._set_log_level = patched_set_log_level.__get__(log)

print("Not that it's patched, try setting the global log level to 'debug' again")
txaio.set_global_log_level('debug')
print("log.debug is", log.debug)
print("log._logger.isEnabledFor(logging.DEBUG)", log._logger.isEnabledFor(logging.DEBUG)) # True
log.debug("Test debug") # logs
log.info("Test info")   # logs
log.warn("Test warn")   # logs