feat: add log content metadata to log records (#175)

* feat: add log content metadata to log records

Signed-off-by: Samuel Anderson <119458760+AWS-Samuel@users.noreply.github.com>

* chore: reword log message to be more clear

Signed-off-by: Samuel Anderson <119458760+AWS-Samuel@users.noreply.github.com>

---------

Signed-off-by: Samuel Anderson <119458760+AWS-Samuel@users.noreply.github.com>

hatch_version_hook.py

@@ -102,7 +102,7 @@ def _prepare(self) -> bool:
             opt for opt in self.REQUIRED_OPTS if opt not in self.config or not self.config[opt]
         ]
         if missing_required_opts:
-            _logger.warn(
+            _logger.warning(
                 f"Required options {missing_required_opts} are missing or empty. "
                 "Contining without copying sources to destinations...",
                 file=sys.stderr,

src/openjd/sessions/_action_filter.py

@@ -8,7 +8,7 @@
 from enum import Enum
 from typing import Any, Callable
 
-from ._logging import LOG
+from ._logging import LOG, LogContent, LogExtraInfo
 
 __all__ = ("ActionMessageKind", "ActionMonitoringFilter")
 
@@ -155,14 +155,18 @@ def filter(self, record: logging.LogRecord) -> bool:
                 # The only way that this happens is if filter_matcher is constructed incorrectly.
                 all_matched_groups = ",".join(k for k in matched_named_groups)
                 LOG.error(
-                    f"Open Job Description: Malformed output stream filter matched multiple kinds ({all_matched_groups})"
+                    f"Open Job Description: Malformed output stream filter matched multiple kinds ({all_matched_groups})",
+                    extra=LogExtraInfo(openjd_log_content=LogContent.COMMAND_OUTPUT),
                 )
                 return True
             message_kind = ActionMessageKind(matched_named_groups[0])
             try:
                 handler = self._internal_handlers[message_kind]
             except KeyError:
-                LOG.error(f"Open Job Description: Unhandled message kind ({message_kind.value})")
+                LOG.error(
+                    f"Open Job Description: Unhandled message kind ({message_kind.value})",
+                    extra=LogExtraInfo(openjd_log_content=LogContent.COMMAND_OUTPUT),
+                )
                 return True
             try:
                 handler(message)

src/openjd/sessions/_embedded_files.py

@@ -15,7 +15,7 @@
 from openjd.model.v2023_09 import (
     ValueReferenceConstants as ValueReferenceConstants_2023_09,
 )
-from ._logging import LoggerAdapter
+from ._logging import LoggerAdapter, LogExtraInfo, LogContent
 from ._session_user import PosixSessionUser, SessionUser, WindowsSessionUser
 from ._types import EmbeddedFilesListType, EmbeddedFileType
 
@@ -148,7 +148,12 @@ def materialize(self, files: EmbeddedFilesListType, symtab: SymbolTable) -> None
             # Add symbols to the symbol table
             for record in records:
                 symtab[record.symbol] = str(record.filename)
-                self._logger.info(f"Mapping: {record.symbol} -> {record.filename}")
+                self._logger.info(
+                    f"Mapping: {record.symbol} -> {record.filename}",
+                    extra=LogExtraInfo(
+                        openjd_log_content=LogContent.FILE_PATH | LogContent.PARAMETER_INFO
+                    ),
+                )
 
             # Write the files to disk.
             for record in records:
@@ -225,5 +230,10 @@ def _materialize_file(
         # Create the file as r/w owner, and optionally group
         write_file_for_user(filename, data, self._user, additional_permissions=execute_permissions)
 
-        self._logger.info(f"Wrote: {file.name} -> {str(filename)}")
-        self._logger.debug("Contents:\n%s", data)
+        self._logger.info(
+            f"Wrote: {file.name} -> {str(filename)}",
+            extra=LogExtraInfo(openjd_log_content=LogContent.FILE_PATH),
+        )
+        self._logger.debug(
+            "Contents:\n%s", data, extra=LogExtraInfo(openjd_log_content=LogContent.FILE_CONTENTS)
+        )

src/openjd/sessions/_logging.py

@@ -75,15 +75,17 @@ def process(
 """
 LOG.setLevel(logging.INFO)
 
+_banner_log_extra = LogExtraInfo(openjd_log_content=LogContent.BANNER)
+
 
 def log_section_banner(logger: LoggerAdapter, section_title: str) -> None:
     logger.info("")
-    logger.info("==============================================")
-    logger.info(f"--------- {section_title}")
-    logger.info("==============================================")
+    logger.info("==============================================", extra=_banner_log_extra)
+    logger.info(f"--------- {section_title}", extra=_banner_log_extra)
+    logger.info("==============================================", extra=_banner_log_extra)
 
 
 def log_subsection_banner(logger: LoggerAdapter, section_title: str) -> None:
-    logger.info("----------------------------------------------")
-    logger.info(section_title)
-    logger.info("----------------------------------------------")
+    logger.info("----------------------------------------------", extra=_banner_log_extra)
+    logger.info(section_title, extra=_banner_log_extra)
+    logger.info("----------------------------------------------", extra=_banner_log_extra)

src/openjd/sessions/_runner_base.py

@@ -19,7 +19,7 @@
 from openjd.model import FormatStringError
 from openjd.model.v2023_09 import Action as Action_2023_09
 from ._embedded_files import EmbeddedFiles, EmbeddedFilesScope, write_file_for_user
-from ._logging import log_subsection_banner, LoggerAdapter
+from ._logging import log_subsection_banner, LoggerAdapter, LogContent, LogExtraInfo
 from ._os_checker import is_posix
 from ._session_user import SessionUser
 from ._subprocess import LoggingSubprocess
@@ -316,7 +316,12 @@ def _run(self, args: Sequence[str], time_limit: Optional[timedelta] = None) -> N
                     user=self._user,
                     additional_permissions=stat.S_IXUSR | stat.S_IXGRP,
                 )
-                self._logger.debug(f"Wrote the following script to {filename}:\n{script}")
+                self._logger.debug(
+                    f"Wrote the following script to {filename}:\n{script}",
+                    extra=LogExtraInfo(
+                        openjd_log_content=LogContent.FILE_PATH | LogContent.FILE_CONTENTS
+                    ),
+                )
             else:
                 try:
                     args = locate_windows_executable(
@@ -325,7 +330,10 @@ def _run(self, args: Sequence[str], time_limit: Optional[timedelta] = None) -> N
                 except RuntimeError as e:
                     # Make use of the action filter to surface the failure reason to
                     # the customer.
-                    self._logger.info(f"openjd_fail: {str(e)}")
+                    self._logger.info(
+                        f"openjd_fail: {str(e)}",
+                        extra=LogExtraInfo(openjd_log_content=LogContent.EXCEPTION_INFO),
+                    )
                     self._state_override = ScriptRunnerState.FAILED
                     # We haven't started the future yet that runs the process,
                     # but the Session still needs to know that the action is over.
@@ -418,7 +426,10 @@ def _materialize_files(
             # Surface the error.
             # Make use of the action filter to surface the failure reason to
             # the customer.
-            self._logger.info(f"openjd_fail: {str(exc)}")
+            self._logger.info(
+                f"openjd_fail: {str(exc)}",
+                extra=LogExtraInfo(openjd_log_content=LogContent.EXCEPTION_INFO),
+            )
             self._state_override = ScriptRunnerState.FAILED
             # We haven't started the future yet that runs the process,
             # but the Session still needs to know that the action is over.
@@ -435,7 +446,10 @@ def _run_action(self, action: ActionModel, symtab: SymbolTable) -> None:
         except FormatStringError as exc:
             # Extremely unlikely since a JobTemplate needs to have passed
             # validation before we could be running it, but just to be safe.
-            self._logger.info(f"openjd_fail: {str(exc)}")
+            self._logger.info(
+                f"openjd_fail: {str(exc)}",
+                extra=LogExtraInfo(openjd_log_content=LogContent.EXCEPTION_INFO),
+            )
             self._state_override = ScriptRunnerState.FAILED
             # We haven't started the future yet that runs the process,
             # but the Session still needs to know that the action is over.
@@ -472,18 +486,24 @@ def _cancel(
 
             if isinstance(method, TerminateCancelMethod):
                 self._logger.info(
-                    f"Canceling subprocess {str(self._process.pid)} via termination method at {now_str}."
+                    f"Canceling subprocess {str(self._process.pid)} via termination method at {now_str}.",
+                    extra=LogExtraInfo(openjd_log_content=LogContent.PROCESS_CONTROL),
                 )
                 try:
                     self._process.terminate()
                 except OSError as err:  # pragma: nocover
                     # Being paranoid. Won't happen... if we could start the process, then we can send it a signal
-                    self._logger.warn(
-                        f"Cancelation could not send terminate signal to process {self._process.pid}: {str(err)}"
+                    self._logger.warning(
+                        f"Cancelation could not send terminate signal to process {self._process.pid}: {str(err)}",
+                        extra=LogExtraInfo(
+                            openjd_log_content=LogContent.PROCESS_CONTROL
+                            | LogContent.EXCEPTION_INFO
+                        ),
                     )
             else:
                 self._logger.info(
-                    f"Canceling subprocess {str(self._process.pid)} via notify then terminate method at {now_str}."
+                    f"Canceling subprocess {str(self._process.pid)} via notify then terminate method at {now_str}.",
+                    extra=LogExtraInfo(openjd_log_content=LogContent.PROCESS_CONTROL),
                 )
                 method = cast(NotifyCancelMethod, method)
 
@@ -510,15 +530,22 @@ def _cancel(
                 write_file_for_user(
                     self._session_working_directory / "cancel_info.json", notify_end, self._user
                 )
-                self._logger.info(f"Grace period ends at {grace_end_time_str}")
+                self._logger.info(
+                    f"Grace period ends at {grace_end_time_str}",
+                    extra=LogExtraInfo(openjd_log_content=LogContent.PROCESS_CONTROL),
+                )
 
                 # 2) Send the notify
                 try:
                     self._process.notify()
                 except OSError as err:  # pragma: nocover
                     # Being paranoid. Won't happen... if we could start the process, then we can send it a signal
-                    self._logger.warn(
-                        f"Cancelation could not send notify signal to process {self._process.pid}: {str(err)}"
+                    self._logger.warning(
+                        f"Cancelation could not send notify signal to process {self._process.pid}: {str(err)}",
+                        extra=LogExtraInfo(
+                            openjd_log_content=LogContent.PROCESS_CONTROL
+                            | LogContent.EXCEPTION_INFO
+                        ),
                     )
 
                 # 4) Set up the timer to send the terminate signal
@@ -540,7 +567,12 @@ def _on_process_exit(self, future: Future) -> None:
                 self._cancel_gracetime_timer = None
 
             if exc := self._run_future.exception():
-                self._logger.error(f"Error running subprocess: {str(exc)}")
+                self._logger.error(
+                    f"Error running subprocess: {str(exc)}",
+                    extra=LogExtraInfo(
+                        openjd_log_content=LogContent.PROCESS_CONTROL | LogContent.EXCEPTION_INFO
+                    ),
+                )
 
             if self._callback is not None:
                 self._callback(ActionState(self.state.value))
@@ -555,13 +587,17 @@ def _on_notify_period_end(self) -> None:
         self._logger.info(
             "Notify period ended. Terminate at %s",
             datetime.utcnow().strftime(TIME_FORMAT_STR),
+            extra=LogExtraInfo(openjd_log_content=LogContent.PROCESS_CONTROL),
         )
         try:
             self._process.terminate()
         except OSError as err:  # pragma: nocover
             # Being paranoid. Won't happen... if we could start the process, then we can send it a kill signal
-            self._logger.warn(
-                f"Cancelation could not send terminate signal to process {self._process.pid}: {str(err)}"
+            self._logger.warning(
+                f"Cancelation could not send terminate signal to process {self._process.pid}: {str(err)}",
+                extra=LogExtraInfo(
+                    openjd_log_content=LogContent.PROCESS_CONTROL | LogContent.EXCEPTION_INFO
+                ),
             )
 
     def _on_timelimit(self) -> None:
@@ -573,6 +609,7 @@ def _on_timelimit(self) -> None:
         self._logger.info(
             "TIMEOUT - Runtime limit reached at %s. Canceling action.",
             datetime.utcnow().strftime(TIME_FORMAT_STR),
+            extra=LogExtraInfo(openjd_log_content=LogContent.PROCESS_CONTROL),
         )
         self._runtime_limit_reached = True
         self.cancel()

src/openjd/sessions/_session.py

@@ -30,7 +30,7 @@
 )
 from ._action_filter import ActionMessageKind, ActionMonitoringFilter
 from ._embedded_files import write_file_for_user
-from ._logging import LOG, log_section_banner, LoggerAdapter
+from ._logging import LOG, log_section_banner, LoggerAdapter, LogExtraInfo, LogContent
 from ._os_checker import is_posix, is_windows
 from ._path_mapping import PathMappingRule
 from ._runner_base import ScriptRunnerBase
@@ -396,24 +396,40 @@ def __init__(
         LOG.addFilter(self._log_filter)
         self._logger = LoggerAdapter(LOG, extra={"session_id": self._session_id})
 
-        self._logger.info(f"openjd.model Library Version: {model_version}")
-        self._logger.info(f"openjd.sessions Library Version: {version}")
-        self._logger.info("Installed at: %s", str(Path(__file__).resolve().parent.parent))
-        self._logger.info(f"Python Interpreter: {sys.executable}")
-        self._logger.info("Python Version: %s", sys.version.replace("\n", " - "))
-        self._logger.info(f"Platform: {sys.platform}")
+        host_info_extra = LogExtraInfo(openjd_log_content=LogContent.HOST_INFO)
+        self._logger.info(f"openjd.model Library Version: {model_version}", extra=host_info_extra)
+        self._logger.info(f"openjd.sessions Library Version: {version}", extra=host_info_extra)
+        self._logger.info(
+            "Installed at: %s", str(Path(__file__).resolve().parent.parent), extra=host_info_extra
+        )
+        self._logger.info(f"Python Interpreter: {sys.executable}", extra=host_info_extra)
+        self._logger.info(
+            "Python Version: %s", sys.version.replace("\n", " - "), extra=host_info_extra
+        )
+        self._logger.info(f"Platform: {sys.platform}", extra=host_info_extra)
         self._logger.info(f"Initializing Open Job Description Session: {self._session_id}")
 
         try:
             self._working_dir = self._create_working_directory()
             self._files_dir = self._create_files_directory()
         except RuntimeError as exc:
-            self._logger.error(f"ERROR creating Session Working Directory: {str(exc)}")
+            self._logger.error(
+                f"ERROR creating Session Working Directory: {str(exc)}",
+                extra=LogExtraInfo(
+                    openjd_log_content=LogContent.COMMAND_OUTPUT | LogContent.FILE_PATH
+                ),
+            )
             self._state = SessionState.ENDED
             raise
 
-        self._logger.info(f"Session Working Directory: {str(self.working_directory)}")
-        self._logger.info(f"Session's Embedded Files Directory: {str(self.files_directory)}")
+        self._logger.info(
+            f"Session Working Directory: {str(self.working_directory)}",
+            extra=LogExtraInfo(openjd_log_content=LogContent.FILE_PATH),
+        )
+        self._logger.info(
+            f"Session's Embedded Files Directory: {str(self.files_directory)}",
+            extra=LogExtraInfo(openjd_log_content=LogContent.FILE_PATH),
+        )
 
         self._state = SessionState.READY
 
@@ -424,7 +440,10 @@ def cleanup(self) -> None:
         self._cleanup_called = True
         if self._working_dir is not None and not self._retain_working_dir:
             log_section_banner(self._logger, "Session Cleanup")
-            self._logger.info(f"Deleting working directory: {str(self.working_directory)}")
+            self._logger.info(
+                f"Deleting working directory: {str(self.working_directory)}",
+                extra=LogExtraInfo(openjd_log_content=LogContent.FILE_PATH),
+            )
             try:
                 # If running as a different user, then that user could have written files to the
                 # session diretory that make removing it as our user impossible. So, do a 2-phase
@@ -461,7 +480,12 @@ def cleanup(self) -> None:
                 self._working_dir.cleanup()
             except RuntimeError as exc:
                 # Warn if we couldn't cleanup the temporary files for some reason.
-                self._logger.exception(exc)
+                self._logger.exception(
+                    exc,
+                    extra=LogExtraInfo(
+                        openjd_log_content=LogContent.EXCEPTION_INFO | LogContent.FILE_PATH
+                    ),
+                )
 
         LOG.removeFilter(self._log_filter)
         del self._log_filter
@@ -612,7 +636,12 @@ def enter_environment(
                 symtab, environment.variables
             )
             for name, value in resolved_variables.items():
-                self._logger.info("Setting: %s=%s", name, value)
+                self._logger.info(
+                    "Setting: %s=%s",
+                    name,
+                    value,
+                    extra=LogExtraInfo(openjd_log_content=LogContent.PARAMETER_INFO),
+                )
             env_var_changes = SimplifiedEnvironmentVariableChanges(resolved_variables)
             self._created_env_vars[identifier] = env_var_changes
         else:
@@ -753,9 +782,15 @@ def run_task(
 
         log_section_banner(self._logger, "Running Task")
         if task_parameter_values:
-            self._logger.info("Parameter values:")
+            self._logger.info(
+                "Parameter values:",
+                extra=LogExtraInfo(openjd_log_content=LogContent.PARAMETER_INFO),
+            )
             for name, value in task_parameter_values.items():
-                self._logger.info(f"{name}({str(value.type.value)}) = {value.value}")
+                self._logger.info(
+                    f"{name}({str(value.type.value)}) = {value.value}",
+                    extra=LogExtraInfo(openjd_log_content=LogContent.PARAMETER_INFO),
+                )
 
         self._reset_action_state()
         symtab = self._symbol_table(step_script.revision, task_parameter_values)
@@ -879,7 +914,10 @@ def _create_working_directory(self) -> TempDir:
                     parent_stat.st_mode & stat.S_ISVTX
                 ) == 0:
                     self._logger.warning(
-                        f"Sticky bit is not set on {str(parent)}. This may pose a risk when running work on this host as users may modify or delete files in this directory which do not belong to them."
+                        f"Sticky bit is not set on {str(parent)}. This may pose a risk when running work on this host as users may modify or delete files in this directory which do not belong to them.",
+                        extra=LogExtraInfo(
+                            openjd_log_content=LogContent.HOST_INFO | LogContent.FILE_PATH
+                        ),
                     )
 
         # Raises: RuntimeError