Logging subclass behavior removed by windows ProactorEventLoop during asyncio.run_in_executor execution

  logging, multithreading, python, python-asyncio, windows

I have built a logger system on top of the standard python Logging package and it works just fine under normal unthreaded behavior. However, when I pass one of these logger objects as an argument in an asyncio run_in_executor command (specifically working with a windows-required ProactorEventLoop, as this works as expected on linux), it seems to strip away all of the custom work I did to the logger, and uses only the base logging behavior. Doesn’t save logs to files, nor does it show them on screen with the correct formatting (or sometimes at all — I can’t pin down the verbosity behavior either). Is this known behavior and is there a workaround? So far I just have to strip all of the custom methods out of any code that gets run in the executor and live without adequate logs and this is really suboptimal.

Here is a (probably mostly but not fully) functional snippet of what I have been doing.

def initialize_logger(app_name, verbosity_stream=None, verbosity_log=None, **kwargs):

    try:
        logging.setLoggerClass(MyLogger)
        logger = logging.getLogger(app_name)
        logger.setLevel(logging.DEBUG)
        logger.propagate = False

        # Set log path location
        if sys.platform == "linux":
            log_location = f"/path/to/log/garbage/bin"
        else:
            log_location = os.path.join("C:", "why", "does", "windows", "sucksomuch", app_name)

        # Set up formatting for output and filenames
        time = datetime.strftime(datetime.now(), '%Y_%m_%d__%H_%M_%S_%f')[:-4]
        log_path = os.path.join(log_location, f"{app_name}_{time}.log")

        # create formatter and add it to the handlers
        formatter = logging.Formatter('%(asctime)st%(levelname)-8st%(user)st%(prefix)s%(message)s',
                                      '%Y-%m-%d %H:%M:%S%z')

        # Connect filehandler
        fh = logging.FileHandler(log_path, mode='w')
        fh.setLevel(verbosity_log.upper())
        fh.setFormatter(formatter)
        logger.addHandler(fh)

        # Connect streamhandler
        ch = logging.StreamHandler()
        ch.setLevel(verbosity_stream.upper())
        ch.setFormatter(formatter)
        logger.addHandler(ch)

        logger.debug(logger.handlers)
    except Exception as e:
        logger = logging.getLogger(app_name)
        logger.error("Exception while preparing logger:", exc_info=1)

    logger.verbose(f"Logger initialized with stream verbosity level "
                   + f"{verbosity_stream} and log verbosity level {verbosity_log}.")

    return logger

class MyLogger(logging.Logger):

    LEVEL_VERBOSE = 15  # between debug and info

    def __init__(self, name, level=logging.NOTSET):
        logging.addLevelName(DFLogger.LEVEL_VERBOSE, "VERBOSE")
        return super().__init__(name, level=level)

    def debug(self, *args, **kwargs):
        return super().debug(*args, **kwargs)

    def verbose(self, message, *args, prefix="", **kwargs):
        return self._log(MyLogger.LEVEL_DEBUG, message, args, **kwargs)

    def info(self, *args, **kwargs):
        return super().info(*args, **kwargs)

def callback(packet, logger):
    logger.info(f"This should print with all my logger formatting: {str(packet)}")
    return 0

if __name__ == "__main__":
    logger = initialize_logger('logger_name', verbosity_stream="DEBUG", verbosity_log="VERBOSE")
    loop = asyncio.ProactorEventLoop()
    with concurrent.futures.ProcessPoolExecutor() as pool:
        result = await loop.run_in_executor(pool, callback, {"test": "please"}, logger)

Source: Python Questions

LEAVE A COMMENT