Serialization does not work when using ZMQ as handler

[nerdfunk-net]

I am trying to use zeromq as handler to send my logs to another device. The code works, but the serialization does not (only for loglevel info). Here is the code to send the logs:

import sys
import zmq
import json
from loguru import logger
from zmq.log.handlers import PUBHandler

def serialize(record):
    subset = {"timestamp": record["time"].timestamp(), "message": record["message"]}
    return json.dumps(subset)

def formatter(record):
    # Note this function returns the string to be formatted, not the actual message to be logged
    record["extra"]["serialized"] = serialize(record)
    return "{extra[serialized]}\n"

loglevel = 'DEBUG'

# zeromq
protocol = 'tcp'
host = '127.0.0.1'
port = 12345

# remove loggers
logger.remove()

# zeromq
context = zmq.Context()
socket = zmq.Context().socket(zmq.PUB)
socket.connect(f'{protocol}://{host}:{port}')
zmq_handler = PUBHandler(socket)

logger.add(sys.stderr, serialize=False, level=loglevel, format=formatter)
logger.add(zmq_handler, serialize=False, level=loglevel, format=formatter)

logger.debug('debug')
logger.info('info')
logger.error('error')
logger.critical('critical')

And this is the code to receive the logs (quick and dirty receiver to clarify the problem):

import zmq

zmq_protocol = 'tcp'
zmq_host = '127.0.0.1'
zmq_port = '12345'

zmq_bind = f'{zmq_protocol}://{zmq_host}:{zmq_port}'
socket = zmq.Context().socket(zmq.SUB)
socket.bind(zmq_bind)
socket.subscribe("")

while True:
    _, message = socket.recv_multipart()
    print(message)

The output looks like

b'DEBUG loguru_zmq_send.py:36 - {"timestamp": 1705911859.062605, "message": "debug"}\n\n'
b'{"timestamp": 1705911859.062999, "message": "info"}\n\n'
b'ERROR loguru_zmq_send.py:38 - {"timestamp": 1705911859.063216, "message": "error"}\n - None\n'
b'CRITICAL loguru_zmq_send.py:39 - {"timestamp": 1705911859.063384, "message": "critical"}\n\n'

As you can see the serialization works but only for the info log. Interestingly the sys.stdout handler works as expected.

{"timestamp": 1705911859.062605, "message": "debug"}
{"timestamp": 1705911859.062999, "message": "info"}
{"timestamp": 1705911859.063216, "message": "error"}
{"timestamp": 1705911859.063384, "message": "critical"}

What am I doing wrong? Or is this a bug? I did not find a solution in the web...

I am using python 3.11, zmq 25.1.2 and loguru 0.7.2

Regards Marc

[Delgan]

Curiously, the PubHandler of ZMQ maintains a set of formatters different for each level: https://github.com/zeromq/pyzmq/blob/ae615d4097ccfbc6b5c17de60355cbe6e00a6065/zmq/log/handlers.py#L91-L105

As hinted in the documentation, you should call setFormatter() to define a consistent format:

setFormatter(fmt, level=0) Set the Formatter for this handler.

If no level is provided, the same format is used for all levels. This will overwrite all selective formatters set in the object constructor.

Your problem can be fixed by adding the following line to your code:

zmq_handler.setFormatter(logging.Formatter("%(message)s"))

[namoshizun]

Curiously, the PubHandler of ZMQ maintains a set of formatters different for each level: https://github.com/zeromq/pyzmq/blob/ae615d4097ccfbc6b5c17de60355cbe6e00a6065/zmq/log/handlers.py#L91-L105

As hinted in the documentation, you should call setFormatter() to define a consistent format:

setFormatter(fmt, level=0) Set the Formatter for this handler. If no level is provided, the same format is used for all levels. This will overwrite all selective formatters set in the object constructor.

Your problem can be fixed by adding the following line to your code:

zmq_handler.setFormatter(logging.Formatter("%(message)s"))

Thanks! That worked for me! @Delgan could you update the loguru doc as well?

[Delgan]

@namoshizun Sure thing, it's done. :+1: