Fix/logging

[paul-finary]

Hi,

Thanks a lot for this library.

I implemented a small fix on the way the cli logging config is set-up.

From what I understood, the issue with basicConfig is that is sets a handler on the root logger, which can be annoying for applications using this library because python's logging automatically propagates the children logs to its parent, resulting in duplicate logs printed. Here's a excerpt from my logs:

I, [2022-05-27T20:03:35.260 #73489]     INFO -- : [None] Processing Job<...>
INFO:saq:Processing Job<...>
I, [2022-05-27T20:03:35.260 #73489]     INFO -- : [None] Enqueuing Job<...>
INFO:saq:Enqueuing Job<...>
I, [2022-05-27T20:03:35.262 #73489]     INFO -- : [None] Finished Job<...>
INFO:saq:Finished Job<...>

A solution to fix that for the client application is to detach all handlers from the root logger, but it can be cumbersome.

Another solution is to replace the usage of basicConfig by dictConfig, as I did here.

[tobymao]

why is there so much stuff here? where did you get this from? is it standard?

[paul-finary]

That's a pretty standard dictConfig. It defines a formatter, which is attached to a handler with a custom log_level, and this handler is attached to the top-level logger "saq".
I decided to put the format explicitly in case you wanted to modify it later on.

[JonasKs]

Wouldn’t it make more sense to pass a logging dict/config as input?

[paul-finary]

@JonasKs Why ? This function exists only to generate the right dictConfig based on the verbosity level the user choose via the cli.

[paul-finary]

Oups sorry, actually the datefmt attribute is not needed, my bad.

[barakalon]

Logging configuration is tricky. I'm trying to understand the implications of this change.

My guess is you've got code that's adding a stream handler to the root logger? And since basicConfig is called first, you end up with two stream handlers on the root logger?

This change seems to only add the stream handler to the saq logger. I'm worried that having two logging handlers could lead to even more confusing behavior. For example, what if I want to override the format of all logs?

I think the existing code is good for the simple use case. But for more complex use cases, when you might want more control over logging... maybe we should have a way to just turn off automatic logging configuration altogether?

[paul-finary]

It is indeed tricky!

In my application, I have a dictConfig that defines a custom format, set custom levels for other loggers, and adds a filter to inject a request_id in each log, here's an excerpt:

{
    "version": 1,
    "disable_existing_loggers": False,
    "incremental": False,
    "formatters": {
        "default": {
            "format": "%(levelname)1.1s, [%(asctime)s.%(msecs)03d #%(process)d] %(levelname)8s -- : [%(request_id)s] %(message)s",
        },
    },
    "handlers": {
        "console": {
            "level": "DEBUG",
        },
    },
    "loggers": {
        "app": {
            "level": "DEBUG",
            "handlers": ["console"],
        },
        "saq": {
            "level": "DEBUG",
            "handlers": ["console"],
        },
        "uvicorn": {
            "level": "INFO",
            "handlers": ["console"],
        },
    },
}

This way I'm able to log only INFO-level server logs, but DEBUG-level worker logs, with my own format, and my own custom data injected.

As I understand it, the root logger is always better left alone, a good practice is to get a logger via logger = logging.getLogger(__name__), this way the application hierarchy is reflected in the logger hierarchy (say your app is called "xxx", you end up with loggers sur as "xxx.utils", "xxx.models", "xxx.views", and so on)

What this change does is NOT adding a handler to the root logger, but explicitly defining the handler, formatter, and attach them to the SAQ logger. This way, users of this library can silence, change the format, select the log_level, or further modify the logging configuration via their own dictConfig (as I do via my dictConfig shown above).

As of now, a user of the library would need to detach the handler attached to the root logger (attached by the basicConfig) to then modify the SAQ logger via his own dictConfig. If not done, he would end up with duplicated logs (as shown in the initial comment).

Hope that's clearer :)

[barakalon]

This way I'm able to log only INFO-level server logs, but DEBUG-level worker logs, with my own format, and my own custom data injected.

👍 Yeah, I'm all for dictConfig, and I think applications should definitely have this kind of control over logging.

As I understand it, the root logger is always better left alone, a good practice is to get a logger via logger = logging.getLogger(name), this way the application hierarchy is reflected in the logger hierarchy (say you app is called "xxx", you end up with loggers sur as "xxx.utils", "xxx.models", "xxx.views", and so on)

Nothing in saq logs to the root logger. Let's not conflate "Loggers" (what you're referring to) and "Handlers" (what's being changed in this PR).

What this change does is NOT adding a handler to the root logger, but explicitly defining the handler, formatter, and attach them to the SAQ logger. This way, users of this library can silence, change the format, select the log_level, or further modify the logging configuration via their own dictConfig (as I do via my dictConfig shown above).

I think your dictConfig is just overriding the saq logger set by saq. So this might happen to work nice for your scenario, where your app's logging config references the saq logger. But it might not work as expected in other scenarios.

As of now, a user of the library would need to detach the handler attached to the root logger (attached by the basicConfig) to then modify the SAQ logger via his own dictConfig. If not done, he would end up with duplicated logs (as shown in the initial comment).

My suggestion was to optionally remove logging configuration from SAQ altogether. I think that's safer and cleaner. And it should work the same given your config file.

Another option is what @JonasKs recommended - allowing a config file to be passed in.

[paul-finary]

Nothing in saq logs to the root logger. Let's not conflate "Loggers" (what you're referring to) and "Handlers" (what's being changed in this PR).

Yes you're right, I got confused.

I think your dictConfig is just overriding the saq logger set by saq. So this might happen to work nice for your scenario, where your app's logging config references the saq logger. But it might not work as expected in other scenarios.

I'm not sure I understand how it wouldn't work in other scenarios. If by "you dictConfig" you refer to the one I commented, then yes. But this works because I had a look at the code and saw you were fetching the logger via logging.getLogger("saq").

My suggestion was to optionally remove logging configuration from SAQ altogether. I think that's safer and cleaner. And it should work the same given your config file.

I mean, that would solve the issue, but then someone with a simple use-case wouldn't be able to control the log-level. If its ok for you then that's ok for me!

[barakalon]

Ah, I mean something like this:

parser.add_argument(
    "--quiet",
    "-q",
    action="store_true",
    help="Disable automatic logging configuration",
)
...

if not args.quiet:
    level = args.verbose
    ...
    logging.basicConfig(...)

[paul-finary]

Ah, I understand! I implemented the flag.

[barakalon]

v0.8.0 is published to pypi: https://pypi.org/project/saq/