Logging issues with discord bot

[BigBigBaka]

Hello, I am currently working on a discord bot using discord.py version 2.0+. So far having two main issues when trying to log the time a user executes a command.

Here is a sample snippet of my code:

from __future__ import annotations
from typing import TYPE_CHECKING
from loguru import logger

from discord.ext import commands

if TYPE_CHECKING:
    from launcher import MyBot


class TEST_COMMAND(commands.Cog):
    def __init__(self, bot: MyBot) -> None:
        self.bot: MyBot = bot

    @commands.hybrid_command(name="test", description="test!", aliases=["t"])
    async def test(
        self,
        ctx: commands.Context[commands.Bot],
    ) -> None:
        logger.add(
            f"logs/user/{ctx.author.id}.log",
            format="{time:YYYY-MM-DD at HH:mm:ss} {message}",
        )
        logger.log("INFO", "/test")

async def setup(bot: MyBot):
    await bot.add_cog(TEST_COMMAND(bot))

The first issue I am having with is that assuming there are two users, A and B, executing the command, "2022-09-08 at 20:11:06 test" will be logged on both A and B's log file once user B executes the command after user A.

The Second issue I noticed is the duplicate loggings. For instance, I noticed that when executing the command 2 times, "2022-09-08 at 20:11:06 test" was logged 3 times instead of the expected result of 2 times.

However, the logs shown on the terminal looks fine and working as intended.

Any help is appreciated =)

[BigBigBaka]

I've just noticed someone else had a similar problem and by simply adding logger.remove() solved both of my issues, my apologies.

[Delgan]

Hi @nopnopwei.

I'm not sure how is your application used but keep in mind that logger.add() should not be called repeatedly. You should add one handler per user (from what I understand) in a "configuration step" and maybe use a custom filter to avoid duplicated logs based on bind() argument.

See examples in the documentation: Creating independent loggers with separate set of handlers.

[BigBigBaka]

Hello @Delgan

Thank you for your response and feedback. Could you explain briefly the consequences of repeating logger.add() repeatedly? Because I am having trouble replicating the "One handler per user", and I assume mainly because of the filtering concept.

So assume that I have a discord command /register, where user will have to register before interacting with the bot. What this command basically does is add user's id into the database, and this might be a good place to create user's log file?

register.py file

def register():
     ... database stuff
     logger.add(
            f"logs/user/{ctx.author.id}.log",
            format="{time:YYYY-MM-DD at HH:mm:ss} {message}",
            filter=lambda record: record["extra"]["task"] == f"{ctx.author.id}",
        )

command.py file

def my_command()
        logger_a = logger.bind(task=f"{ctx.author.id}")
        logger_a.info("Starting task A")
        ... Do stuff
        logger_a.success("End of task A")

This does not log anything and I'm assuming it's bad filtering and the logger.add() is on a different file, or maybe I'm in a completely wrong path. Adding logger.add() file also seems to only make sense to add it inside the my_command() function, which again I felt like this violate what you suggest earlier where logger.add() should not be called repeatedly.

So I'm kinda lost now >.>, so any help is really appreciated :)

[Delgan]

Hi @nopnopwei.

Now I understand why you need to call .add() multiple times. Although I don't recommend it (for performances reason mainly), it's acceptable.

You make a good usage of filter and bind(), it should work well. However, I suspect you're facing a common pitfall of using a global variable in a closure function: Creating functions (or lambdas) in a loop (or comprehension).

The problem is likely because the {ctx.author.id} value changed between the time .add() was called and filter was executed.

You need to capture the task identifier like so:

filter=lambda record, task=ctx.author.id: record["extra"]["task"] == f"{task}",

If that still doesn't work, try printing the values in your register and my_command functions to help debugging.

[BigBigBaka]

Hello @Delgan

It is working as intended now. Thank you for your help and suggestions =)

[Delgan]

You're welcome, glad it worked. :+1:

I'm closing the issue then. ;)