diff --git a/py/api/logging_routes.py b/py/api/logging_routes.py index 5329a1f..e7e9d4e 100644 --- a/py/api/logging_routes.py +++ b/py/api/logging_routes.py @@ -1,6 +1,13 @@ -"""Logging API routes for PromptManager.""" +"""Logging API routes for PromptManager. + +Every route that names a log file goes through Rule R (#329, +``utils/logging_config.py``): a download is served only for a regular, +non-link file listed directly in the log folder, and Clear deletes only +rotated copies. File work runs off the event loop. +""" import os +import stat from aiohttp import web @@ -85,6 +92,31 @@ def _validate_log_config(data): return clean, None +def _read_log_bytes(path): + """The whole file at ``path``, opened without following a link (blocking). + + The file is checked again through the open handle (a regular file), so a + name swapped for a link after it was listed is refused as missing. The + handle is closed before this returns. + """ + flags = os.O_RDONLY | getattr(os, "O_BINARY", 0) | getattr(os, "O_NOFOLLOW", 0) + try: + fd = os.open(str(path), flags) + except OSError as error: + if getattr(os, "O_NOFOLLOW", 0) and os.path.islink(str(path)): + raise FileNotFoundError("Log file not found") from error + raise + with os.fdopen(fd, "rb") as handle: + if not stat.S_ISREG(os.fstat(handle.fileno()).st_mode): + raise FileNotFoundError("Log file not found") + return handle.read() + + +def _download(logger_manager, filename): + """``bytes`` of a downloadable log file; FileNotFoundError otherwise.""" + return _read_log_bytes(logger_manager.log_file_entry(filename)) + + class LoggingRoutesMixin: """Mixin providing logging-related API endpoints.""" @@ -195,16 +227,16 @@ class LoggingRoutesMixin: {"success": False, "error": "Invalid filename"}, status=400 ) - log_file_path = logger_manager.log_dir / filename - - if not log_file_path.exists(): + try: + file_content = await self._run_in_executor( + _download, logger_manager, filename + ) + except FileNotFoundError: + # Missing, a link, a folder or not listed: all read as absent. return web.json_response( {"success": False, "error": "Log file not found"}, status=404 ) - with open(log_file_path, "rb") as f: - file_content = f.read() - return web.Response( body=file_content, content_type="text/plain", @@ -224,7 +256,7 @@ class LoggingRoutesMixin: """Truncate all log files.""" try: logger_manager = self._get_logger_manager() - results = logger_manager.truncate_logs() + results = await self._run_in_executor(logger_manager.truncate_logs) return web.json_response( { @@ -266,7 +298,7 @@ class LoggingRoutesMixin: return web.json_response({"success": False, "error": error}, status=400) logger_manager = self._get_logger_manager() - logger_manager.update_config(clean) + await self._run_in_executor(logger_manager.update_config, clean) return web.json_response( { diff --git a/tests/test_api_logging.py b/tests/test_api_logging.py index 97c18c4..c6551bb 100644 --- a/tests/test_api_logging.py +++ b/tests/test_api_logging.py @@ -5,9 +5,10 @@ import os import shutil import sys import tempfile +import threading import unittest from pathlib import Path -from unittest.mock import MagicMock +from unittest.mock import MagicMock, patch _mock_server = MagicMock() _mock_server.PromptServer.instance.routes = MagicMock() @@ -20,7 +21,9 @@ from aiohttp.test_utils import AioHTTPTestCase # noqa: E402 from database.operations import PromptDatabase # noqa: E402 from py.api import PromptManagerAPI # noqa: E402 +from py.api import logging_routes # noqa: E402 from py.api.logging_routes import LOG_CONFIG_KEYS # noqa: E402 +from utils import logging_config # noqa: E402 class FakeLoggerManager: @@ -38,11 +41,16 @@ class FakeLoggerManager: } self.update_calls = [] self.logs = [] + self.threads = {} def update_config(self, new_config): + self.threads["update_config"] = threading.current_thread() self.update_calls.append(dict(new_config)) self.config.update(new_config) + def log_file_entry(self, name): + return logging_config.log_file_entry(self.log_dir, name) + def get_config(self): return dict(self.config) @@ -54,23 +62,36 @@ class FakeLoggerManager: def get_log_files(self): files = [] - for path in sorted(self.log_dir.glob("*.log*")): + for row in sorted( + logging_config.scan_log_folder(self.log_dir), key=lambda r: r["name"] + ): + if row["_dir"]: + continue files.append( { - "filename": path.name, - "path": str(path), - "size": path.stat().st_size, + "filename": row["name"], + "path": str(self.log_dir / row["name"]), + "size": row["size"], "modified": "2026-10-07T00:00:00", - "is_main": path.name == "prompt_manager.log", + "is_main": row["kind"] == "active", + "kind": row["kind"], } ) return files def truncate_logs(self): + """Rule R: empty the active log, delete rotated copies, keep the rest.""" + self.threads["truncate_logs"] = threading.current_thread() truncated = [] - for path in self.log_dir.glob("prompt_manager.log*"): - path.write_text("") - truncated.append(path.name) + for row in logging_config.scan_log_folder(self.log_dir): + path = self.log_dir / row["name"] + if row["kind"] == "active": + path.write_text("") + elif row["kind"] == "rotated": + path.unlink() + else: + continue + truncated.append(row["name"]) return {"truncated": truncated, "errors": []} def get_log_stats(self): @@ -378,12 +399,90 @@ class TestLogFilesAndDownload(LoggingAPITestCase): self.assertEqual(resp.status, 400) async def test_download_read_failure_is_500(self): - (self.log_dir / "dir.log").mkdir() - resp = await self.client.request("GET", "/prompt_manager/logs/download/dir.log") + # Rewritten (#329): a directory is now a 404; inject a read error. + (self.log_dir / "prompt_manager.log").write_bytes(b"x") + secret = os.path.join(self.tmpdir, "logs", "prompt_manager.log") + + def fail(path): + raise PermissionError(13, "Permission denied", secret) + + with patch.object(logging_routes, "_read_log_bytes", fail): + resp = await self.client.request( + "GET", "/prompt_manager/logs/download/prompt_manager.log" + ) body = await resp.text() self.assertEqual(resp.status, 500) self.assertNotIn(self.tmpdir, body) + async def test_directory_download_is_404(self): + (self.log_dir / "dir.log").mkdir() + resp = await self.client.request("GET", "/prompt_manager/logs/download/dir.log") + self.assertEqual(resp.status, 404) + + async def test_download_refuses_a_symlink(self): + secret = Path(self.tmpdir) / "secret.txt" + secret.write_text("the key") + try: + os.symlink(secret, self.log_dir / "prompt_manager.log.3") + except (OSError, NotImplementedError): # pragma: no cover + self.skipTest("this account cannot create symlinks") + resp = await self.client.request( + "GET", "/prompt_manager/logs/download/prompt_manager.log.3" + ) + body = await resp.text() + self.assertEqual(resp.status, 404) + self.assertNotIn("the key", body) + + async def test_download_reads_off_the_loop(self): + (self.log_dir / "prompt_manager.log").write_bytes(b"line\n") + seen = [] + real = logging_routes._read_log_bytes + + def read(path): + seen.append(threading.current_thread()) + return real(path) + + with patch.object(logging_routes, "_read_log_bytes", read): + resp = await self.client.request( + "GET", "/prompt_manager/logs/download/prompt_manager.log" + ) + self.assertEqual(resp.status, 200) + self.assertEqual(len(seen), 1) + self.assertIsNot(seen[0], threading.current_thread()) + + async def test_download_keeps_its_response_shape(self): + (self.log_dir / "prompt_manager.log.2").write_bytes(b"a\nb\n") + resp = await self.client.request( + "GET", "/prompt_manager/logs/download/prompt_manager.log.2" + ) + self.assertEqual(resp.status, 200) + self.assertEqual(resp.content_type, "text/plain") + self.assertEqual( + resp.headers["Content-Disposition"], + 'attachment; filename="prompt_manager.log.2"', + ) + self.assertEqual(resp.headers["Content-Length"], "4") + self.assertEqual(await resp.read(), b"a\nb\n") + + async def test_log_files_rows_carry_their_kind(self): + for name in ( + "prompt_manager.log", + "prompt_manager.log.1", + "prompt_manager.log.bak", + ): + (self.log_dir / name).write_text("x") + resp = await self.client.request("GET", "/prompt_manager/logs/files") + data = await resp.json() + kinds = {row["filename"]: row["kind"] for row in data["files"]} + self.assertEqual( + kinds, + { + "prompt_manager.log": "active", + "prompt_manager.log.1": "rotated", + "prompt_manager.log.bak": "other", + }, + ) + class TestTruncateConfigAndStats(LoggingAPITestCase): @@ -395,6 +494,40 @@ class TestTruncateConfigAndStats(LoggingAPITestCase): self.assertEqual(data["results"]["truncated"], ["prompt_manager.log"]) self.assertEqual((self.log_dir / "prompt_manager.log").read_text(), "") + async def test_truncate_keeps_other_files(self): + for name in ( + "prompt_manager.log", + "prompt_manager.log.1", + "prompt_manager.log.bak", + ): + (self.log_dir / name).write_text("data") + resp = await self.client.request("POST", "/prompt_manager/logs/truncate") + data = await resp.json() + self.assertEqual(resp.status, 200) + self.assertEqual(set(data), {"success", "message", "results"}) + self.assertEqual( + sorted(data["results"]["truncated"]), + ["prompt_manager.log", "prompt_manager.log.1"], + ) + self.assertEqual( + sorted(p.name for p in self.log_dir.iterdir()), + ["prompt_manager.log", "prompt_manager.log.bak"], + ) + + async def test_truncate_runs_off_the_loop(self): + resp = await self.client.request("POST", "/prompt_manager/logs/truncate") + self.assertEqual(resp.status, 200) + self.assertIsNot( + self.manager.threads["truncate_logs"], threading.current_thread() + ) + + async def test_update_config_runs_off_the_loop(self): + resp = await self._post_config({"level": "DEBUG"}) + self.assertEqual(resp.status, 200) + self.assertIsNot( + self.manager.threads["update_config"], threading.current_thread() + ) + async def test_truncate_failure_is_500(self): def boom(): raise RuntimeError("locked") diff --git a/tests/test_utils_logging_config.py b/tests/test_utils_logging_config.py index 286c1cf..37dec48 100644 --- a/tests/test_utils_logging_config.py +++ b/tests/test_utils_logging_config.py @@ -1,6 +1,7 @@ """PromptManagerLogger: memory buffer, file rotation, level changes, truncation.""" import logging +import ntpath import os import pathlib import sys @@ -11,14 +12,20 @@ import unittest.mock as mock sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__)))) -from utils import logging_config -from utils.logging_config import ( +from utils import logging_config # noqa: E402 +from utils.logging_config import ( # noqa: E402 MemoryBufferHandler, PromptManagerLogger, + RotatedChanged, get_logger, get_logger_manager, ) +try: + from tests.open_handles import assert_closed # noqa: E402 +except ImportError: # discovered with tests/ as the top-level directory + from open_handles import assert_closed # noqa: E402 + class IsolatedLoggerTestCase(unittest.TestCase): """A logger manager whose log directory is a temporary folder.""" @@ -32,6 +39,7 @@ class IsolatedLoggerTestCase(unittest.TestCase): with mock.patch.object(logging_config, "__file__", fake_file): self.manager = object.__new__(PromptManagerLogger) # bypass singleton self.manager.__init__() + self.allowed_thread_names = set() self.manager.update_config({"console_logging": False}) # Drop the "Updated logging configuration" entry. self.manager._log_buffer.clear() @@ -53,12 +61,21 @@ class IsolatedLoggerTestCase(unittest.TestCase): def _filter_to_this_thread(self): this_thread = threading.get_ident() + # A test may let named helper threads of its own through too. + allowed_names = self.allowed_thread_names + + def allowed(record): + return record.thread == this_thread or record.threadName in allowed_names + for handler in self.manager.logger.handlers: - handler.addFilter(lambda record: record.thread == this_thread) + handler.filters.clear() + handler.addFilter(allowed) def _restore_global_logging(self): for handler in logging.getLogger("prompt_manager").handlers[:]: handler.close() + # Windows refuses to delete an open log: prove every handle is closed. + assert_closed(self, self.tmp.name) get_logger_manager()._setup_loggers() self.tmp.cleanup() @@ -175,15 +192,14 @@ class TestFilesAndRotation(IsolatedLoggerTestCase): def test_unreadable_files_are_skipped_in_the_listing(self): self.logger.info("something") - original_stat = pathlib.Path.stat + original_lstat = os.lstat - def stat_failing_for_logs(path, *args, **kwargs): - if path.suffix == ".log": + def lstat_failing_for_logs(path, *args, **kwargs): + if str(path).endswith(".log"): raise OSError("denied") - return original_stat(path, *args, **kwargs) + return original_lstat(path, *args, **kwargs) - with mock.patch.object(pathlib.Path, "stat", autospec=True) as stat: - stat.side_effect = stat_failing_for_logs + with mock.patch.object(logging_config.os, "lstat", lstat_failing_for_logs): self.assertEqual(self.manager.get_log_files(), []) def test_truncate_does_not_roll_the_log_over_while_deleting_backups(self): @@ -228,10 +244,477 @@ class TestFilesAndRotation(IsolatedLoggerTestCase): def test_truncate_reports_files_it_cannot_remove(self): self._rotate() - with mock.patch.object(pathlib.Path, "unlink", side_effect=OSError("busy")): + + def busy(path, *args, **kwargs): + raise PermissionError(13, "busy", str(path)) + + with mock.patch.object(logging_config.os, "unlink", busy): result = self.manager.truncate_logs() self.assertEqual(len(result["errors"]), 2) self.assertEqual(result["truncated"], ["prompt_manager.log"]) + for error in result["errors"]: + self.assertNotIn(self.tmp.name, error) + self.assertRegex(error, r"prompt_manager\.log\.[12]") + + +class TestRotatedCopyRule(IsolatedLoggerTestCase): + """Rule R (#329): only prompt_manager.log. regular files are deletable.""" + + def setUp(self): + super().setUp() + self.logger.info("active log line") # the active log exists + self.outside = os.path.join(self.tmp.name, "outside") + os.makedirs(self.outside) + + def _path(self, name): + return os.path.join(self.log_dir, name) + + def _write(self, name, data=b"rotated\n"): + with open(self._path(name), "wb") as handle: + handle.write(data) + return self._path(name) + + def _symlink(self, name, target_name="secret.txt", data=b"secret " * 1000): + """A symlink in the log folder to a file outside it, or None.""" + target = os.path.join(self.outside, target_name) + with open(target, "wb") as handle: + handle.write(data) + try: + os.symlink(target, self._path(name)) + except (OSError, NotImplementedError): # pragma: no cover - no privilege + return None + return target + + def _require_symlink(self, name, **kwargs): + target = self._symlink(name, **kwargs) + if target is None: # pragma: no cover - Windows without the privilege + self.skipTest("this account cannot create symlinks") + return target + + def _kinds(self): + return {row["name"]: row["kind"] for row in self.manager.scan_log_folder()} + + def _rotated_rows(self): + return [r for r in self.manager.scan_log_folder() if r["kind"] == "rotated"] + + def _names(self): + return sorted(os.listdir(self.log_dir)) + + def _file_handler(self): + return next( + h + for h in self.manager.logger.handlers + if isinstance(h, logging.FileHandler) + ) + + def test_scan_classes_rotated_active_link_and_other(self): + for name in ("prompt_manager.log.1", "prompt_manager.log.2"): + self._write(name) + self._write("prompt_manager.log.3", b"x" * 3000) + for name in ( + "prompt_manager.log.0", + "prompt_manager.log.01", + "prompt_manager.log.bak", + "prompt_manager.log.1.gz", + "prompt_manager.log.-1", + "notes.txt", + ): + self._write(name) + os.makedirs(self._path("prompt_manager.log.5")) + self._require_symlink("prompt_manager.log.4") + kinds = self._kinds() + self.assertEqual( + kinds, + { + "prompt_manager.log": "active", + "prompt_manager.log.1": "rotated", + "prompt_manager.log.2": "rotated", + "prompt_manager.log.3": "rotated", + "prompt_manager.log.0": "other", + "prompt_manager.log.01": "other", + "prompt_manager.log.bak": "other", + "prompt_manager.log.1.gz": "other", + "prompt_manager.log.-1": "other", + "notes.txt": "other", + "prompt_manager.log.5": "other", + "prompt_manager.log.4": "link", + }, + ) + row = next( + r + for r in self.manager.scan_log_folder() + if r["name"] == "prompt_manager.log.3" + ) + self.assertEqual( + set(row), {"name", "kind", "size", "mtime_ns", "ino", "modified"} + ) + stat = os.lstat(self._path("prompt_manager.log.3")) + self.assertEqual(row["size"], 3000) + self.assertEqual(row["mtime_ns"], stat.st_mtime_ns) + self.assertEqual(row["ino"], stat.st_ino) + + def test_scan_matches_names_case_insensitively_on_windows(self): + self._write("PROMPT_MANAGER.LOG.2") + if os.name == "nt": # pragma: no cover - native case folding + self.assertEqual(self._kinds()["PROMPT_MANAGER.LOG.2"], "rotated") + return + # POSIX names are case-sensitive: another file, never deleted. + self.assertEqual(self._kinds()["PROMPT_MANAGER.LOG.2"], "other") + with mock.patch.object(logging_config, "_name_key", ntpath.normcase): + self.assertEqual(self._kinds()["PROMPT_MANAGER.LOG.2"], "rotated") + result = self.manager.delete_rotated(self._rotated_rows()) + self.assertEqual(result["removed"], ["PROMPT_MANAGER.LOG.2"]) + + def test_a_junction_is_classed_as_a_link_and_kept(self): + # Portable control: whatever os.path.isjunction reports is a link. + self._write("prompt_manager.log.4") + self._write("prompt_manager.log.1") + junction = self._path("prompt_manager.log.4") + real_isjunction = os.path.isjunction + + def isjunction(path): + return os.fspath(path) == junction or real_isjunction(path) + + with mock.patch.object(logging_config.os.path, "isjunction", isjunction): + self.assertEqual(self._kinds()["prompt_manager.log.4"], "link") + self.manager.delete_rotated(self._rotated_rows()) + self.manager.truncate_logs() + self.assertIn("prompt_manager.log.4", self._names()) + self.assertNotIn("prompt_manager.log.1", self._names()) + + @unittest.skipUnless(os.name == "nt", "junctions exist only on Windows") + def test_junction_is_never_deleted_on_windows(self): # pragma: no cover + import _winapi + + target = os.path.join(self.outside, "kept") + os.makedirs(target) + with open(os.path.join(target, "inside.txt"), "wb") as handle: + handle.write(b"keep me") + _winapi.CreateJunction(target, self._path("prompt_manager.log.4")) + self._write("prompt_manager.log.1") + self.assertEqual(self._kinds()["prompt_manager.log.4"], "link") + self.manager.delete_rotated(self._rotated_rows()) + self.manager.truncate_logs() + self.assertIn("prompt_manager.log.4", self._names()) + self.assertTrue(os.path.exists(os.path.join(target, "inside.txt"))) + with self.assertRaises(FileNotFoundError): + self.manager.log_file_entry("prompt_manager.log.4") + os.rmdir(self._path("prompt_manager.log.4")) # removes the junction only + + def test_delete_rotated_removes_exactly_the_listed_files(self): + for n in (1, 2, 3): + self._write(f"prompt_manager.log.{n}", b"r" * n) + self._write("prompt_manager.log.bak") + os.makedirs(self._path("prompt_manager.log.7")) + target = self._symlink("prompt_manager.log.4") + listed = [ + r for r in self._rotated_rows() if r["name"] != "prompt_manager.log.3" + ] + result = self.manager.delete_rotated(listed) + self.assertEqual( + result, + {"removed": ["prompt_manager.log.1", "prompt_manager.log.2"], "failed": []}, + ) + expected = [ + "prompt_manager.log", + "prompt_manager.log.3", + "prompt_manager.log.7", + "prompt_manager.log.bak", + ] + if target is not None: + expected.append("prompt_manager.log.4") + self.assertTrue(os.path.exists(target)) + self.assertEqual(self._names(), sorted(expected)) + + def test_delete_rotated_refuses_all_when_one_changed(self): + def change_size(path): + with open(path, "ab") as handle: + handle.write(b"more") + + def change_mtime(path): + stat = os.lstat(path) + os.utime(path, ns=(stat.st_atime_ns, stat.st_mtime_ns + 5_000_000_000)) + + def change_inode(path): + stat = os.lstat(path) + with open(path, "rb") as handle: + data = handle.read() + other = path + ".new" + with open(other, "wb") as handle: + handle.write(data) + os.utime(other, ns=(stat.st_atime_ns, stat.st_mtime_ns)) + os.replace(other, path) + if os.lstat(path).st_ino in (0, stat.st_ino): # pragma: no cover + self.skipTest("this filesystem reports no inode numbers") + + def remove(path): + os.unlink(path) + + def replace_by_link(path): + os.unlink(path) + target = os.path.join(self.outside, "elsewhere.txt") + with open(target, "wb") as handle: + handle.write(b"rotated\n") + try: + os.symlink(target, path) + except (OSError, NotImplementedError): # pragma: no cover + self.skipTest("this account cannot create symlinks") + + changes = { + "size": change_size, + "mtime": change_mtime, + "inode": change_inode, + "missing": remove, + "link": replace_by_link, + } + for label, change in changes.items(): + with self.subTest(change=label): + for n in (1, 2, 3): + self._write(f"prompt_manager.log.{n}", b"rotated\n") + reviewed = self._rotated_rows() + change(self._path("prompt_manager.log.2")) + before = self._names() + with self.assertRaises(RotatedChanged): + self.manager.delete_rotated(reviewed) + self.assertEqual(self._names(), before) + self.assertIn("prompt_manager.log.1", before) + self.assertIn("prompt_manager.log.3", before) + for name in self._names(): + if name.startswith("prompt_manager.log."): + os.unlink(self._path(name)) + + def test_rollover_waits_while_cleanup_holds_the_handler_lock(self): + # The file is already over its limit: the next record rolls it over, + # renaming .1 to .2 and the active log to .1. + self.manager.update_config({"max_file_size": 64, "backup_count": 3}) + self.logger.info("x" * 100) + self._write("prompt_manager.log.1", b"first copy\n") + self._write("prompt_manager.log.2", b"second copy\n") + reviewed = self._rotated_rows() + holding = threading.Event() + release = threading.Event() + logged = threading.Event() + real_unlink = os.unlink + self.allowed_thread_names.add("pm-test-rollover") + + def log_from_another_thread(): + self.logger.info("rolls the log over") + logged.set() + + worker = threading.Thread( + target=log_from_another_thread, name="pm-test-rollover", daemon=True + ) + + def slow_unlink(path, *args, **kwargs): + if not holding.is_set(): + worker.start() # its record must wait for the cleanup's lock + holding.set() + if not release.wait(10): + raise RuntimeError("the test never released the cleanup") + return real_unlink(path, *args, **kwargs) + + result = {} + + def cleanup(): + result.update(self.manager.delete_rotated(reviewed)) + + with mock.patch.object(logging_config.os, "unlink", slow_unlink): + cleaner = threading.Thread(target=cleanup, daemon=True) + cleaner.start() + self.assertTrue(holding.wait(10), "the cleanup never started deleting") + # The record waits on the handler lock the cleanup holds. + self.assertFalse(logged.wait(0.3), "a record was written mid-cleanup") + release.set() + cleaner.join(10) + worker.join(10) + self.assertFalse(cleaner.is_alive()) + self.assertTrue(logged.is_set()) + self.assertEqual( + result, + {"removed": ["prompt_manager.log.1", "prompt_manager.log.2"], "failed": []}, + ) + # The rollover ran after the cleanup: only the old active log moved. + self.assertEqual(self._names(), ["prompt_manager.log", "prompt_manager.log.1"]) + with open(self._path("prompt_manager.log.1"), "rb") as handle: + self.assertIn(b"x" * 100, handle.read()) + + def test_open_rotated_copy_is_reported_not_deleted(self): + for n in (1, 2, 3): + self._write(f"prompt_manager.log.{n}") + real_unlink = os.unlink + held = self._path("prompt_manager.log.2") + + def unlink(path, *args, **kwargs): + if os.fspath(path) == held: + error = PermissionError( + 13, + "The process cannot access the file because it is being " + "used by another process", + held, + ) + error.winerror = 32 + raise error + return real_unlink(path, *args, **kwargs) + + with mock.patch.object(logging_config.os, "unlink", unlink): + result = self.manager.delete_rotated(self._rotated_rows()) + self.assertEqual( + result["removed"], ["prompt_manager.log.1", "prompt_manager.log.3"] + ) + [(name, error)] = result["failed"] + self.assertEqual(name, "prompt_manager.log.2") + self.assertIsInstance(error, PermissionError) + self.assertIn("prompt_manager.log.2", self._names()) + + @unittest.skipUnless(os.name == "nt", "only Windows refuses to unlink an open file") + def test_open_rotated_copy_is_reported_not_deleted_on_windows( + self, + ): # pragma: no cover + for n in (1, 2, 3): + self._write(f"prompt_manager.log.{n}") + reviewed = self._rotated_rows() + handle = open(self._path("prompt_manager.log.2"), "rb") + try: + result = self.manager.delete_rotated(reviewed) + finally: + handle.close() + self.assertEqual( + result["removed"], ["prompt_manager.log.1", "prompt_manager.log.3"] + ) + [(name, error)] = result["failed"] + self.assertEqual(name, "prompt_manager.log.2") + self.assertIsInstance(error, PermissionError) + self.assertIn("prompt_manager.log.2", self._names()) + + def test_cleanup_never_logs_while_holding_the_handler_lock(self): + for n in (1, 2): + self._write(f"prompt_manager.log.{n}") + handler = self._file_handler() + depth = 0 + calls = [] + real_acquire, real_release = handler.acquire, handler.release + + def acquire(): + nonlocal depth + real_acquire() + depth += 1 + + def release(): + nonlocal depth + depth -= 1 + real_release() + + real_call_handlers = logging.Logger.callHandlers + + def call_handlers(logger_self, record): + calls.append((record.getMessage(), depth)) + return real_call_handlers(logger_self, record) + + with ( + mock.patch.object(handler, "acquire", acquire), + mock.patch.object(handler, "release", release), + mock.patch.object(logging.Logger, "callHandlers", call_handlers), + ): + self.manager.delete_rotated(self._rotated_rows()) + self.assertEqual(depth, 0) + self._write("prompt_manager.log.1") + self.manager.truncate_logs() + self.assertEqual(depth, 0) + self.assertTrue(calls, "the cleanup logged no summary") + self.assertEqual([c for c in calls if c[1]], []) + + def test_truncate_keeps_other_files_and_links(self): + # Corrected (#329): the legacy glob deleted every prompt_manager.log*. + self._rotate() + self._write("prompt_manager.log.bak", b"mine") + self._write("prompt_manager.log.1.gz", b"zip") + target = self._symlink("prompt_manager.log.4") + result = self.manager.truncate_logs() + self.assertEqual(result["errors"], []) + self.assertEqual( + sorted(result["truncated"]), + ["prompt_manager.log", "prompt_manager.log.1", "prompt_manager.log.2"], + ) + names = self._names() + self.assertIn("prompt_manager.log.bak", names) + self.assertIn("prompt_manager.log.1.gz", names) + self.assertNotIn("prompt_manager.log.1", names) + if target is not None: + self.assertIn("prompt_manager.log.4", names) + self.assertTrue(os.path.islink(self._path("prompt_manager.log.4"))) + with open(target, "rb") as handle: + self.assertEqual(handle.read(), b"secret " * 1000) + + def test_truncate_with_file_logging_off_never_creates_the_active_log(self): + self.manager.update_config({"file_logging": False}) + os.unlink(self._path("prompt_manager.log")) + self._write("prompt_manager.log.1") + result = self.manager.truncate_logs() + self.assertEqual(result, {"truncated": ["prompt_manager.log.1"], "errors": []}) + self.assertEqual(self._names(), []) + + def test_truncate_never_empties_a_linked_active_log(self): + self.manager.update_config({"file_logging": False}) + os.unlink(self._path("prompt_manager.log")) + target = self._require_symlink("prompt_manager.log", data=b"keep") + self.manager.truncate_logs() + with open(target, "rb") as handle: + self.assertEqual(handle.read(), b"keep") + + def test_log_files_mark_kind_and_lstat_links(self): + self._write("prompt_manager.log.1", b"r" * 10) + self._write("prompt_manager.log.bak", b"b") + target = self._require_symlink("prompt_manager.log.4") + rows = {row["filename"]: row for row in self.manager.get_log_files()} + self.assertEqual(rows["prompt_manager.log"]["kind"], "active") + self.assertTrue(rows["prompt_manager.log"]["is_main"]) + self.assertEqual(rows["prompt_manager.log.1"]["kind"], "rotated") + self.assertEqual(rows["prompt_manager.log.bak"]["kind"], "other") + link = rows["prompt_manager.log.4"] + self.assertEqual(link["kind"], "link") + self.assertEqual( + link["size"], os.lstat(self._path("prompt_manager.log.4")).st_size + ) + self.assertNotEqual(link["size"], os.path.getsize(target)) + for row in rows.values(): + self.assertEqual( + set(row), {"filename", "path", "size", "modified", "is_main", "kind"} + ) + + def test_stats_exclude_links(self): + self._write("prompt_manager.log.1", b"r" * 10) + before = self.manager.get_log_stats() + self._require_symlink("prompt_manager.log.4") + after = self.manager.get_log_stats() + self.assertEqual(after["log_files_count"], before["log_files_count"]) + self.assertEqual(after["total_log_size"], before["total_log_size"]) + + def test_log_file_entry_accepts_only_listed_regular_files(self): + self._write("prompt_manager.log.1") + self._write("prompt_manager.log.bak") + os.makedirs(self._path("folder.log")) + self._symlink("prompt_manager.log.4") + self.assertEqual( + os.path.normcase(str(self.manager.log_file_entry("prompt_manager.log.1"))), + os.path.normcase(self._path("prompt_manager.log.1")), + ) + self.manager.log_file_entry("prompt_manager.log") + self.manager.log_file_entry("prompt_manager.log.bak") + for name in ( + "prompt_manager.log.4", + "folder.log", + "missing.log", + "", + ".", + "..", + "../outside/secret.txt", + "..\\outside\\secret.txt", + "prompt_manager.log:stream", + "prompt_manager.log\x00", + ): + with self.subTest(name=name): + with self.assertRaises(FileNotFoundError): + self.manager.log_file_entry(name) class TestConfiguration(IsolatedLoggerTestCase): diff --git a/utils/logging_config.py b/utils/logging_config.py index bb147a2..cc23608 100644 --- a/utils/logging_config.py +++ b/utils/logging_config.py @@ -10,9 +10,12 @@ This module provides centralized logging configuration with support for: """ import collections +import fnmatch import logging import logging.handlers import os +import re +import stat import threading from datetime import datetime from typing import Dict, Any, Optional, List @@ -20,6 +23,131 @@ from pathlib import Path from . import library_location +ACTIVE_LOG_NAME = "prompt_manager.log" +# Rule R (#329): a rotated copy is prompt_manager.log., n >= 1, no leading 0. +_ROTATED_NAME = re.compile(r"prompt_manager\.log\.([1-9][0-9]*)") +# The legacy listing's pattern (GET /logs/files and /logs/stats). +_LISTED_PATTERN = "*.log*" +LOG_FILE_KINDS = ("active", "rotated", "link", "other") + + +class RotatedChanged(Exception): + """A reviewed rotated copy changed since the review; nothing was deleted.""" + + def __init__(self, name): + super().__init__(f"{name} changed since the review") + self.name = name + + +def _name_key(name: str) -> str: + """How a name compares: case-folded where the filesystem folds it (Windows).""" + return os.path.normcase(name) + + +def _rotated_number(name: str) -> Optional[int]: + match = _ROTATED_NAME.fullmatch(_name_key(name)) + return int(match.group(1)) if match else None + + +def _is_link(path: str, st: os.stat_result) -> bool: + return stat.S_ISLNK(st.st_mode) or os.path.isjunction(path) + + +def _kind(name: str, path: str, st: os.stat_result) -> str: + """Rule R: ``active``, ``rotated``, ``link`` or ``other`` (never deleted).""" + if _is_link(path, st): + return "link" + if not stat.S_ISREG(st.st_mode): + return "other" + if _name_key(name) == _name_key(ACTIVE_LOG_NAME): + return "active" + if _rotated_number(name) is not None: + return "rotated" + return "other" + + +def scan_log_folder(log_dir) -> List[Dict[str, Any]]: + """Every direct entry of ``log_dir`` with its Rule R kind (blocking). + + Rows are ``{name, kind, size, mtime_ns, ino, modified}``, read with + ``lstat`` so a link is described, never followed. An entry that cannot + be read is left out. Never logs: the cleanup calls it while it holds the + file handler's lock. + """ + rows = [] + try: + names = [entry.name for entry in os.scandir(log_dir)] + except OSError: + return rows + for name in names: + path = os.path.join(log_dir, name) + try: + st = os.lstat(path) + kind = _kind(name, path, st) + except OSError: + continue + rows.append( + { + "name": name, + "kind": kind, + "size": st.st_size, + "mtime_ns": st.st_mtime_ns, + "ino": st.st_ino, + "modified": datetime.fromtimestamp(st.st_mtime).isoformat(), + "_dir": stat.S_ISDIR(st.st_mode) and kind != "link", + } + ) + return rows + + +def public_row(row: Dict[str, Any]) -> Dict[str, Any]: + """A scan row without its private keys.""" + return {key: value for key, value in row.items() if not key.startswith("_")} + + +def rotated_sort_key(row: Dict[str, Any]) -> int: + return _rotated_number(row["name"]) or 0 + + +def log_file_entry(log_dir, name) -> Path: + """The path of a downloadable log file named ``name`` (blocking). + + Only a regular, non-link file listed directly in ``log_dir`` under that + exact name; a separator, ``..``, a stream suffix or any unlisted name + raises FileNotFoundError, as a missing file does. + """ + if not isinstance(name, str) or not name or name in (".", ".."): + raise FileNotFoundError("Log file not found") + if any(ch in name for ch in ("/", "\\", "\x00", ":")): + raise FileNotFoundError("Log file not found") + for row in scan_log_folder(log_dir): + if row["name"] == name and row["kind"] in ("active", "rotated", "other"): + if row["_dir"]: + break + return Path(log_dir) / row["name"] + raise FileNotFoundError("Log file not found") + + +def _error_text(error: BaseException) -> str: + """An OSError's reason and file name, without the folder it is in.""" + if isinstance(error, OSError): + parts = [error.strerror or type(error).__name__] + if error.filename: + parts.append(os.path.basename(str(error.filename))) + return ": ".join(parts) + return str(error) or type(error).__name__ + + +def _matches_review(row: Optional[Dict[str, Any]], reviewed: Dict[str, Any]) -> bool: + if row is None or row["kind"] != "rotated": + return False + if row["size"] != reviewed.get("size") or row["mtime_ns"] != reviewed.get( + "mtime_ns" + ): + return False + ino = reviewed.get("ino") or 0 + return not (ino and row["ino"] and row["ino"] != ino) + class _OwnedRotatingFileHandler(logging.handlers.RotatingFileHandler): """Keep a retired owned sink closed when an in-flight record resumes.""" @@ -87,6 +215,9 @@ class PromptManagerLogger: # Memory buffer for recent logs (for web viewer) self._log_buffer = collections.deque(maxlen=self.config["buffer_size"]) self._buffer_lock = threading.Lock() + # Held while a handler is replaced or log files are deleted (#329): + # taken before any file handler's own lock, never the other way round. + self._files_lock = threading.Lock() # Initialize loggers self._setup_loggers() @@ -238,6 +369,14 @@ class PromptManagerLogger: # Return most recent first return list(reversed(logs[-limit:])) + def scan_log_folder(self) -> List[Dict[str, Any]]: + """Every entry of the log folder with its Rule R kind (blocking).""" + return [public_row(row) for row in scan_log_folder(self.log_dir)] + + def log_file_entry(self, name: str) -> Path: + """A downloadable (regular, non-link) log file; FileNotFoundError else.""" + return log_file_entry(self.log_dir, name) + def get_log_files(self) -> List[Dict[str, Any]]: """Get information about available log files. @@ -245,26 +384,27 @@ class PromptManagerLogger: List of dictionaries containing file information: - filename: Name of the log file - path: Full path to the log file - - size: File size in bytes + - size: File size in bytes (a link's own size: links are not followed) - modified: ISO formatted modification timestamp - is_main: True if this is the main log file + - kind: ``active``, ``rotated``, ``link`` or ``other`` (Rule R) """ log_files = [] - - for log_file in self.log_dir.glob("*.log*"): - try: - stat = log_file.stat() - log_files.append( - { - "filename": log_file.name, - "path": str(log_file), - "size": stat.st_size, - "modified": datetime.fromtimestamp(stat.st_mtime).isoformat(), - "is_main": log_file.name == "prompt_manager.log", - } - ) - except Exception as e: - self.logger.error(f"Error getting info for log file {log_file}: {e}") + for row in scan_log_folder(self.log_dir): + if row["_dir"]: + continue + if not fnmatch.fnmatchcase(_name_key(row["name"]), _LISTED_PATTERN): + continue + log_files.append( + { + "filename": row["name"], + "path": str(self.log_dir / row["name"]), + "size": row["size"], + "modified": row["modified"], + "is_main": row["kind"] == "active", + "kind": row["kind"], + } + ) # Sort by modification time, newest first log_files.sort(key=lambda x: x["modified"], reverse=True) @@ -302,6 +442,31 @@ class PromptManagerLogger: self.logger.error(f"Error reading log file {filename}: {e}") raise + def _file_handlers(self) -> List[logging.Handler]: + return [h for h in self.logger.handlers if isinstance(h, logging.FileHandler)] + + def _acquire_file_handlers(self) -> List[logging.Handler]: + """Take every file handler's lock: no rollover renames a file meanwhile. + + The caller holds ``_files_lock`` (so no handler is replaced) and must + not log until it released them: the lock is re-entrant, so a record + logged here could roll the log over under the caller's feet. + """ + held = [] + try: + for handler in self._file_handlers(): + handler.acquire() + held.append(handler) + except BaseException: + self._release_handlers(held) + raise + return held + + @staticmethod + def _release_handlers(held) -> None: + for handler in reversed(held): + handler.release() + def _truncate_main_log(self, log_file: Path) -> None: """Empty the main log through the handler that writes to it. @@ -309,7 +474,8 @@ class PromptManagerLogger: stream at its old offset: later records land past the new end (zero-padded on POSIX) and ``tell()`` keeps reporting the old size, so the next record rolls the file over. Truncating the handler's stream - keeps position and size in step. + keeps position and size in step. Without a handler on it (file logging + off) the existing file is emptied in place, never through a link. """ handled = False target = os.path.normcase(os.path.realpath(str(log_file))) @@ -329,14 +495,65 @@ class PromptManagerLogger: finally: handler.release() if not handled: - with open(log_file, "w", encoding="utf-8", errors="replace") as f: - f.write("") + flags = os.O_WRONLY | os.O_TRUNC | getattr(os, "O_NOFOLLOW", 0) + os.close(os.open(str(log_file), flags)) + + def delete_rotated(self, expected: List[Dict[str, Any]]) -> Dict[str, Any]: + """Delete exactly the reviewed rotated copies, or none of them (blocking). + + ``expected`` are scan rows (``name``, ``size``, ``mtime_ns``, + ``ino``). Under ``_files_lock`` and every file handler's lock the + folder is scanned again; when any expected file is missing, is no + longer a rotated copy (Rule R) or differs in size, ``mtime_ns`` or a + non-zero ``ino``, RotatedChanged is raised with nothing deleted. + Otherwise each is unlinked in ```` order. + + Returns ``{"removed": [names], "failed": [(name, OSError)]}``. One + summary line is logged once both locks are released. + """ + removed, failed = [], [] + changed = None + with self._files_lock: + held = self._acquire_file_handlers() + try: + current = { + _name_key(row["name"]): row for row in scan_log_folder(self.log_dir) + } + targets = [] + for reviewed in sorted(expected, key=rotated_sort_key): + row = current.get(_name_key(str(reviewed.get("name", "")))) + if not _matches_review(row, reviewed): + changed = str(reviewed.get("name", "")) + break + targets.append(row["name"]) + if changed is None: + for name in targets: + try: + os.unlink(os.path.join(self.log_dir, name)) + removed.append(name) + except OSError as error: + failed.append((name, error)) + finally: + self._release_handlers(held) + if changed is not None: + self.logger.warning( + "Rotated log cleanup refused: %s changed since the review", changed + ) + raise RotatedChanged(changed) + self.logger.info( + "Deleted %d rotated log copies%s", + len(removed), + f", {len(failed)} could not be deleted" if failed else "", + ) + return {"removed": removed, "failed": failed} def truncate_logs(self) -> Dict[str, Any]: - """Truncate all log files. + """Empty the active log and delete its rotated copies (Rule R). - Clears the main log file and deletes rotated log files. - Also clears the memory buffer. + Every other file in the log folder, and every link, is kept. Also + clears the memory buffer. Runs under ``_files_lock`` and the file + handlers' locks, so no rollover recreates a just-deleted copy, and + logs only once they are released. Returns: Dictionary with: @@ -345,28 +562,31 @@ class PromptManagerLogger: """ results = {"truncated": [], "errors": []} - # Collect first and stay silent until every file has been handled: - # a log line written mid-way can roll the just-emptied main log over - # and recreate the backup that was deleted a moment earlier. - log_files = sorted(self.log_dir.glob("prompt_manager.log*")) - for log_file in log_files: + with self._files_lock: + held = self._acquire_file_handlers() try: - if log_file.name == "prompt_manager.log": - self._truncate_main_log(log_file) - else: - # For rotated files, delete them - log_file.unlink() - - results["truncated"].append(log_file.name) - - except Exception as e: - results["errors"].append( - f"Failed to truncate {log_file.name}: {str(e)}" + rows = scan_log_folder(self.log_dir) + active = [row for row in rows if row["kind"] == "active"] + rotated = sorted( + (row for row in rows if row["kind"] == "rotated"), + key=rotated_sort_key, ) - - # Clear memory buffer - with self._buffer_lock: - self._log_buffer.clear() + for row in active + rotated: + path = os.path.join(self.log_dir, row["name"]) + try: + if row["kind"] == "active": + self._truncate_main_log(Path(path)) + else: + os.unlink(path) + results["truncated"].append(row["name"]) + except OSError as error: + results["errors"].append( + f"Failed to truncate {row['name']}: {_error_text(error)}" + ) + with self._buffer_lock: + self._log_buffer.clear() + finally: + self._release_handlers(held) if results["truncated"]: self.logger.info("Truncated log files: %s", ", ".join(results["truncated"])) @@ -409,7 +629,9 @@ class PromptManagerLogger: "backup_count", ] ): - self._setup_loggers() + # No cleanup may hold the old handler while it is replaced. + with self._files_lock: + self._setup_loggers() self.logger.info(f"Updated logging configuration: {new_config}") @@ -440,7 +662,9 @@ class PromptManagerLogger: level = entry["level"] level_counts[level] = level_counts.get(level, 0) + 1 - log_files = self.get_log_files() + # A link's target is not a log file of this folder: neither counted + # nor sized. + log_files = [f for f in self.get_log_files() if f["kind"] != "link"] total_log_size = sum(f["size"] for f in log_files) return {