python-logfmter
python-logfmter copied to clipboard
jteppinette
Support `|` separator for readability
I didn't find any real specification of logfmt. But https://www.brandur.org/logfmt seems to be the origin. It defines the following valid format (and links back to this nice project):
info | Stopping all fetchers module=kafka.consumer.ConsumerFetcherManager
info | Performing log compaction module=kafka.compacter.LogCompactionManager
info | Performing garbage collection module=kafka.cleaner.GarbageCollectionManager
info | Starting all fetchers module=kafka.consumer.ConsumerFetcherManager
So we have msg, when/time and at separeted from the parameters.
at (level) also has a different length.
For example, we need:
2023-10-27T08:22:57.275138+00:00 INFO | modified group | id="..." old={..} new={..} module=app.main.loop pid=13825 request_id=31f863092ade
2023-10-27T08:22:58.123454+00:00 DEBUG | received request | headers={..} method='POST' json={..} module=app.net.http pid=13825 request_id=b0ca915ec433
2023-10-27T08:22:58.351345+00:00 TRACE | cache hit | hash="..." ttl=... module=app.backend.cache pid=13825 request_id=b0ca915ec433
so after level is a "\t" so that the length is expanded to 8 chars making INFO and DEBUG look like the same length.
→ it should be configurable which args should be treated as non-keyword-args and being | + \t separated.
Current way to achieve it more or less:
class Formatter(Logfmter):
def __init__(self, keys, mapping, **kwargs):
super().__init__(keys=keys, mapping=mapping, datefmt="%Y-%m-%d %H:%M:%S", **kwargs)
def format(self, record):
when = self.formatTime(record, "%z")
return f"{when} {record.levelname}\t| {record.getMessage()}\t| " + super().format(record)
I think it might be nicer If Logfmter would provide a logging.Filter as alternative way to use.
Then one can setup the log format like:
import logging
from logfmter import Logfmter
class LogfmterFilter(logging.Filter):
def __init__(self, key, *args, **kwargs):
self.key = key
self.logfmter = Logfmter(*args, **kwargs)
def filter(self, record):
message = record.msg
try:
# make sure, logfmt doesn't log the msg
record.msg = record.msg.copy() if isinstance(record.msg, dict) else {}
record.msg.pop('msg', None)
setattr(record, self.key, self.logfmter.format(record))
finally:
record.msg = message.get('msg') if isinstance(message, dict) else message
return True
class SyslogPrefix(logging.Filter):
def filter(self, record):
record.request_id = '-'
record.syslog_prio = '<7>' # TODO: map level to syslog level
return True
fmt = (
"{syslog_prio}"
"<green>{asctime}</green> | "
"{levelname:>7} | "
'{request_id} | '
"{module}.{funcName}:{lineno} | "
"{name} | "
"{message} \t| "
"{logfmt}"
)
formatter = logging.Formatter(fmt, style="{", datefmt="%Y-%m-%d %H:%M:%S.%f %z")
handler = logging.StreamHandler()
handler.setFormatter(formatter)
handler.addFilter(LogfmterFilter(
"logfmt",
keys=['lineno', 'pid', 'func'],
mapping={'pid': 'process', 'lineno': 'lineno', 'func': 'funcName'}
))
handler.addFilter(SyslogPrefix())
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
logger.addHandler(handler)
logger.info("Hello my %s", "world", extra={'hello': 'world', 'foo': 'bar', 'bar': 'Baz'})
logger.info({'msg': 'Hello my world', 'hello': 'world', 'foo': 'bar', 'bar': 'Baz'})
This gives:
<7><green>2025-08-29 10:51:05.%f +0200</green> | INFO | - | X.<module>:55 | __main__ | Hello my world | lineno=55 pid=867814 func=<module> hello=world foo=bar bar=Baz
<7><green>2025-08-29 10:51:05.%f +0200</green> | INFO | - | X.<module>:56 | __main__ | Hello my world | lineno=56 pid=867814 func=<module> hello=world foo=bar bar=Baz
We would need some flag in Logfmter that msg should not be logged, to realize this without the workaround.
The filer approach is not good, because adding multiple filters make the order of execution important. I wrote a formatter which combines both ways of formatting resulting in:
<7><green>2025-09-08T13:04:49.801 +0200</green> | INFO | - | formatter2.<module>:110 | __main__ | Hello my world | pid=46671 hello=world foo=bar bar=Ba
<7><green>2025-09-08T13:04:49.801 +0200</green> | INFO | - | formatter2.<module>:111 | __main__ | Hello my world | pid=46671 hello=world foo=bar bar=Baz
import logging
import time
import traceback
from logfmter import Logfmter
class StructuredFormatter(logging.Formatter):
default_time_format = '%Y-%m-%dT%H:%M:%S.{msecs:03.0f} %z'
def __init__(
self,
fmt=None,
datefmt=None,
*,
defaults=None,
data_fields=None,
data_mapping=None,
data_defaults=None,
data_ignored_keys=None,
add_full_tracebacks=True,
with_date_prefix=False,
key='logfmt',
):
# fmt = fmt or '[{request_id:>10}] {module}.{funcName}:{lineno} {message}\t| {logfmt}'
fmt = fmt or '[{request_id:>10}] {message}\t| {logfmt}'
if with_date_prefix:
fmt = f'{{asctime}} {{levelname:>8}} {fmt}'
style = '{'
self.key = key
self.add_full_tracebacks = add_full_tracebacks
self.logfmter = Logfmter(
keys=data_fields or ['pid', 'logname', 'func'],
mapping=data_mapping or {'at': 'levelname', 'pid': 'process', 'time': 'asctime', 'logname': 'name'},
defaults=data_defaults or {'func': '{module}.{funcName}:{lineno}'},
ignore_keys=data_ignored_keys or ['msg', 'request_id'], # 'stack_info', 'exc_info'
datefmt=datefmt or self.default_time_format,
)
super().__init__(fmt=fmt, datefmt=datefmt, defaults=defaults or {'request_id': '-', key: ''}, style=style)
def formatMessage(self, record):
setattr(record, self.key, self.logfmter.format(record))
return super().formatMessage(record)
def format(self, record):
msg = record.msg
if isinstance(record.msg, dict):
record.msg = msg.get('msg')
for key, val in msg.items():
if key != 'msg':
setattr(record, key, val)
try:
record.message = record.getMessage()
if self.usesTime():
record.asctime = self.formatTime(record, self.datefmt)
s = self.formatMessage(record).rstrip('\n')
finally:
record.msg = msg
if not self.add_full_tracebacks:
return s
if record.exc_info and not record.exc_text:
record.exc_text = ''.join(traceback.format_exception(*record.exc_info)).rstrip('\n')
if record.exc_text:
s = f'{s}\n{record.exc_text}'
if record.stack_info:
s = f'{s}\n{self.formatStack(record.stack_info)}'
return s
def formatTime(self, record, datefmt=None):
ct = self.converter(record.created)
datefmt = datefmt or self.default_time_format
return time.strftime(datefmt, ct).format(msecs=record.msecs)
class SyslogPrefix(logging.Filter):
def filter(self, record):
record.request_id = '-'
record.syslog_prio = '<7>' # TODO: map level to syslog level
return True
fmt = (
"{syslog_prio}"
"<green>{asctime}</green> | "
"{levelname:>8} | "
'{request_id:>10} | '
"{module}.{funcName}:{lineno} | "
"{name} | "
"{message} \t| "
"{logfmt}"
)
handler = logging.StreamHandler()
handler.addFilter(SyslogPrefix())
formatter = StructuredFormatter(
fmt,
data_fields=['pid'],
data_mapping={'pid': 'process'},
data_ignored_keys=['msg', 'request_id', 'func', 'syslog_prio'],
)
handler.setFormatter(formatter)
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
logger.addHandler(handler)
logger.info("Hello my %s", "world", extra={'hello': 'world', 'foo': 'bar', 'bar': 'Ba'})
logger.info({'msg': 'Hello my world', 'hello': 'world', 'foo': 'bar', 'bar': 'Baz'})