general message scope prefix mechanism for plugin log messages

prapti/core/action.py

@@ -27,6 +27,7 @@ class Action:
     function: Callable[[str, str, ActionContext], None|str|Message]
     exclamation_only: bool = False # !-only commands may only appear in markdown with the ! prefix
     plugin_config: Any|None = None
+    plugin_log: DiagnosticsLogger|None = None
 
 class ActionNamespace:
     def __init__(self):
@@ -59,10 +60,11 @@ def decorator(func):
             return func
         return decorator
 
-    def set_plugin_config(self, plugin_config: Any):
+    def set_plugin_config_and_log(self, plugin_config: Any, plugin_log: DiagnosticsLogger):
         for _,v in self._actions.items():
             for action in v:
                 action.plugin_config = plugin_config
+                action.plugin_log = plugin_log
 
     def lookup_action(self, name: str) -> list[Action]:
         name_components = name.split('.')

prapti/core/builtins.py

@@ -18,7 +18,7 @@
 from .responder import ResponderContext
 from .hooks import Hooks, HooksContext
 from .source_location import SourceLocation
-from .logger import DiagnosticsLogger
+from .logger import DiagnosticsLogger, ScopedDiagnosticsLogger
 from .plugin import Plugin, PluginCapabilities, PluginContext
 
 builtin_actions: ActionNamespace = ActionNamespace()
@@ -89,7 +89,7 @@ def load_plugin_entry_point(plugin_name, source_loc: SourceLocation, log: Diagno
                     log.error("incompatible-plugin-version", f"couldn't load plugin '{plugin_name}'. plugin API version {plugin.api_version} is not compatible with Prapti API version {PRAPTI_API_VERSION}. you need to upgrade the plugin or downgrade Prapti.")
             except Exception as ex:
                 log.error("load-plugin-entry-point-exception", f"couldn't load plugin '{plugin_name}'. an error occurred: exception while loading plugin entry point '{plugin_entry_point.name}': {repr(ex)}", source_loc)
-                log.logger.debug(ex, exc_info=True)
+                log.debug_exception(ex)
                 result = None
         else:
             log.error("plugin-not-found", f"couldn't load plugin '{plugin_name}'. plugin not found. use `%!plugins.list` to list available plugins.", source_loc)
@@ -100,7 +100,8 @@ def load_plugin(plugin: Plugin, source_loc: SourceLocation, state: ExecutionStat
     try:
         core_state = get_private_core_state(state)
 
-        plugin_context = PluginContext(state=state, plugin_name=plugin.name, root_config=state.root_config, plugin_config=None, log=state.log)
+        plugin_log = ScopedDiagnosticsLogger(sink=state.log, scopes=(plugin.name,))
+        plugin_context = PluginContext(state=state, plugin_name=plugin.name, root_config=state.root_config, plugin_config=None, log=plugin_log)
         plugin_context.plugin_config = setup_newly_constructed_config(plugin.construct_configuration(plugin_context), empty_factory=EmptyPluginConfiguration, root_config=state.root_config, log=state.log)
         plugin_actions: ActionNamespace|None = plugin.construct_actions(plugin_context) if PluginCapabilities.ACTIONS in plugin.capabilities else None
         plugin_hooks: Hooks|None = plugin.construct_hooks(plugin_context) if PluginCapabilities.HOOKS in plugin.capabilities else None
@@ -120,18 +121,18 @@ def load_plugin(plugin: Plugin, source_loc: SourceLocation, state: ExecutionStat
         setattr(config_attach_point, plugin_name, plugin_context.plugin_config)
 
         if plugin_actions:
-            plugin_actions.set_plugin_config(plugin_context.plugin_config)
+            plugin_actions.set_plugin_config_and_log(plugin_context.plugin_config, plugin_context.log)
             core_state.actions.merge(plugin_actions)
 
         core_state.loaded_plugins[plugin.name] = plugin
 
         if plugin_hooks:
-            hooks_context = HooksContext(state=state, root_config=state.root_config, plugin_config=plugin_context.plugin_config, hooks=plugin_hooks, log=state.log)
+            hooks_context = HooksContext(state=state, root_config=state.root_config, plugin_config=plugin_context.plugin_config, hooks=plugin_hooks, log=plugin_context.log)
             plugin_hooks.on_plugin_loaded(hooks_context)
             core_state.hooks_distributor.add_hooks(hooks_context)
     except Exception as ex:
         state.log.error("load-plugin-exception", f"exception while loading plugin '{plugin.name}': {repr(ex)}", source_loc)
-        state.log.logger.debug(ex, exc_info=True)
+        state.log.debug_exception(ex)
 
 def load_plugin_by_name(plugin_name: str, source_loc: SourceLocation, state: ExecutionState) -> None:
     core_state = get_private_core_state(state)
@@ -217,14 +218,15 @@ def responder_new(name: str, raw_args: str, context: ActionContext) -> None|str|
     if plugin := core_state.loaded_plugins.get(plugin_name, None):
         if PluginCapabilities.RESPONDER in plugin.capabilities:
             plugin_config = get_subobject(context.root_config.plugins, plugin_name, None)
+            plugin_log = ScopedDiagnosticsLogger(sink=context.state.log, scopes=(plugin.name,))
             plugin_context = PluginContext(
                     state=context.state, plugin_name=plugin_name,
-                    root_config=context.root_config, plugin_config=plugin_config, log=context.log)
+                    root_config=context.root_config, plugin_config=plugin_config, log=plugin_log)
             if responder := plugin.construct_responder(plugin_context):
                 responder_context = ResponderContext(
                         state=context.state, plugin_name=plugin_name,
                         root_config=context.root_config, plugin_config=plugin_config, responder_config=None,
-                        responder_name=responder_name, responder=responder, log=context.log)
+                        responder_name=responder_name, responder=responder, log=plugin_context.log)
                 responder_context.responder_config = setup_newly_constructed_config(responder.construct_configuration(responder_context), empty_factory=EmptyResponderConfiguration, root_config=context.root_config, log=context.log)
                 core_state.responder_contexts[responder_name] = responder_context
                 setattr(context.root_config.responders, responder_name, responder_context.responder_config)

prapti/core/command_interpreter.py

@@ -30,7 +30,8 @@ def run_action(has_exclamation: bool, action_name: str, raw_args: str, source_lo
                 state.log.error("excl-only-action-without-excl", f"didn't run action '{action_name}'. action is !-only but written without a '!'", source_loc)
                 return None
 
-            context = ActionContext(state=state, root_config=state.root_config, plugin_config=action.plugin_config, source_loc=source_loc, log=state.log)
+            action_log = action.plugin_log if action.plugin_log else state.log
+            context = ActionContext(state=state, root_config=state.root_config, plugin_config=action.plugin_config, source_loc=source_loc, log=action_log)
             return action.function(action_name, raw_args, context)
         case _:
             alternatives = _join_alternatives([action.qualified_name for action in matches])

prapti/core/execution_state.py

@@ -2,7 +2,7 @@
 from dataclasses import dataclass, field
 import pathlib
 
-from .logger import DiagnosticsLogger
+from .logger import RootDiagnosticsLogger
 from .configuration import RootConfiguration
 from .command_message import Message
 
@@ -14,7 +14,7 @@ class ExecutionState:
     """
     prapti_version: str
     argv: list[str]
-    log: DiagnosticsLogger
+    log: RootDiagnosticsLogger
     input_file_path: pathlib.Path
     user_prapti_config_dir: pathlib.Path|None = None # typically ~/.config/prapti but other locations are possible
     prapticonfig_dirs: list[pathlib.Path] = field(default_factory=list)

prapti/core/load_configuration.py

@@ -36,7 +36,7 @@ def load_config_file(config_path: pathlib.Path, state: ExecutionState) -> bool:
             parse_messages_and_interpret_commands(config_file_lines, config_path, state)
         except Exception as ex:
             state.log.error("config-file-exception", f"exception while loading configuration file: {repr(ex)}", config_path)
-            state.log.logger.debug(ex, exc_info=True)
+            state.log.debug_exception(ex)
         return True
     return False
 
@@ -117,7 +117,7 @@ def locate_and_parse_in_tree_prapticonfig_md_files(state: ExecutionState) -> tup
                 message_sequence = parse_messages(config_file_lines, config_path)
             except Exception as ex:
                 state.log.error("read-config-file-exception", f"exception while reading configuration file: {repr(ex)}", config_path)
-                state.log.logger.debug(ex, exc_info=True)
+                state.log.debug_exception(ex)
         prapticonfig_mds.append((config_path, message_sequence))
         if message_sequence and is_config_root(message_sequence): # stop iterating once we hit a config file with `%config_root = true`
             break
@@ -138,7 +138,7 @@ def execute_in_tree_prapticonfig_md_files(prapticonfig_mds: list[tuple[pathlib.P
                 state.root_config.prapti.config_root = False
             except Exception as ex:
                 state.log.error("load-config-file-exception", f"exception while loading configuration file: {repr(ex)}", config_path)
-                state.log.logger.debug(ex, exc_info=True)
+                state.log.debug_exception(ex)
 
 def default_load_config_files(state: ExecutionState):
     """Default configuration loading. Load configuration from:

prapti/core/logger.py

@@ -24,6 +24,7 @@
 import logging
 import pathlib
 import sys
+import abc
 from .source_location import SourceLocation
 
 # Add HINT and DETAIL logging levels, without monkey patching anything.
@@ -58,7 +59,46 @@ def add_logging_level(level: int, name: str, lower_bound: int, upper_bound: int)
     'DEBUG': logging.DEBUG,
 }
 
-class DiagnosticsLogger:
+class DiagnosticsLogger(metaclass=abc.ABCMeta):
+    """Ergonomic facade for logging compiler-style diagnostic messages."""
+    @abc.abstractmethod
+    def critical(self, msg_id_or_msg: str, *msg_and_or_extras, **kwextras):
+        pass
+
+    @abc.abstractmethod
+    def error(self, msg_id_or_msg: str, *msg_and_or_extras, **kwextras):
+        pass
+
+    @abc.abstractmethod
+    def warning(self, msg_id_or_msg: str, *msg_and_or_extras, **kwextras):
+        pass
+
+    @abc.abstractmethod
+    def hint(self, msg_id_or_msg: str, *msg_and_or_extras, **kwextras):
+        pass
+
+    @abc.abstractmethod
+    def info(self, msg_id_or_msg: str, *msg_and_or_extras, **kwextras):
+        pass
+
+    @abc.abstractmethod
+    def detail(self, msg_id_or_msg: str, *msg_and_or_extras, **kwextras):
+        pass
+
+    @abc.abstractmethod
+    def debug(self, msg_id_or_msg: str, *msg_and_or_extras, **kwextras):
+        pass
+
+    @abc.abstractmethod
+    def error_exception(self, ex: BaseException):
+        pass
+
+    @abc.abstractmethod
+    def debug_exception(self, ex: BaseException):
+        pass
+
+
+class RootDiagnosticsLogger(DiagnosticsLogger):
     """Ergonomic facade for logging compiler-style diagnostic messages.
     - Requires message ids for INFO and above.
     - Supports a range of source location arguments.
@@ -86,7 +126,7 @@ def _decode_extras(self, extras_dict: dict[str, Any], extras: tuple[Any, ...], k
             - source_line # 1-based
             - source_column # 1-based
         """
-        file_path, line, column = None, None, None
+        file_path, line, column, scopes = None, None, None, None
 
         for obj in extras:
             if isinstance(obj, SourceLocation):
@@ -103,6 +143,8 @@ def _decode_extras(self, extras_dict: dict[str, Any], extras: tuple[Any, ...], k
                 line = value
             elif name == "column":
                 column = value
+            elif name == "scopes":
+                scopes = value
             else:
                 assert False, f"unrecognised keyword extra log argument {name} = {repr(value)}"
 
@@ -112,6 +154,8 @@ def _decode_extras(self, extras_dict: dict[str, Any], extras: tuple[Any, ...], k
             extras_dict['source_line'] = line
         if column is not None:
             extras_dict['source_column'] = column
+        if scopes is not None:
+            extras_dict['scopes'] = scopes
 
     def _make_extra(self, message_id, extras: tuple[Any, ...], kwextras: dict[str, Any]) -> dict[str, Any]:
         extras_dict: dict[str, Any] = {'message_id': message_id}
@@ -170,6 +214,53 @@ def detail(self, msg_id_or_msg: str, *msg_and_or_extras, **kwextras):
     def debug(self, msg_id_or_msg: str, *msg_and_or_extras, **kwextras):
         self._log(logging.DEBUG, msg_id_or_msg, msg_and_or_extras, kwextras)
 
+    def error_exception(self, ex: BaseException):
+        self.logger.error(ex, exc_info=True)
+
+    def debug_exception(self, ex: BaseException):
+        self.logger.debug(ex, exc_info=True)
+
+
+class ScopedDiagnosticsLogger(DiagnosticsLogger):
+    """decorator/wrapper logger that prepends scopes to log messages"""
+    def __init__(self, sink: DiagnosticsLogger, scopes: tuple[str,...]|str):
+        self.sink = sink
+        self.scopes = scopes if isinstance(scopes, tuple) else (scopes,)
+
+    def _add_scopes(self, kwextras: dict[str, Any]) -> dict[str, Any]:
+        if "scopes" in kwextras:
+            kwextras["scopes"] = self.scopes +  kwextras["scopes"]
+        else:
+            kwextras["scopes"] = self.scopes
+        return kwextras
+
+    def critical(self, msg_id_or_msg: str, *msg_and_or_extras, **kwextras):
+        self.sink.critical(msg_id_or_msg, *msg_and_or_extras, **self._add_scopes(kwextras))
+
+    def error(self, msg_id_or_msg: str, *msg_and_or_extras, **kwextras):
+        self.sink.error(msg_id_or_msg, *msg_and_or_extras, **self._add_scopes(kwextras))
+
+    def warning(self, msg_id_or_msg: str, *msg_and_or_extras, **kwextras):
+        self.sink.warning(msg_id_or_msg, *msg_and_or_extras, **self._add_scopes(kwextras))
+
+    def hint(self, msg_id_or_msg: str, *msg_and_or_extras, **kwextras):
+        self.sink.hint(msg_id_or_msg, *msg_and_or_extras, **self._add_scopes(kwextras))
+
+    def info(self, msg_id_or_msg: str, *msg_and_or_extras, **kwextras):
+        self.sink.info(msg_id_or_msg, *msg_and_or_extras, **self._add_scopes(kwextras))
+
+    def detail(self, msg_id_or_msg: str, *msg_and_or_extras, **kwextras):
+        self.sink.detail(msg_id_or_msg, *msg_and_or_extras, **self._add_scopes(kwextras))
+
+    def debug(self, msg_id_or_msg: str, *msg_and_or_extras, **kwextras):
+        self.sink.debug(msg_id_or_msg, *msg_and_or_extras, **self._add_scopes(kwextras))
+
+    def error_exception(self, ex: BaseException):
+        self.sink.error_exception(ex)
+
+    def debug_exception(self, ex: BaseException):
+        self.sink.debug_exception(ex)
+
 
 class DiagnosticRecordFormatter(logging.Formatter):
     """Format log messages in a compiler-like format for console display."""
@@ -192,15 +283,16 @@ def formatMessage(self, record) -> str:
             message_id= None
 
         message = record.__dict__['message']
+        scopes = record.__dict__.get('scopes', tuple())
 
         # filename:ln:col: level: [message_id]: ... message goes here ...
         if message:
-            return ": ".join(s for s in (source_location_str, levelname, message_id, message) if s)
+            return ": ".join(s for s in (source_location_str, levelname, message_id) + scopes + (message,) if s)
         else:
-            return ": ".join(s for s in (source_location_str, levelname, message_id) if s) + ":"
+            return ": ".join(s for s in (source_location_str, levelname, message_id) + scopes if s) + ":"
 
 
-def create_diagnostics_logger(initial_level=logging.DEBUG) -> DiagnosticsLogger:
+def create_root_diagnostics_logger(initial_level=logging.DEBUG) -> RootDiagnosticsLogger:
     logger = logging.getLogger(name='prapti')
     logger.setLevel(initial_level)
     if not logger.handlers:
@@ -210,4 +302,4 @@ def create_diagnostics_logger(initial_level=logging.DEBUG) -> DiagnosticsLogger:
         stream_handler.setFormatter(formatter)
         logger.addHandler(stream_handler)
 
-    return DiagnosticsLogger(logger=logger)
+    return RootDiagnosticsLogger(logger=logger)

prapti/plugins/capture_everything.py

@@ -112,7 +112,7 @@ def on_response_completed(self, context: HooksContext):
             return
 
         if not self._capture_file_name:
-            context.log.error("bad-capture-file-name", "prapti.capture_everything: skipping capture. no capture file name.")
+            context.log.error("bad-capture-file-name", "skipping capture. no capture file name.")
             return
 
         self._end_time = datetime.now()
@@ -145,9 +145,9 @@ def on_response_completed(self, context: HooksContext):
                 with capture_file_path.open("w") as file:
                     json.dump(self._capture_data, file)
             else:
-                context.log.error("bad-capture-dir", f"prapti.capture_everything: skipping capture. capture directory '{capture_dir}' does not exist or is not a directory")
+                context.log.error("bad-capture-dir", f"skipping capture. capture directory '{capture_dir}' does not exist or is not a directory")
         else:
-            context.log.warning("capture-dir-not-set", "prapti.capture_everything: plugin is loaded but capture directory has not been set. add '% prapti.plugins.capture_everything.capture_dir = ... to your config.")
+            context.log.warning("capture-dir-not-set", "plugin is loaded but capture directory has not been set. add '% prapti.plugins.capture_everything.capture_dir = ... to your config.")
 
 class CaptureEverythingPlugin(Plugin):
     def __init__(self):