Set up standard logging module

docs/dev-guide/writing-modules.md

@@ -811,6 +811,49 @@ Loadavg 1.41 1.61 1.82
 Loadavg 1.41 1.61 1.82
 ^C
 ```
+
+## Logging
+
+Modules are encouraged to use Python's standard
+[`logging`](https://docs.python.org/3/library/logging.config.html?highlight=logging#logging-config-dictschema)
+module for debugging. By default, logs will be written to
+[`syslog`](https://docs.python.org/3/library/logging.config.html?highlight=logging#logging-config-dictschema)
+with a minimum level of `INFO`.
+
+Several existing modules will write to logs, with varying levels of details.
+Therefore, when debugging a specific module, it may be useful to show only the
+one you're interested in. This can be done by using the `--log-config` flag to
+pass a JSON file that configures logging. This file must be in the format
+specified in
+[`logging`'s configuration schema](https://docs.python.org/3/library/logging.config.html?highlight=logging#logging-config-dictschema).
+For example, to show only logs from your module in a `DEBUG` level, while
+keeping all others at `WARNING`, you can use:
+
+```json
+{
+    "version": 1,
+    "handlers": {
+        "file": {
+            "class": "logging.handlers.RotatingFileHandler",
+            "filename": "/tmp/py3status_log.log",
+            "maxBytes": 2048,
+            "formatter": "default"
+        }
+    },
+    "formatters": {
+        "default": {
+            "validate": true,
+            "format":"%(asctime)s %(levelname)s %(module)s %(message)s",
+            "datefmt":"%Y-%m-%d %H:%M:%S"
+        }
+    },
+    "loggers": {
+        "root": {"handlers": ["file"], "level": "WARNING"},
+        "<my_module>": {"level": "DEBUG"}
+    }
+}
+```
+
 ## Publishing custom modules on PyPI
 
 You can share your custom modules and make them available for py3status

py3status/argparsers.py

@@ -82,12 +82,6 @@ def _format_action_invocation(self, action):
         metavar="FILE",
         type=Path,
     )
-    parser.add_argument(
-        "-d",
-        "--debug",
-        action="store_true",
-        help="enable debug logging in syslog or log file if --log-file option is passed",
-    )
     parser.add_argument(
         "-i",
         "--include",
@@ -97,15 +91,6 @@ def _format_action_invocation(self, action):
         metavar="PATH",
         type=Path,
     )
-    parser.add_argument(
-        "-l",
-        "--log-file",
-        action="store",
-        dest="log_file",
-        help="enable logging to FILE (this option is not set by default)",
-        metavar="FILE",
-        type=Path,
-    )
     parser.add_argument(
         "-s",
         "--standalone",
@@ -157,6 +142,33 @@ def _format_action_invocation(self, action):
         help="specify window manager i3 or sway",
     )
 
+    logging_args = parser.add_argument_group()
+    logging_args.add_argument(
+        "-d",
+        "--debug",
+        action="store_true",
+        help="enable debug logging in syslog or log file if --log-file option is passed",
+    )
+    logging_args.add_argument(
+        "-l",
+        "--log-file",
+        action="store",
+        dest="log_file",
+        help="enable logging to FILE (this option is not set by default)",
+        metavar="FILE",
+        type=Path,
+    )
+    logging_args.add_argument(
+        "--log-config",
+        action="store",
+        dest="log_config",
+        help="path to a file that fully configures the 'logging' module. This "
+        "must contain a JSON dictionary in the format expected by "
+        "logging.config.dictConfig.",
+        metavar="FILE",
+        type=Path,
+    )
+
     # parse options, command, etc
     options = parser.parse_args()
 

py3status/core.py

@@ -1,11 +1,13 @@
+import logging
+import logging.config
+import logging.handlers
 import sys
 import time
 from collections import deque
+from json import JSONDecodeError, load
 from pathlib import Path
-from pprint import pformat
 from signal import SIGCONT, SIGTERM, SIGTSTP, SIGUSR1, Signals, signal
 from subprocess import Popen
-from syslog import LOG_ERR, LOG_INFO, LOG_WARNING, syslog
 from threading import Event, Thread
 from traceback import extract_tb, format_stack, format_tb
 
@@ -22,7 +24,12 @@
 from py3status.profiling import profile
 from py3status.udev_monitor import UdevMonitor
 
-LOG_LEVELS = {"error": LOG_ERR, "warning": LOG_WARNING, "info": LOG_INFO}
+LOGGING_LEVELS = {
+    "error": logging.ERROR,
+    "warning": logging.WARNING,
+    "info": logging.INFO,
+    "debug": logging.DEBUG,
+}
 
 DBUS_LEVELS = {"error": "critical", "warning": "normal", "info": "low"}
 
@@ -40,6 +47,8 @@
 ENTRY_POINT_NAME = "py3status"
 ENTRY_POINT_KEY = "entry_point"
 
+_logger = logging.getLogger("core")
+
 
 class Runner(Thread):
     """
@@ -515,8 +524,7 @@ def load_modules(self, modules_list, user_modules):
                 # only handle modules with available methods
                 if my_m.methods:
                     self.modules[module] = my_m
-                elif self.config["debug"]:
-                    self.log(f'ignoring module "{module}" (no methods found)')
+                _logger.debug('ignoring module "%s" (no methods found)', module)
             except Exception:
                 err = sys.exc_info()[1]
                 msg = f'Loading module "{module}" failed ({err}).'
@@ -565,10 +573,52 @@ def _log_gitversion(self):
             self.log(f"git commit: {commit.hexsha[:7]} {commit.summary}")
             self.log(f"git clean: {not repo.is_dirty()!s}")
 
+    def _setup_logging(self):
+        """Set up the global logger."""
+        log_config = self.config.get("log_config")
+        if log_config:
+            if self.config.get("debug"):
+                self.report_exception("--debug is invalid when --log-config is passed")
+            if self.config.get("log_file"):
+                self.report_exception("--log-file is invalid when --log-config is passed")
+
+            with log_config.open() as f:
+                try:
+                    config_dict = load(f, strict=False)
+                    config_dict.setdefault("disable_existing_loggers", False)
+                    logging.config.dictConfig(config_dict)
+                except JSONDecodeError as e:
+                    self.report_exception(str(e))
+            # Nothing else to do. All logging config is provided by the config
+            # dictionary.
+            return
+
+        root = logging.getLogger(name=None)
+        if self.config.get("debug"):
+            root.setLevel(logging.DEBUG)
+        else:
+            root.setLevel(logging.INFO)
+
+        log_file = self.config.get("log_file")
+        if log_file:
+            handler = logging.FileHandler(log_file, encoding="utf8")
+        else:
+            # https://stackoverflow.com/a/3969772/340862
+            handler = logging.handlers.SysLogHandler(address="/dev/log")
+        handler.setFormatter(
+            logging.Formatter(
+                fmt="%(asctime)s %(levelname)s %(module)s %(message)s",
+                datefmt="%Y-%m-%d %H:%M:%S",
+                style="%",
+            )
+        )
+        root.addHandler(handler)
+
     def setup(self):
         """
         Setup py3status and spawn i3status/events/modules threads.
         """
+        self._setup_logging()
 
         # log py3status and python versions
         self.log("=" * 8)
@@ -580,8 +630,7 @@ def setup(self):
 
         self.log("window manager: {}".format(self.config["wm_name"]))
 
-        if self.config["debug"]:
-            self.log(f"py3status started with config {self.config}")
+        _logger.debug("py3status started with config %s", self.config)
 
         # read i3status.conf
         config_path = self.config["i3status_config_path"]
@@ -631,10 +680,7 @@ def setup(self):
                     i3s_mode = "mocked"
                     break
                 time.sleep(0.1)
-        if self.config["debug"]:
-            self.log(
-                "i3status thread {} with config {}".format(i3s_mode, self.config["py3_config"])
-            )
+        _logger.debug("i3status thread %s with config %s", i3s_mode, self.config["py3_config"])
 
         # add i3status thread monitoring task
         if i3s_mode == "started":
@@ -645,15 +691,13 @@ def setup(self):
         self.events_thread = Events(self)
         self.events_thread.daemon = True
         self.events_thread.start()
-        if self.config["debug"]:
-            self.log("events thread started")
+        _logger.debug("events thread started")
 
         # initialise the command server
         self.commands_thread = CommandServer(self)
         self.commands_thread.daemon = True
         self.commands_thread.start()
-        if self.config["debug"]:
-            self.log("commands thread started")
+        _logger.debug("commands thread started")
 
         # initialize the udev monitor (lazy)
         self.udev_monitor = UdevMonitor(self)
@@ -696,8 +740,7 @@ def setup(self):
         # get a dict of all user provided modules
         self.log("modules include paths: {}".format(self.config["include_paths"]))
         user_modules = self.get_user_configured_modules()
-        if self.config["debug"]:
-            self.log(f"user_modules={user_modules}")
+        _logger.debug("user_modules=%s", user_modules)
 
         if self.py3_modules:
             # load and spawn i3status.conf configured modules threads
@@ -807,8 +850,7 @@ def stop(self):
 
         try:
             self.lock.set()
-            if self.config["debug"]:
-                self.log("lock set, exiting")
+            _logger.debug("lock set, exiting")
             # run kill() method on all py3status modules
             for module in self.modules.values():
                 module.kill()
@@ -839,12 +881,10 @@ def refresh_modules(self, module_string=None, exact=True):
                 or (not exact and name.startswith(module_string))
             ):
                 if module["type"] == "py3status":
-                    if self.config["debug"]:
-                        self.log(f"refresh py3status module {name}")
+                    _logger.debug("refresh py3status module %s", name)
                     module["module"].force_update()
                 else:
-                    if self.config["debug"]:
-                        self.log(f"refresh i3status module {name}")
+                    _logger.debug("refresh i3status module %s", name)
                     update_i3status = True
         if update_i3status:
             self.i3status_thread.refresh_i3status()
@@ -918,29 +958,11 @@ def notify_update(self, update, urgent=False):
     def log(self, msg, level="info"):
         """
         log this information to syslog or user provided logfile.
+
+        This is soft-deprecated; prefer using the 'logging' module directly in
+        new code.
         """
-        if not self.config.get("log_file"):
-            # If level was given as a str then convert to actual level
-            level = LOG_LEVELS.get(level, level)
-            syslog(level, f"{msg}")
-        else:
-            # Binary mode so fs encoding setting is not an issue
-            with self.config["log_file"].open("ab") as f:
-                log_time = time.strftime("%Y-%m-%d %H:%M:%S")
-                # nice formatting of data structures using pretty print
-                if isinstance(msg, (dict, list, set, tuple)):
-                    msg = pformat(msg)
-                    # if multiline then start the data output on a fresh line
-                    # to aid readability.
-                    if "\n" in msg:
-                        msg = "\n" + msg
-                out = f"{log_time} {level.upper()} {msg}\n"
-                try:
-                    # Encode unicode strings to bytes
-                    f.write(out.encode("utf-8"))
-                except (AttributeError, UnicodeDecodeError):
-                    # Write any byte strings straight to log
-                    f.write(out)
+        _logger.log(LOGGING_LEVELS.get(level, logging.DEBUG), msg)
 
     def create_output_modules(self):
         """

py3status/modules/xrandr.py

@@ -140,10 +140,13 @@
 {'full_text': 'DP1'}
 """
 
+import logging
 from collections import OrderedDict, deque
 from itertools import combinations
 from time import sleep
 
+_logger = logging.getLogger("xrandr")
+
 
 class Py3status:
     """"""
@@ -223,7 +226,7 @@ def _get_layout(self):
                 else:
                     continue
             except Exception as err:
-                self.py3.log(f'xrandr error="{err}"')
+                _logger.exception("xrandr error", err)
             else:
                 layout[state][output] = {"infos": infos, "mode": mode, "state": state}
 
@@ -307,7 +310,7 @@ def _choose_what_to_display(self, force_refresh=False):
             if force_refresh:
                 self.displayed = self.available_combinations[0]
             else:
-                self.py3.log('xrandr error="displayed combination is not available"')
+                _logger.warning('xrandr error="displayed combination is not available"')
 
     def _center(self, s):
         """
@@ -343,7 +346,7 @@ def _apply(self, force=False):
                 resolution = f"--mode {resolution}" if resolution else "--auto"
                 rotation = getattr(self, f"{output}_rotate", "normal")
                 if rotation not in ["inverted", "left", "normal", "right"]:
-                    self.py3.log(f"configured rotation {rotation} is not valid")
+                    _logger.warning("configured rotation %s is not valid", rotation)
                     rotation = "normal"
                 #
                 if primary is True and not primary_added:
@@ -365,7 +368,7 @@ def _apply(self, force=False):
             self.active_comb = combination
             self.active_layout = self.displayed
             self.active_mode = mode
-        self.py3.log(f'command "{cmd}" exit code {code}')
+        _logger.info('command "%s" exit code %s', cmd, code)
 
         if self.command:
             self.py3.command_run(self.command)
@@ -395,7 +398,7 @@ def _apply_workspaces(self, combination, mode):
                     cmd = '{} move workspace to output "{}"'.format(self.py3.get_wm_msg(), output)
                     self.py3.command_run(cmd)
                     # log this
-                    self.py3.log(f"moved workspace {workspace} to output {output}")
+                    _logger.info("moved workspace %s to output %s", workspace, output)
 
     def _fallback_to_available_output(self):
         """
@@ -494,7 +497,7 @@ def xrandr(self):
 
         # follow on change
         if not self._no_force_on_change and self.force_on_change and self._layout_changed():
-            self.py3.log("detected change of monitor setup")
+            _logger.info("detected change of monitor setup")
             self._force_on_change()
 
         # this was a click event triggered update