[core] Rework logging

[Exirel]

Fix #1337

Python built-in logging package makes a lot of thing way easier: no more raw log manually added to a file, no more a scaffold of try/except because opening a log file could be a problem... everything better now.

Of course, this isn't 100% ISO-functionnal, because that's not the point. And I'm also sure we could spend a ridiculous amount of time to make sure we have a 100% perfectly consistent logging system everywhere.

But I believe it's a good first step. Something that we can be proud of, and build upon. It's still better quality code than it was!

[Exirel]

@dgw once we agree on these changes, I'll update the documentation accordingly. I think this deserve some explanation for end-users, and for plugin developers.

[dgw]

Hmmmm. This is a massive rewrite just to tweak some log levels for #1337. 😛 Can you implement 01feeae in a separate PR, and we can, ahem, bikeshed this overhaul without blocking that?

I have some design questions. Like, why remove sopel.logger.get_logger instead of fixing it? Of course I understand that this function duplicates stuff the same as sopel.web.get/.head/.post did (as they were literally just wrappers around the equivalent functions from requests), but at the same time I'd really like to have sopel.logger.get_logger() just work without worrying about the argument at all. That is, the dream would be to have it automatically figure out the correct name based on whether it's invoked from a core file, core plugin, or custom/external package/plugin—but that might be too magic. Convince me why that dream actually would be a nightmare and I'll wake up. 😁

Rotating log files is a nice idea, but I don't see where old files will be deleted. Of course, Sopel's current logging setup doesn't prune itself either, but… that's something I should have opened an issue for long ago. It's bad to have logs stick around forever.

My first look at this was split over multiple sessions, and I hope I didn't forget any big questions. Nitpicks were deliberately excluded, though. Don't worry, the usual "dgw edits Exirel's English" will happen later! I just didn't want either of us to spend time on it just yet.

[Exirel]

A Nice Conversation Starter

Can you implement 01feeae in a separate PR

I could, but I think I wouldn't like it - neither would you. I've two main concerns about the current implementation: the force redirect output, and the manual writing in a file.

First, the force redirect output. This is a bad developer solution to a 100% ops problem. As a result, properly using logs become a nightmare, because you would think that all we do is log to the console... but that's not true at all! Beside, the stdio.log is a mess, because it will log both sopel start and any kind of print that would happen in a non-"run" command. This is bonkers.

The proper way to solve that, is to use logging where it's relevant, and to use the good old fashioned print elsewhere. On a surface level, it looks like I changed a lot of code, but deep down, I've removed a lot of ad-hoc code by battle tested, reusable code from Python built-in.

Second, manually writing into log files. I think it was produced by the best intention in the world. Here, make sure we log everything critical. Also the folder creation might fail, that's only fair that we protect us from that! Sure thing... yet logging already does that, in a much better and efficient way than we do.

Except that it won't work properly if you redirect the output, and of course there is always the possibility to mess-up the configuration. But again, it looks like a huge risky change, yet it's replaced with fewer lines of code (i.e. easier to read), using battle tested Python built-in.

There are lot I don't like with the logging system in Python (I even made a talk at a Python French Conference about how ugly its documentation is), yet it's a standard, and it does its job wonderfully: it's steady, functional, and quite simple to reuse all over the place (in core, plugins, etc.).

As a result, changing the log level wouldn't do us any good, but create lots of unintended side effects that would inevitably lead us to... replace everything with logging.

I Have Some Design Questions.

sopel.logger.get_logger

Quick note: the docstring of get_logger is full of lie and I hate it. Using this inside, say, the remind core module:

logger = get_logger(__name__)

Actually means that the logger will be sopel.modules.sopel.modules.remind. Which is bonkers. And for that, I hate you, get_logger.

why remove sopel.logger.get_logger instead of fixing it?

