Log failing cleanups as warnings

(See `fable-review-pr431-2026-07-05.md::P13` in #5)

line_profiler/_child_process_profiling/_cache_logging.py
    TIMESTAMP_PATTERN
        Added formatting field `level`
    add_timestamp()
        Added optional argument `level`
    CacheLoggingEntry
        .__doc__
            Updated instantiations in doctest
        .level
            New field (2nd item)
        .to_text(), .from_text(), .write()
            Added handling of the `.level` field
        .new()
            Added optional argument `level`

line_profiler/_child_process_profiling/cache.py::LineProfilingCache
    _debug_output()
        - Added optional argument `level` in keeping with the base class
        - Moved implementation of `._make_debug_entry` (used nowhere
          else) inside
    _setup_in_child_process()
        Updated patching of `CuratedProfilerContext._debug_output`
    _make_debug_entry
        Removed

line_profiler/cleanup.py::Cleanup
    _debug_output()
        Added optional argument `level` for setting the logging level
    _cleanup()
        If a callback fails, it is now logged with `Logger.warning()`
        instead of `Logger.debug()`

Author: TTsangSC

line_profiler/_child_process_profiling/_cache_logging.py

@@ -7,6 +7,7 @@
 import re
 from collections.abc import Generator
 from datetime import datetime
+from enum import auto
 from itertools import pairwise
 from pathlib import Path
 from string import Formatter as StringParser
@@ -15,14 +16,13 @@
 from typing_extensions import Self
 
 from .. import _diagnostics as diagnostics
-from ..line_profiler_utils import block_indent
+from ..line_profiler_utils import block_indent, StringEnum
 
 
 __all__ = ('CacheLoggingEntry',)
 
-
 FILENAME_PATTERN = 'debug_log_{main_pid}_{current_pid}.log'
-TIMESTAMP_PATTERN = '[cache-debug-log {timestamp} DEBUG]'
+TIMESTAMP_PATTERN = '[cache-debug-log {timestamp} {level}]'
 HEADER_PATTERN = 'PID {current_pid} ({main_pid}): Cache {obj_id:#x}'
 
 TIMESTAMP_FORMAT = '%Y-%m-%d %H:%M:%S'
@@ -34,6 +34,14 @@
 HEADER_MAIN_INDICATOR = 'main process'
 
 
+class LogLevel(StringEnum):
+    DEBUG = auto()
+    INFO = auto()
+    WARNING = auto()
+    ERROR = auto()
+    CRITICAL = auto()
+
+
 def get_logger_header(current_pid: int, main_pid: int, obj_id: int) -> str:
     """
     Returns:
@@ -88,7 +96,11 @@ def parse_timestamp(ts: str) -> datetime:
     return datetime.strptime(ts, parse_format)
 
 
-def add_timestamp(msg: str, timestamp: datetime | None = None) -> str:
+def add_timestamp(
+    msg: str,
+    timestamp: datetime | None = None,
+    level: str | LogLevel = LogLevel.DEBUG,
+) -> str:
     """
     Returns:
         msg_with_timestamp (str):
@@ -99,6 +111,7 @@ def add_timestamp(msg: str, timestamp: datetime | None = None) -> str:
         timestamp = datetime.now()
     ts_formatted = TIMESTAMP_PATTERN.format(
         timestamp=format_timestamp(timestamp),
+        level=str(level).upper(),
     )
     return block_indent(msg, ts_formatted + TIMESTAMP_SPACING)
 
@@ -205,6 +218,7 @@ class CacheLoggingEntry(NamedTuple):
         >>>
         >>> entry = CacheLoggingEntry(
         ...     datetime(1900, 1, 1, 0, 0, 0, 0),
+        ...     LogLevel.DEBUG,
         ...     12345,
         ...     12345,
         ...     12345678,
@@ -217,13 +231,14 @@ class CacheLoggingEntry(NamedTuple):
 multiple lines
         >>> another_entry = CacheLoggingEntry(
         ...     datetime(2000, 12, 31, 12, 34, 56, 789000),
+        ...     LogLevel.INFO,
         ...     12345,
         ...     54321,
         ...     87654321,
         ...     'FOO BAR BAZ',
         ... )
         >>> print(another_entry.to_text())
-        [cache-debug-log 2000-12-31 12:34:56,789 DEBUG] PID 54321 \
+        [cache-debug-log 2000-12-31 12:34:56,789 INFO] PID 54321 \
 (12345): Cache 0x5397fb1: FOO BAR BAZ
         >>> log_text = '\\n'.join([
         ...     e.to_text() for e in [entry, another_entry]
@@ -233,30 +248,46 @@ class CacheLoggingEntry(NamedTuple):
         ... ]
     """
     timestamp: datetime
+    level: LogLevel
     main_pid: int
     current_pid: int
     cache_id: int
     msg: str
 
     def to_text(self) -> str:
-        return add_timestamp(self._get_header() + self.msg, self.timestamp)
+        return add_timestamp(
+            self._get_header() + self.msg, self.timestamp, self.level,
+        )
 
     def _get_header(self) -> str:
         return get_logger_header(
             self.current_pid, self.main_pid, self.cache_id,
         ) + HEADER_SEP
 
     def write(self, tee: os.PathLike[str] | str | None = None) -> None:
+        """
+        Write the log message using
+        :py:mod:`line_profiler._diagnostics.log`. If ``tee`` is a path,
+        also tee thereto with an appropriate timestamp.
+        """
         log_msg = self._get_header() + self.msg
-        diagnostics.log.debug(log_msg)
+        log_func = getattr(diagnostics.log, self.level.lower())
+        log_func(log_msg)
         if tee is None:
             return
         with Path(tee).open(mode='a') as fobj:
-            print(add_timestamp(log_msg, self.timestamp), file=fobj)
+            full_msg = add_timestamp(log_msg, self.timestamp, self.level)
+            print(full_msg, file=fobj)
 
     @classmethod
-    def new(cls, main_pid: int, cache_id: int, msg: str) -> Self:
-        return cls(datetime.now(), main_pid, os.getpid(), cache_id, msg)
+    def new(
+        cls, main_pid: int, cache_id: int, msg: str,
+        level: str | LogLevel = LogLevel.DEBUG,
+    ) -> Self:
+        return cls(
+            datetime.now(), LogLevel(level), main_pid,
+            os.getpid(), cache_id, msg,
+        )
 
     @classmethod
     def from_file(cls, file: os.PathLike[str] | str | TextIO) -> list[Self]:
@@ -286,7 +317,7 @@ def gen_timestamps(text: str) -> Generator[re.Match, None, None]:
                     return
 
         def gen_message_blocks(text: str) -> Generator[
-            tuple[datetime, re.Match, str], None, None
+            tuple[datetime, LogLevel, re.Match, str], None, None
         ]:
             timestamps = list(gen_timestamps(text))
             if not timestamps:
@@ -295,18 +326,22 @@ def gen_message_blocks(text: str) -> Generator[
             # Handle all the entries up till the 2nd-to-last one
             for this_match, next_match in pairwise(timestamps):
                 ts = parse_timestamp(this_match.group('timestamp'))
+                level = LogLevel(this_match.group('level'))
                 text_block = text[this_match.start():next_match.start()]
-                yield (ts, this_match, text_block.rstrip('\n'))
+                yield (ts, level, this_match, text_block.rstrip('\n'))
             # Handle the last entry
             last_match = timestamps[-1]
             yield (
                 parse_timestamp(last_match.group('timestamp')),
+                LogLevel(last_match.group('level')),
                 last_match,
                 text[last_match.start():].rstrip('\n'),
             )
 
         def get_entries(text: str) -> Generator[Self, None, None]:
-            for timestamp, ts_match, text_block in gen_message_blocks(text):
+            for (
+                timestamp, level, ts_match, text_block,
+            ) in gen_message_blocks(text):
                 # Strip the block indent
                 ts_text = ts_match.group(0)
                 assert text_block.startswith(ts_text), (
@@ -326,10 +361,14 @@ def get_entries(text: str) -> Generator[Self, None, None]:
                 cache_id = parse_id(header_match.group('obj_id'))
                 # The rest of the block is the message proper
                 msg = text_block[header_match.end():]
-                yield cls(timestamp, main_pid, current_pid, cache_id, msg)
+                yield cls(
+                    timestamp, level, main_pid, current_pid, cache_id, msg,
+                )
 
         timestamp_pattern = fmt_to_regex(
-            f'{TIMESTAMP_PATTERN}{TIMESTAMP_SPACING}', timestamp='.+?',
+            f'{TIMESTAMP_PATTERN}{TIMESTAMP_SPACING}',
+            timestamp='.+?',
+            level='({})'.format('|'.join(LogLevel.__members__)),
         )
         timestamp_regex = re.compile('^' + timestamp_pattern, re.MULTILINE)
         header_regex = re.compile(fmt_to_regex(

line_profiler/_child_process_profiling/cache.py

@@ -26,7 +26,7 @@
 
 from _line_profiler_hooks import INHERITED_PID_ENV_VARNAME, load_pth_hook
 from .. import _diagnostics as diagnostics
-from ..cleanup import Cleanup, _CALLBACK_REPR_HELPER
+from ..cleanup import Cleanup, LogLevel, _CALLBACK_REPR_HELPER
 from ..curated_profiling import CuratedProfilerContext
 from ..line_profiler import LineProfiler, LineStats
 from ..toml_config import ConfigSource
@@ -371,13 +371,14 @@ def get_pth_config() -> Mapping[str, Any]:
 
         return fpath
 
-    def _debug_output(self, msg: str) -> None:
+    def _debug_output(self, msg: str, /, level: LogLevel = 'debug') -> None:
         """
         Beside writing to the logger, also write to the
         :py:attr:`~._debug_log`.
         """
+        entry = CacheLoggingEntry.new(self.main_pid, id(self), msg, level)
         try:
-            self._make_debug_entry(msg).write(self._debug_log)
+            entry.write(self._debug_log)
         except OSError:  # Cache dir may have been rm-ed during cleanup
             pass
 
@@ -446,9 +447,10 @@ def _setup_in_child_process(
                 calling this function, true otherwise
         """
         def wrap_ctx_debug(
-            ctx: CuratedProfilerContext, msg: str,
+            ctx: CuratedProfilerContext, msg: str, /,
+            level: LogLevel = 'debug',
         ) -> None:
-            self._debug_output(f'  Context {id(ctx):#x}: {msg}')
+            self._debug_output(f'  Context {id(ctx):#x}: {msg}', level)
 
         if not context:
             context = '...'
@@ -820,10 +822,6 @@ def _debug_log(self) -> Path | None:
         )
         return Path(self.cache_dir) / fname
 
-    @cached_property
-    def _make_debug_entry(self) -> Callable[[str], CacheLoggingEntry]:
-        return partial(CacheLoggingEntry.new, self.main_pid, id(self))
-
     @cached_property
     def _consistent_with_loaded_instance(self) -> bool:
         cls = type(self)

line_profiler/cleanup.py

@@ -10,7 +10,7 @@
 from inspect import getattr_static
 from operator import setitem
 from pathlib import Path
-from typing import Any, TypeVar, cast
+from typing import Any, Literal, Protocol, TypeVar, cast, overload
 from typing_extensions import Concatenate, ParamSpec, Self
 
 from .line_profiler_utils import CallbackRepr, make_tempfile
@@ -24,12 +24,26 @@
 V = TypeVar('V')
 _Stacks = dict[float, list[Callable[[], Any]]]
 _StackContexts = list[_Stacks]
+LogLevel = Literal['debug', 'info', 'warning', 'error', 'critical']
 
 
 _CALLBACK_REPR_HELPER = CallbackRepr(maxother=cast(int, float('inf')))
 _CALLBACK_REPR = _CALLBACK_REPR_HELPER.repr
 
 
+class _LoggingCallback(Protocol):
+    @overload
+    def __call__(self, msg: str, /) -> Any:
+        ...
+
+    @overload
+    def __call__(self, msg: str, /, level: LogLevel) -> Any:
+        ...
+
+    def __call__(self, *_, **__):
+        ...
+
+
 class Cleanup:
     """
     Object which holds cleanup callbacks. Also provides convenience
@@ -124,7 +138,7 @@ def pop_n_levels_of_contexts(
 
     @staticmethod
     def _cleanup(
-        log: Callable[[str], Any], stacks: _Stacks, reason: str | None,
+        log: _LoggingCallback, stacks: _Stacks, reason: str | None,
     ) -> None:
         ncallbacks_total = sum(len(stack) for stack in stacks.values())
         note = f'{ncallbacks_total} callback(s)'
@@ -146,14 +160,15 @@ def _cleanup(
                 try:
                     callback()
                 except Exception as e:
-                    state = 'failed'
+                    success, state = False, 'failed'
                     msg = f'{callback_repr}: {type(e).__name__}: {e}'
                 else:
-                    state, msg = 'succeeded', f'{callback_repr}'
-                log(
+                    success, state, msg = True, 'succeeded', f'{callback_repr}'
+                msg = (
                     f'- Cleanup {state} '
-                    f'({ncallbacks_run}/{ncallbacks_total}): {msg}',
+                    f'({ncallbacks_run}/{ncallbacks_total}): {msg}'
                 )
+                log(msg, 'debug' if success else 'warning')
         log(f'... cleanup completed ({note})')
 
     def add_cleanup(
@@ -399,15 +414,16 @@ def _get_name(obj: Any, /) -> str:
                 name = f'{obj.__module__}.{name}'
         return str(name)
 
-    def _debug_output(self, msg: str, /) -> None:
+    def _debug_output(self, msg: str, /, level: LogLevel = 'debug') -> None:
         """
         Write debugging output.
 
         Note:
             This default implementation just writes to the logger at the
-            ``DEBUG`` level.
+            specified level.
         """
-        diagnostics.log.debug(msg)
+        log_func = getattr(diagnostics.log, level)
+        log_func(msg)
 
     @property
     def _current_context(self) -> _Stacks: