Feature: multiple independent bound Loggers wich have separate set of handlers

[Fak3]

Hi. In my app I found a need to create a Logger with its own set of handlers, disjoint with the root logger.
In my usecase, I am trying to spawn many tasks (async functions), so that each task logs into its own file. Minimal code snippet:

import asyncio
from loguru import logger

async def runtasks():
    async def worker(taskid, log):
        log.info(f'ping {taskid}')
        
    tasks = []
    for taskid in (1,2,3,1):
        log = logger.bind(taskid=taskid)   # Bound logger still shares handlers with root logger :(
        log.add(f'{taskid}.log')
        tasks.append(asyncio.create_task(worker(taskid, log)))
    await asyncio.gather(*tasks)

asyncio.run(runtasks())

In this code snippet, i spawn 4 tasks, with identifiers 1, 2, 3, and 1 again. I want each task to write into its log file, named {taskid}.log. Ufortunately it is hard to accomplish right with any of the logging libraries i tried - loguru, structlog, stdlib.
The above snippet fails to achieve what i want, and the contents of 2.log contains the log messages from the wrong tasks:

> cat 2.log 
2019-03-28 17:20:14.000 | INFO     | __main__:worker:178 - ping 1
2019-03-28 17:20:14.001 | INFO     | __main__:worker:178 - ping 2
2019-03-28 17:20:14.001 | INFO     | __main__:worker:178 - ping 3
2019-03-28 17:20:14.002 | INFO     | __main__:worker:178 - ping 1

It would work if the call to log = logger.bind(taskid=taskid) would return a bound logger instance, not connected to the root logger, so that subsequent call to log.add() only affected this bound logger instance. That would be a nice feature to have.

[Fak3]

I just tried my quick poc with the code snippet above, and it worked flawlessly - each task only logged to its own file. I have not yet checked what parts this change could break (Obviously bunch of tests fail with it)

[Delgan]

Hi @Fak3.

This is an interesting use case. However, your workaround to bound handlers to logger instances rather than Logger class is quite opposed to the deliberated design of this library. 😄

Fortunately, there is a recipe for this kind of situation. Using bind() and filter parameter, you can filter-out logs which do not match your taskid. This also avoid having to pass the logger objet around your functions.

async def runtasks():
    async def worker(taskid):
        logger.bind(taskid=taskid).info(f'ping {taskid}')

    tasks = []
    seen = set()

    for taskid in (1,2,3,1):
        if taskid not in seen:
            def filter(record, taskid=taskid):
                return record["extra"]["taskid"] == taskid
            logger.add(f'{taskid}.log', filter=filter)
            seen.add(taskid)
        tasks.append(asyncio.create_task(worker(taskid)))
    await asyncio.gather(*tasks)

asyncio.run(runtasks())

The only downside is that each log has to be checked by the filter function of each added handler. This may needlessly slow down your application if you have really a lot of task identifiers. In such case, I would suggest to use one unique handler with a custom sink selecting file appropriately based on the extra["taskid"] value.

async def runtasks():
    async def worker(taskid):
        logger.bind(taskid=taskid).info(f'ping {taskid}')

    def sink(message):
        taskid = message.record["extra"]["taskid"]
        with open(f'{taskid}.log', 'a') as file:
            file.write(message)

    logger.add(sink)

    tasks = []
    for taskid in (1,2,3,1):
        tasks.append(asyncio.create_task(worker(taskid)))
    await asyncio.gather(*tasks)

asyncio.run(runtasks())

[Fak3]

Thanks. I think the last example would fit my needs, albeit sad that it takes much more lines.

The downisde is that file will be constantly opened\closed on each log message. It will require more code lines to prevent that...

Actually I wonder if something like "ParametrizedFileSink" could become part of loguru standard package. Currently loguru already supports parametrizing with {time} for rotation, and it could theoretically become even smarter about filenames.
It could work like this: when you call logger.add('{taskid}.log'), loguru could understand that the passed string is parametrized (other than currently supported {time} token). So it would create a ParametrizedFileSink(pattern='{taskid}.log'). The ParametrizedFileSink on receiving a message, would parametrize the filename pattern against the extra dict of the message, and check if it has that file opened already (perhaps holding all currently opened files "cache" in the internal dict). If file already opened - write message there.

[Delgan]

The problem is that the file handler actually does not know what should be parametrized. Currently, it just has to call filename.format(time=datetime.now()) and it works fine. Adding more parameters is complicated for several reasons, notably because it would rely on the extra dict which is user-defined and it would be too dependant on the logged messages. One handler should be responsible for one file, no more.

Actually, I think the solution I first proposed and your ParametrizedFileSink idea are imperfect workarounds for what is basically a missing feature in the Loguru design.

I will try to think about an improvement of the API so it can handle such use case.

[Delgan]

Next Loguru release will add a way to use independent loggers, finally. 🎉

I refactored the logger so that handlers are bound to the logger instances and not class (see #157). I also removed some internal functions which caused the logger to not be picklable. Now that logger can be pickled, it also means it can be deep copied using copy.deepcopy().

So, if you want to use independent loggers with independent handlers, you just have to call logger_2 = copy.deepcopy(logger). Updating your initial code snippet, it may look like this for example:

import asyncio
import copy
from loguru import logger

async def runtasks():
    async def worker(taskid, log):
        log.info(f'ping {taskid}')

    loggers = {}

    logger.remove()

    for taskid in (1, 2, 3):
        task_logger = copy.deepcopy(logger)
        task_logger.add(f'{taskid}.log')
        loggers[taskid] = task_logger

    tasks = []
    for taskid in (1,2,3,1):
        log = loggers[taskid]
        tasks.append(asyncio.create_task(worker(taskid, log)))
    await asyncio.gather(*tasks)

asyncio.run(runtasks())

This is intentionally not part of the Loguru API (it requires to import the copy module) because I think this goes against the design of Loguru (one global logger to manage everything). However, I'm very happy there exists a workaround for some use cases like the one of this issue.

Note that most of the handlers are not picklable by default, so it's better to remove() all handlers before copying the logger.

I also added this to the documentation:

• Creating independent loggers with separate set of handlers

I will close this issue once next Loguru release is published. 😉

[lsabi]

@Delgan any news about the release? I'm in the same situation and would start using deepcopy rather than bind.

Thanks.

[Delgan]

@lsabi I just published the v0.4.0!

The deepcopy() workaround should work fine. Please, tell me if you have any problem. 👍