Accept a Callable for the serialize argument when adding a sink

[gjeusel]

Hello Delgan ! Love your library !

I was wondering what you would think about accepting a Callable for the serialize parameter in logger.add method ?

This would ease customization of the jsonified records. And I'm thinking about ELK stack usage for example.

I managed to achieve this purpose by overwriting the Handler._serialize_record staticmethod:

import sys

import flask
import loguru
import orjson
import pytz
import stackprinter
from flask_login import current_user


def _serialize_record_elk(text, record):
    # Format timestamp for Elasticache
    timestamp = record["time"].astimezone(pytz.utc)
    timestamp = timestamp.strftime("%Y-%m-%dT%H:%M:%S.{:03d}Z").format(
        timestamp.microsecond // 1000
    )

    # Current User's email of flask app
    user_email = getattr(current_user, "email", "anonymous")

    # Can add some config variable of interest from the flask app
    env = None
    if flask.has_request_context():
        if hasattr(flask.current_app, "config"):
            env = flask.current_app.config["ENV"]

    serializable = {
        # Base fields
        "@timestamp": timestamp,  # Elasticache index overwrite
        "icon": record["level"].icon,
        "log": {"level": record["level"].name},
        "name": record["name"],
        "message": record["message"],
        # App related:
        "user": {"email": user_email},
        "env": env,
        # Extra
        "extra": record["extra"],
        "misc": {
            "elapsed": {
                "repr": record["elapsed"],
                "seconds": record["elapsed"].total_seconds(),
            },
            "file": {"name": record["file"].name, "path": record["file"].path},
            "function": record["function"],
            "level": {
                "icon": record["level"].icon,
                "name": record["level"].name,
                "no": record["level"].no,
            },
            "line": record["line"],
            "module": record["module"],
            "process": {"id": record["process"].id, "name": record["process"].name},
            "thread": {"id": record["thread"].id, "name": record["thread"].name},
        },
    }
    if record["exception"]:
        exc_class = record["exception"].type
        serializable = {
            **serializable,
            "exc": {
                "type": f"{exc_class.__module__}.{exc_class.__name__}",
                "value": record["exception"].value,
                "traceback": stackprinter.format(record["exception"], show_vals="line"),
            },
        }

    return orjson.dumps(serializable, default=str).decode("utf-8") + "\n"


loguru._handler.Handler._serialize_record = staticmethod(_serialize_record_elk)

loguru.logger.add(sink=sys.stdout, serialize=True, format="{message}")

Still, that would be a nice to have in official doc IMO ! 😉

[Delgan]

Hi @gjeusel, glad you like loguru. 😁

Accepting a callable to serialize is something that had crossed my mind in the past and was also suggested in #203, but I don't think it's actually needed.

The thing is that there is already two ways to customize the serialized output: use a custom sink or a custom format function. I also think patch() could be useful for your use case.

For example, you can convert your _serialize_record_elk() to an actual sink like that and the result will be perfectly equivalent even if serialize=False:

def _serialize_record_elk(text):
    record = text.record
    ...
    print(orjson.dumps(serializable, default=str).decode("utf-8"))

logger.add(_serialize_record_elk, serialize=False, format="{message}")

If you need to send structured logs to a file (or any kind of sink in general), a similar trick can be accomplished by using a custom format:

def _serialize_record_elk(record):
    ...
    return orjson.dumps(serializable, default=str).decode("utf-8") + "\n"

logger.add("file.log", serialize=False, format=_serialize_record_elk)

# Edit: above snippet was incorrect
def _serialize_record_elk(record):
    ...
    record["extra"]["serialized"] =  orjson.dumps(serializable, default=str).decode("utf-8")
    return "{extra[serialized]}\n"

logger.add("file.log", serialize=False, format=_serialize_record_elk)

Finally, if there is just a few attributes that you would like to be added to the logged message, an alternative is to use patch() like that:

def patcher(record):
    timestamp = record["time"].astimezone(pytz.utc)
    timestamp = timestamp.strftime("%Y-%m-%dT%H:%M:%S.{:03d}Z").format(
        timestamp.microsecond // 1000
    )
    record["@timestamp"] = timestamp

logger.configure(patcher=patcher)
logger.add(sys.stdout, serialize=True, format="{message}")

I prefer that the serialize parameter remains a basic boolean, and that if the user needs to customize the structure of his messages, he can do so using sink or format.

[gjeusel]

Ahah perfect !
I knew I would get better alternative asking it directly there !

Thx !

[Delgan]

No problem. 👍

I will add a recipe about the possible alternatives in the documentation.

[gjeusel]

Hello, me again!
I'm struggling with your second proposal, making use of a callable format.

import sys
import orjson
from loguru import logger


def _serialize_record_elk(record):
    serializable = {
        "log": {"level": record["level"].name}
    }
    return orjson.dumps(serializable, default=str).decode("utf-8") + "\n"


logger.add(sys.stdout, colorize=False, serialize=False, format=_serialize_record_elk)

logger.info("YO")

2020-06-06 13:05:29.839 | INFO     | __main__:<module>:17 - YO
--- Logging error in Loguru Handler #1 ---
Record was: {'elapsed': datetime.timedelta(microseconds=6336), 'exception': None, 'extra': {}, 'file': (name='testlog.py', path='/tmp/testlog.py'), 'function': '<module>', 'level': (name='INFO', no=20, icon='ℹ️'), 'line': 17, 'message': 'YO', 'module': 'testlog', 'name': '__main__', 'process': (id=64358, name='MainProcess'), 'thread': (id=4436309440, name='MainThread'), 'time': datetime(2020, 6, 6, 13, 5, 29, 839045, tzinfo=datetime.timezone(datetime.timedelta(seconds=7200), 'CEST'))}
Traceback (most recent call last):
  File "/Users/jd5584/src/loguru/loguru/_handler.py", line 131, in emit
    formatted = precomputed_format.format_map(formatter_record)
KeyError: '"log"'
--- End of logging error ---

It seems it still tries to colorize the jsonified record, even asking explicitly not to ?

[Delgan]

@gjeusel Oh yeah, sorry, I'm dumb. >.<

The format function should not create the log message by itself. It should not return a already formatted message. Instead, it should return a string which later will be used to actually create the logged message. The function should be used as a way to dynamically create a static format string.

Here is what I mean:

# OK
logger.add(sys.stderr, format="{level} {message}")

# OK
logger.add(sys.stderr, format=lambda _: "{level} {message}\n")

# NOK
logger.add(sys.stderr, format=lambda record: "{} {}\n".format(record["level"], record["message"])

The string returned by the format function is used to create the log message by calling returned_string.format(**record).

It's a bit counter-intuitive (hence my mistake), but it's necessary to allow the use of colors dynamically. The "idiomatic" workaround is to add the generated message to the extra dict and use it in the dynamic format returned:

def _serialize_record_elk(record):
    ...
    record["extra"]["serialized"] = orjson.dumps(serializable, default=str).decode("utf-8")
    return "{extra[serialized]}\n"

logger.add(sys.stdout, colorize=False, serialize=False, format=_serialize_record_elk)

Again, it's also possible to patch() the logger with _serialize_record_elk() and use format=lambda _: "{extra[serialized]}\n" directly. It has the advantage of calling the function just once if you want to use it in multiple sinks.

[Delgan]

I added a small recipe to the documentation: Serializing log messages using a custom function.