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')
