log: decouple py3status logging

[lasers]

Working with codex off this #2327 (comment)

It's certainly terrible to look at those added if debug.

Direct logging avoids this.

Original logging PR called for using the logging module directly everywhere plus using lazy %s strings. One can look into adding ruff rule to prevent f-strings logging to reduce wasted f-string calculation.

Addressed.
Lint ruled added -- https://docs.astral.sh/ruff/rules/logging-f-string/

I think the real issue is that we're logging everything through a busy self.log instead of breaking up into either using logging functions directly or create additional py3 logging (ie self.py3.debug pass if disabled, self.py3.info). I looked at how we logged debug/warn code... we just print plain strings most times, so no need to check for arrays/lists/sets/etc and other functions. Those should be just for user-facing logging.

See above. self.py3.log() is now for user-facing module logging. We also could remove self.py3_wrapper.log() in favor of direct logging... for performance reasons since we don't really need wrapper / additional checks.

And to really improve performance, we should be able to disable logs completely too, no syslog, no info log, for most runs, which your proposal PR currently doesn't cover. This issue is acknowledged too.

I haven't looked into this.

@valdur55 Additional suggestion is to fail fast when calling disallowed logging level

Added in self.py3.log().

1. I still have to review more. I just want to toss this PR out and see how you think/feel about this...
2. I think core code should stick with direct logging and user-facing modules can stick with self.py3.log()
3. This changed lot of things. For instance, we now can see logging names (via __name__) rather than piping everything through self.py3.log() / self.py3_wrapper.log() functions.

Here's the benchmarks.

Summary (median µs/call)

benchmark                      | master | logging-memory-leak | logging-split
-------------------------------+--------+---------------------+--------------
internal_debug_disabled_simple | 0.96   | 0.70                | 0.18
internal_debug_disabled_dict   | 10.68  | 0.70                | 0.18
internal_info_enabled_simple   | 5.81   | 6.37                | 4.92
py3_debug_disabled_simple      | 1.20   | 0.78                | 0.35
py3_debug_disabled_dict        | 10.88  | 0.78                | 0.35
py3_info_enabled_simple        | 6.21   | 7.13                | 5.79

Replaces / Closes #2327

[lasers]

Ready for review, but do not merge.

Summary (median us/call)
benchmark                      | master | logging-memory-leak | logging-split
-------------------------------+--------+---------------------+--------------
internal_debug_disabled_simple | 0.81   | 0.60                | 0.14         
internal_debug_disabled_dict   | 9.66   | 0.59                | 0.14         
internal_info_enabled_simple   | 5.27   | 5.38                | 4.39         
py3_debug_disabled_simple      | 1.11   | 0.65                | 0.33         
py3_debug_disabled_dict        | 10.09  | 0.66                | 0.33         
py3_info_enabled_simple        | 5.63   | 6.28                | 5.11

[ultrabug]

Thanks @lasers on the principle I like it very much. Will try to review soon (vacations)

[ultrabug]

not tested yet, just pure code review, looking promising so far!

[lasers]

Wanting to make it clear in the logs about detecting available modules: default modules, user-included modules, and entrypoint modules.... I saw questionable code relating to entrypoint so I need to install and test entrypoint modules eventually.

Your suggestions had been largely included.

[ultrabug]

Now we've been that far it looks like:

1. Py3statusWrapper.log() is dead code to be removed
2. module_test.py will not print anything anymore so we should call logging.basicConfig(level=logging.DEBUG) to get back useful debug infos

[lasers]

1. Py3statusWrapper.log() is dead code to be removed

Dead, but I wasn't sure if we should remove it. Now dead and gone.

2. module_test.py will not print anything anymore so we should call logging.basicConfig(level=logging.DEBUG) to get back useful debug infos

OK. Added. New arg also added --log-level [LEVEL] such as python loadavg.py --log-level debug # (default info). Filter also added to silence method noises occurring in module.py on debug level during module_testing.

---

Cleaning up i3status, other files, and especially module importing code to make it easy/compact to log. Additional code in entry_points-related added to permit loading only once, not again and again for logging (and maybe one more other thing).

