Search code examples
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 was 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 pythoon 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)