Set up standard logging module

[rlerm]

Initial parts of https://github.com/ultrabug/py3status/issues/2063: Set up the root logger from the logging module. Make py3.log defer to that logger.

The root logger's configuration was built in a way that tries to preserve the existing behavior as much as possble.

[lgtm-com[bot]]

This pull request introduces 1 alert when merging ac081129d82cd8475da528222e2c8e5f3fc3803f into cafe0c7a1840d105ea585e16b95eda3ecd96c219 - view on LGTM.com

new alerts:

• 1 for Unused import

[ultrabug]

Thanks @rlerm, this is a very promising first contribution to this project :medal_sports:

When you say "initial parts" I guess you plan on adding things, is that correct? If so, please mark this PR as WIP and tell me when the time is right to review and test it please?

Also, you will want to demonstrate and document what this new logging system brings to the table and how to use it to achieve the goals you expressed in #2063 please

Thanks again

[lgtm-com[bot]]

This pull request introduces 2 alerts when merging 7736dfa6fa755a08a69581323bf5d8dbcdafd85c into cafe0c7a1840d105ea585e16b95eda3ecd96c219 - view on LGTM.com

new alerts:

• 1 for Syntax error
• 1 for Module is imported with 'import' and 'import from'

[rlerm]

Thanks! (And sorry for the delay in responding)

The initial PR was usable, but it was lacking a way to configure the logging in a more advanced way. I've added, that, and the documentation.

Please let me know what you think.

[ultrabug]

Trying your PR locally

For now I get

py3status: Setup error (local variable 'logging' referenced before assignment). Please try to fix this and reload i3wm (Mod+Shift+R)

EDIT:

This is Python 3.9 I run

Traceback (most recent call last):
  File "/tmp/py3status/py3status/__init__.py", line 39, in main
    py3.setup()
  File "/tmp/py3status/py3status/core.py", line 576, in setup
    self._setup_logging()
  File "/tmp/py3status/py3status/core.py", line 552, in _setup_logging
    root = logging.getLogger(name=None)
UnboundLocalError: local variable 'logging' referenced before assignment

[rlerm]

That's weird. Do you have a line number? The logging module is being imported quite high up in the module.

[ultrabug]

That's weird. Do you have a line number? The logging module is being imported quite high up in the module.

Yep, see edited comment

There must be a scope context that's not obvious and that's why we need to either global logging in the function or import it again inside I guess

[ultrabug]

Even when bypassing this error, it looks like I get no logs in my syslog when running with the -d debug flag

[rlerm]

Thanks for catching this. I believe I've fixed both issues.

[ultrabug]

So @rlerm thanks for the fix, and sorry for the delay

Tried it, does not crash :+1:

But then I tried your JSON example and I'm not sure it works as expected

{
    "version": 1,
    "handlers": {
        "file": {
            "class": "logging.handlers.RotatingFileHandler",
            "filename": "/tmp/py3status_log.log",
            "maxBytes": 2048,
            "formatter": "default"
        }
    },
    "formatters": {
        "default": {
            "validate": false,
            "format":"%(asctime)s %(levelname)s %(module)s %(message)s",
            "datefmt":"%Y-%m-%d %H:%M:%S"
        }
    },
    "loggers": {
        "root": {"handlers": ["file"], "level": "INFO"},
        "xrandr": {"handlers": ["file"], "level": "DEBUG"}
    }
}

I expected everything INFO logged to the file, and the xrandr module as DEBUG but I don't get anything else than a third party lib (google api) log output written on the file. journalctl goes silent as well...

Shouldn't we propose a default log-config json file that mimics the current behavior we have first?

[rlerm]

Thanks (and sorry for the delay).

You're right, the default Python behavior is to use disable_existing_loggers=True, which makes the "core" logger be disabled when we do the configuration. That was effectively disabling the "core" logger.

As for controlling the "xrandr" module, that won't work directly. Because it wasn't changed to create its own logger (logging.getLogger('xrandr')), it will get logged by the "core" logger. I'd expect people who want to use this logging facility to update their modules before trying to configure logging. (When I wrote this, I was working on a new module locally, and used the logging there)

It's expected that syslog gets silent with the config in the example, since that takes over the entire configuration.

So now the logs should be working even with the example in the doc, minus the "xrandr" part.

[ultrabug]

I tried again and failed @rlerm I'm sorry but the documentation you wrote is not easy enough for stupid people like me...

Could you please:

• convert the xrandr to logging, the way you intend it
• make xrandr an example in your JSON config in the readme?
• specify in the text that by using this, the core will be logged as INFO while xrandr as DEBUG in the /tmp/py3status_log.log file

?

[rlerm]

Thanks, that's a great suggestion. I've ported the module and updated the docs. I don't have a lot of stuff going on in my monitor setup to use everything the xrandr module, but I tested a few layout changes and I was able to get the logs in the expected file.

[lgtm-com[bot]]

This pull request introduces 1 alert when merging 27caf064af388e4bf150ee59e9d698f684206b0c into 5e2a3c16edf91b94081098de5c86fd6b4875638a - view on LGTM.com

new alerts:

• 1 for Unused import

[ultrabug]

Looks like my rebase broke your PR I'm sorry, could you fix it again? promise I'll get this in!

[rlerm]

I've done the rebase, can you check it again? Thanks!

[ultrabug]

@rlerm as I'm trying to figure out how to get the same behavior as the current syslog state using your PR I fail to get a debug log to systemd but I don't get debug logs of the core/py3status if I try to use:

{
    "version": 1,
    "handlers": {
        "syslog": {
            "formatter": "default",
            "class": "logging.handlers.SysLogHandler"
        },
        "file": {
            "class": "logging.handlers.RotatingFileHandler",
            "filename": "/tmp/py3status_log.log",
            "maxBytes": 2048,
            "formatter": "default"
        }
    },
    "formatters": {
        "default": {
            "validate": false,
            "format":"%(asctime)s %(levelname)s %(module)s %(message)s",
            "datefmt":"%Y-%m-%d %H:%M:%S"
        }
    },
    "loggers": {
        "root": {"handlers": ["syslog"], "level": "DEBUG"},
        "core": {"handlers": ["syslog"], "level": "DEBUG"},
        "xrandr": {"handlers": ["file"], "level": "DEBUG"}
    }
}

what I am missing please?

[rlerm]

You were missing https://stackoverflow.com/a/3969772/340862: the syslog handler requires an "address" parameter (we are setting it correctly in the default setting in core.py.

By adding the same parameter to the json config, I am able to get the logs for core:

    "handlers": {
        "syslog": {
            "formatter": "default",
            "class": "logging.handlers.SysLogHandler",
            "address": "/dev/log"
        },
(...)

[lgtm-com[bot]]

This pull request introduces 1 alert when merging 004967107a72670e1759212c99c9a725dbc02be2 into afeab682409fafcb3948c2c1b6b63680b39f9e7c - view on LGTM.com

new alerts:

• 1 for Variable defined multiple times

[ultrabug]

closing, I never got to the bottom of it and I apologize for this

recent updates would require work from you