Support `|` separator for readability

[spaceone]

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.

[spaceone]

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)

[spaceone]

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

[spaceone]

We would need some flag in Logfmter that msg should not be logged, to realize this without the workaround.

[spaceone]

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