My main concern is that we try to outsmart and hide a system that is otherwise pretty common and industry standard in Python application (also it's buggy).

The real fix is to allow developers to use logging.getLogger properly. For that, we need to create a context that allows them to do so freely and safely (no force redirect output, proper use of logging everywhere, good documentation and guidance, etc.).

That is, the dream would be to have it automatically figure out the correct name based on whether it's invoked from a core file, core plugin, or custom/external package/plugin—but that might be too magic.

You said it: too magic. It means looking at the stack trace, figuring out where we are. And I really don't like that approach. There is enough magic in a logging.getLogger(__name__), while keeping the "explicit is better than implicit" zen of Python.

The best part would be to document our logging handlers, so that plugin developers can do that in their own code:

SCRAP that little part: it doesn't work. Python's logging dictConfig is dumb and can't reuse a reference to a handler in dictConfig from a previous call. It must be given everything all the time...
That's annoying.

Rotating log files is a nice idea

On that one, I had mixed feeling at first, just like you:

I don't see where old files will be deleted.

Until I had the exact same realization as you:

Of course, Sopel's current logging setup doesn't prune itself either

Yeah, Sopel does nothing to its log at the moment. It's solution is to: just open the file every single time something is output on stdout/stderr. If the file doesn't exist anymore, it's directly re-created. It makes log rotating easy, but that's also a good context for race condition and I/O congestion.

In the "rotating file" scenario, Sopel would write a log file every single day. To delete them, you can use any kind of cron tasks to remove files older than X days/weeks/months.

Design Conclusion From A Totally Objective Person (me)

As of today, we don't let the user decided what they will get with logging. I think this PR shows that we can give them more control with a system that is already existing, battle tested code, and that is closer to industry standards.

Let people use logging is what I'm trying to say. 💪

"dgw edits Exirel's English"

🇫🇷 🇫🇷 🇫🇷 🇫🇷 🇫🇷 🇫🇷

[dgw]

Almost an hour since I reviewed #1680, and nearly the entire time was spent directly on this. It's a big patch! But the more I thought about your arguments, and the more I looked at the changes themselves, the more convinced I became that this is necessary, and that sopel.logger.get_logger is indeed a kludge at best.

This completes (for now) my list of "Awaiting your review" PRs. I expect it will have more entries in 12-24 hours at most, since the bulk of the PRs I reviewed were yours and you have a lot of free time coming up. 😁

Edit: Forgot to mention this before submitting the review, but what if we just moved sopel.logger to sopel.logging? It would make a lot more sense being named that, since it isn't a "logger" at all, but the "logging" machinery.

[Exirel]

The live test for Google Translate is broken. Of course it is.

[dgw]

One easy English nitpick, and a logic question that might or might not be relevant depending on how bad my quick-glance code comprehension is. 😹

[dgw]

From an unrelated IRC question, I found

sopel/sopel/coretasks.py

Line 218 in c752b10

LOGGER.info("Received an apparently useless MODE message: {}"

which should be a debug message.

Can you change that in this PR so we don't need to open a separate one? 😸

[dgw]

I had some conflicting ideas about get_logger vs. get_plugin_logger. Obviously, not all of them were good: Good ideas don't conflict with each other. (Just kidding; sometimes they do.) But here are the ones that didn't conflict and seemed good enough to share.

One part of me wants to keep the simple name get_logger going forward, since the new function does basically the same thing when passed a name (the only supported use now). Since we only supported get_logger() with no argument in core, and third parties always should have used get_logger('name_here'), would we invite catastrophe by keeping the old name around?

Another part of me thinks that get_plugin_logger belongs somewhere in sopel.tools, and/or that sopel.logger should really be named sopel.logging (potential for import name clashes with stdlib notwithstanding—i.e. from sopel import logging and import logging in the same file). Any thoughts?

You'll find the usual grammatical tweaks attached. 😛

[Exirel]

One part of me wants to keep the simple name get_logger going forward

My main concern is that its docstring promoted get_logger(__name__) which is very bad because the end result was sopel.modules.sopel_modules.my_module when called from the sopel_modules.my_module custom plugin. But I totally get what you say. What I want to do is to:

• keep get_logger where it is for now
• change it so it can detect if the argument is a fully qualified name or not
• if so, use logging.getLogger()
• otherwise, use get_plugin_logger (or something similar)

Another part of me thinks that get_plugin_logger belongs somewhere in sopel.tools

What about sopel.plugins.get_logger? That could make sense. It would allow to slowly deprecate sopel.logger.get_logger (doc in 7.0, warning in 8.0, removed in 9.0), while having a "plugin" specific version that we could promote and work with.

[Exirel]

@dgw I made the changes I suggested above. I think it's a sane approach, and I'm glad you made me reconsider this. 😃

With that, internal plugins will have to use:

# in sopel/modules/clock.py
import logging
LOGGER = logging.getLogger(__name__)

And it'll be under the sopel namespace, which is perfect.

For an external plugin, such as sopel_modules.youtube or any new fancy entry-point based plugins for Sopel 7.x:

# in modsopelunker.py
from sopel import plugins
LOGGER = plugins.get_logger('sopelunker')

Which will log everything with the sopel.externals.sopelunker logger, which is under the right logging namespace. So that's perfect too!

[Exirel]

@dgw I moved get_logger into sopel.tools. For everything else, I think the way forward is "another PR".

[dgw]

Some of these were left over from an interrupted review a little while back, and some are new. Basically all of them are nitpicking. I wanna get this merged today! 🚀

[dgw]

Quick, before I notice any more grammar to tweak!

(RIP "Conversation [69]", sorry @Exirel 😆)

[Exirel]

🎉