Renaming variables user_modules to something a bit more explicit/clear... discoverable_modules to illustrate combined path included modules and entry point modules. Also, using more variables such as path_included_modules and entry_point too.

Ready for review again.

Same benchmarks as last two. Nothing significant changed.

Summary (median us/call)
benchmark                      | master | logging-memory-leak | logging-split
-------------------------------+--------+---------------------+--------------
internal_debug_disabled_simple | 0.82   | 0.59                | 0.14         
internal_debug_disabled_dict   | 9.83   | 0.59                | 0.14         
internal_info_enabled_simple   | 5.32   | 5.40                | 4.38         
py3_debug_disabled_simple      | 1.11   | 0.64                | 0.33         
py3_debug_disabled_dict        | 9.98   | 0.64                | 0.33         
py3_info_enabled_simple        | 5.69   | 6.30                | 5.05         

[ultrabug]

So far so good, tried with journald and it's really an improvement!

I'm wondering about those logs tho, looks like we catch modules' loaded modules own logs but without referencing them:

DEBUG [requests] Making request: POST https://oauth2.googleapis.com/token

This comes from my google_calendar module but we only see it as requests.

I will give the logfile option a try

[ultrabug]

Tested logfile, do user really expect to have BOTH syslog and the defined logfile being fed by py3status logs? I did not but maybe it's just I'm old and confused :)

[lasers]

This comes from my google_calendar module but we only see it as requests.

Nothing turned up in grepping Making request. That one came from google.auth.transport.requests.

The real culrpit is shortname filter with no guards.

record.shortname = record.name.rsplit(".", 1)[-1]

Prefix added to make sure it only happens on py3status files. I also modified py3staus modules to have py3status.modules. namespace... So you tell me if you like shortname modules.sysdata prefix.. or you prefer sysdata. The latter introduces additional leafname field.

do user really expect to have BOTH syslog and the defined logfile being fed by py3status logs?

AFAIK, same behavior. Logfile isn't in use by default.... Styling / formatting for both syslog and logfile are being assigned to stay backward compatibility with --log-file. We backward compatible --debug too.
EDIT: If you're asking me that we should only allow one or another, this breaks old same behavior. Idc.

[ultrabug]

So you tell me if you like shortname modules.sysdata prefix.. or you prefer sysdata.

I like modules.sysdata

[ultrabug]

EDIT: If you're asking me that we should only allow one or another

I think we should default to syslog but if log-file is used we should only use that log file; so make it exclusive

[lasers]

I think we should default to syslog but if log-file is used we should only use that log file; so make it exclusive

Done.

[ultrabug]

Tested OK, almost there mate will do another code review ASAP

[ultrabug]

My turn with AI

One thing I'd still raise, since this commit touches exactly these lines: _setup_logging() starts from init_logging_config = dict(LOGGING_CONFIG) — a shallow copy. _deep_merge(), the handler insertion, and the root-handlers rewrite all mutate the nested dicts, which are shared with the module-level LOGGING_CONFIG constant. In a single normal run that's invisible, but if _setup_logging() ever runs twice in one process (tests, restarts-in-process), state from the first call pollutes the constant. It's a pre-existing wart inherited from master, but since this commit is rewriting the handler-wiring logic anyway, switching to copy.deepcopy(LOGGING_CONFIG) would be a one-line hardening with zero downside.

wdyt? sounds reasonable tho not super necessary

[lasers]

I think it is not necessary because since we only run it once (to set up logging config) per process. Also, this is what happened with your https://github.com/ultrabug/py3status/issues/859 and my https://github.com/ultrabug/py3status/issues/1062. We also don't do anything with logging config after that.

[lasers]

Right now, we only have to keep an eye out on trivial typos, inconsistency style, less-than-ideal or redundant messages.

Code for loading-once/logging entry-point modules is ugly because it's sharing code with path-included modules and maybe default modules too, but it gets the logging part done reasonably nice without loading repeatedly. One day, I may want to see if we can make it more lean/clean in future. I don't have more to do with this.

Don't forget to review feedback/mergeability on all those other PRs too.

[ultrabug]

I agree, sounds reasonable like this indeed thanks for the hard work.

Will give it a last try and start merging

[ultrabug]

Thank you so much, let's move on!