customizationpython-3.8python-loggingpython-3.11

Python 3.11 (and 3.12) broke custom logging level


i have this custom logger that extend the classic levles to our organization needs

import logging
from config import cfg
from json import dumps
from pydash import map_
import pathlib
import re


class CustomFormatter(logging.Formatter):    
    logging.INPUT = logging.DEBUG + 1
    logging.OUTPUT = logging.DEBUG  + 2
    logging.MIDDLEWARE = logging.INFO + 1
    logging.API = logging.INFO + 2
    logging.DOMAIN = logging.INFO + 3 
    logging.REPOSITORY = logging.INFO + 4
    logging.CHECK = logging.INFO + 5
    logging.SETUP = logging.INFO + 6
    logging.START = logging.INFO + 7
    logging.addLevelName(logging.INPUT, "INPUT")
    logging.addLevelName(logging.OUTPUT, "OUTPUT")
    logging.addLevelName(logging.MIDDLEWARE, "MIDDLEWARE")
    logging.addLevelName(logging.API, "API")
    logging.addLevelName(logging.DOMAIN, "DOMAIN")
    logging.addLevelName(logging.REPOSITORY, "REPOSITORY")
    logging.addLevelName(logging.CHECK, "CHECK")
    logging.addLevelName(logging.START, "START")
    logging.addLevelName(logging.SETUP, "SETUP")
    grey = "\x1b[38;20m"
    green= "\033[92m"
    yellow = "\x1b[33;20m"
    red = "\x1b[31;20m"
    blue = "\u001b[36m"
    bold_red = "\x1b[31;1m"
    purple = "\x1b[1;35m"
    yellow_bold= "\033[1;33m"
    blue_bold = "\033[1;34m"
    green_bold = "\033[1;32m"
    cyan_bold = "\033[1;36m" 
    reset = "\x1b[0m"
    italic= "\x1b[3m"
    format = "%(asctime)s %(levelname)s: §-§%(pathname)s§-§ | %(funcName)s()" + reset + "\n%(message)s\n"
    extended_format = format +italic +"[ %(pathname)s:%(lineno)d ]\n"
    start_format =  "%(message)s"

    FORMATS = {
        logging.DEBUG: grey+ "⚪  " + format + reset, #10
        logging.INPUT: purple + "🔻\n " + format + reset, #11
        logging.OUTPUT: purple + format + "🔺  \n" + reset, #12
        logging.INFO: blue+ "ℹ️  " + extended_format + reset, #20
        logging.MIDDLEWARE: yellow_bold + "🔑  " + extended_format + reset, #21
        logging.API: green_bold + "📤  " + extended_format + reset, #22
        logging.DOMAIN: cyan_bold + "🛠️  " + extended_format + reset, #23
        logging.REPOSITORY: blue_bold + "📁  " + extended_format + reset, #24
        logging.CHECK: green + "✅  " + extended_format + reset, #25
        logging.START:italic + green_bold + "🚀  "  + start_format + reset, #26
        logging.SETUP:italic + cyan_bold + "⚙️  "  + start_format + reset, #26
        logging.WARNING: yellow + "🟡  " + extended_format + reset, #30
        logging.ERROR: red + "❌  " + extended_format + reset, #40
        logging.CRITICAL: bold_red + "⛔  " + extended_format + reset, #50
    }
    
    def format(self, record):
        log_fmt = self.FORMATS.get(record.levelno)
        formatter = logging.Formatter(log_fmt, datefmt="%Y-%m-%dT%H:%M:%S.%fZ.00Z")
        if (record.levelno in [logging.START, logging.SETUP]):
            return formatter.format(record)
        formatted_record = re.sub(f"{str(pathlib.Path().resolve())}/".replace('\\','/'), '',  formatter.format(record) )

        return re.sub("(§-§.*§-§)", format_path(re.search('(§-§.*§-§)'.replace('\\', '/'), formatted_record).group(0)), formatted_record ).replace("§-§","") 
    
level= cfg['logging']['level']
logger = logging.getLogger('waitress')
logger.check = lambda msg, *args: logger._log(logging.CHECK, msg, args)
logger.input = lambda msg, *args: logger._log(logging.INPUT, msg, args)
logger.output = lambda msg, *args: logger._log(logging.OUTPUT, msg, args)
logger.middleware = lambda msg, *args: logger._log(logging.MIDDLEWARE, msg, args)
logger.api = lambda msg, *args: logger._log(logging.API, msg, args)
logger.domain = lambda msg, *args: logger._log(logging.DOMAIN, msg, args)
logger.repository = lambda msg, *args: logger._log(logging.REPOSITORY, msg, args)
logger.start = lambda msg, *args: logger._log(logging.START, msg, args)
logger.setup = lambda msg, *args: logger._log(logging.SETUP, msg, args)
logger.setLevel(level)
ch = logging.StreamHandler()

ch.setLevel(level)
ch.setFormatter(CustomFormatter())

logger.addHandler(ch)

def stringify(obj: dict)-> str:
    return dumps(obj, separators=(',',':'), indent=2)

def format_path(path):
    parts = re.sub(f"{str(pathlib.Path().resolve())}\\".replace('\\','/'), '', str(path.replace('\\', '/'))).split('/')
    to_return = f"{' | '.join(map_(parts, lambda part, i: part.upper() if(i < len(parts) -1) else part.lower()))} "
    return to_return

with python 3.8 i could see that the variables like pathname were relate to the file where the logger was called. But with python 3.11 i always get the logging file and the lambda function as "caller".

This is happening only with the custom levels, so I'm guessing is related to the fact that I'm using a lambda function to call the ._logg( *** ) method But I can't understand why it worked on python 3.8 and why it stopped in python 3.11 And most importantly, since i found it extrimely useful, I would like to find a way to make the logging format as before, so it tells me where the loggger was called

Thanks in advance !

When I wrote it I was using python 3.8, and if i called in a file like api/user/init.py at row 12 inside the get_user function something like this
logger.check('here')

the console would have shown the log "here" with this format

✅ 2023-09-05T12:02:31.%fZ.00Z CHECK: API | USERS | init.py | get_user() here [ api/users/init.py:12 ]

but now with python 11 and 12 is printing

✅ 2023-09-05T12:02:31.%fZ.00Z CHECK: utils | logger | init.py | lambda here [ utils/loggers/init.py:73 ]


Solution

  • It turns out is all about the stack level set in the configuration, while in Python 3.8 it is irrelevant; from 3.11 you have to set the stack level at 2, like this:

    logger.check = lambda msg, *args: logger._log(logging.CHECK, msg, args, stacklevel=2)
    

    to be 100% sure that it runs either way, I used the sys library to get the Python version and then set a variable to use like that:

    import sys
    
    # Get the major and minor version of Python
    major_version = sys.version_info.major
    minor_version = sys.version_info.minor
    ...
    stackLevelPerPyVersion = 2 if (major_version, minor_version) >= (3, 9) else 1
    logger.input = lambda msg, *args: logger._log(logging.INPUT, msg, args, stacklevel=stackLevelPerPyVersion)