CODEWITHSUNDEEP
pythonloggingsqlalchemywarningspython-logging
Stev_k
Stev_k

Reputation: 2126

Avoid formatting issues when warnings.captureWarnings(True) is set

I have created a log handler which logs to a database table, and I wanted to also capture warnings issued by the program into a different table, so used warnings.captureWarnings(True)

I had some issues with the message formatting in the py.warnings logger - the message always showed as %s. I triangulated it to this line (logger.warning("%s", s))in the logging library code which implements warning emission when captureWarnings is True.

When it is replaced by logger.warning(s) the message appears as expected. I presume therefore that it's some sort of formatting issue, but I can't figure out what.

I also saw BPO-46557 which actually implements this behaviour, seemingly for unrelated reasons (but only for Python3.11+, I am on 3.10).

My DB log handler code is below. Is there any way of fixing this without upgrading to Python 3.11 - seems like it should be unnecessary.

Code called before main code is run:

logging.captureWarnings(True)
warnings_logger = logging.getLogger("py.warnings")
warnings_logger.setLevel(logging.DEBUG)
from db_logging import SQLAlchemyWarningHandler
handler = SQLAlchemyWarningHandler()
warnings_logger.addHandler(handler)

handler and LogRecord code (db_logging.py). However I don't believe it's anything in this code as I get: <LogRecord: py.warnings, 30, /usr/lib/python3.10/warnings.py, 110, "%s"> when I print out the record before it's emitted

from database import database

# lib imports
from sqlalchemy import Column
from sqlalchemy.types import DateTime, Integer, String
from sqlalchemy.sql import func
from sqlalchemy.ext.declarative import declarative_base, declared_attr
from sqlalchemy.orm import sessionmaker
from sqlalchemy import DDL, event

# stdlib imports
import logging
import traceback
import sys

class Base(object):
    @declared_attr
    def __tablename__(cls):
        return cls.__name__.lower()

    __table_args__ = {"schema": "logs"}
    id = Column(Integer, primary_key=True) # auto incrementing
    logger = Column(String) # the name of the logger. (e.g. myapp.views)
    level = Column(String) # info, debug, or error?
    trace = Column(String) # the full traceback printout
    msg = Column(String) # any custom log you may have included
    created_at = Column(DateTime, default=func.now()) # the current timestamp
    source_loc = Column(String)

    def __init__(self, logger=None, level=None, trace=None, msg=None, source_loc=None):
        self.logger = logger
        self.level = level
        self.trace = trace
        self.msg = msg
        self.source_loc = source_loc

    def __unicode__(self):
        return self.__repr__()

    def __repr__(self):
        return "<Log: %s - %s>" % (self.created_at.strftime('%m/%d/%Y-%H:%M:%S'), self.msg[:50])



Base = declarative_base(cls=Base)
event.listen(Base.metadata, 'before_create', DDL("CREATE SCHEMA IF NOT EXISTS logs"))

class Logs(Base):
    "log class which writes all main db logs"
    pass

class WarningLogs(Base):
    "seperate log class for deprecation warnings which writes to a different db table"
    pass

class SQLAlchemyHandler(logging.Handler):
    "A very basic logger that commits a LogRecord to the SQL Db"
    def __init__(self):
        logging.Handler.__init__(self)
        Base.metadata.create_all(database.engine)
        Session = sessionmaker(bind=database.engine)
        self.session = Session()
        self.log_class = getattr(sys.modules[__name__], 'Logs')

    def emit(self, record):
        trace = None
        exc = record.__dict__['exc_info']
        if exc:
            trace = traceback.format_exc()
        log = self.log_class(
            logger=record.__dict__['name'],
            level=record.__dict__['levelname'],
            trace=trace,
            msg=record.__dict__['msg'],
            source_loc=f"{record.__dict__['pathname']}:{record.__dict__['lineno']}")
        self.session.add(log)
        self.session.commit()

    class SQLAlchemyWarningHandler(SQLAlchemyHandler):
    "Extends SQLAlchemyHandler to use WarningLog objects, which use a different table"
    def __init__(self,  **kwargs):
        super().__init__(**kwargs)
        self.log_class = getattr(sys.modules[__name__], 'WarningLogs')

Upvotes: 1

Views: 152

Answers (1)

blues
blues

Reputation: 5185

It looks like you are reading the msg attribute on the LogRecord and storing that, which you are not supposed to do. (As per documentation, specifically what it says about the msg and message attributes.) It contains a possibly unformatted string missing the user supplied arguments. In the case of the warnings capture the whole message is supplied as an argument as you have already found.

Replace your line: msg=record.__dict__['msg'] with msg=record.getMessage() and it will work as intended.

Upvotes: 1

Related Questions