diff --git a/TESTING.md b/TESTING.md index d0ab868..67df06a 100644 --- a/TESTING.md +++ b/TESTING.md @@ -3983,7 +3983,30 @@ modals use the same routes and keep working. other: each file's identity is checked just before its unlink. - **Clear all logs** (`POST /logs/truncate`, also the admin page's Clear) empties the active log through its handler, deletes the rotated copies (Rule R) and clears the - buffer; other files and links are kept. Response keys are unchanged. + buffer; other files and links are kept. Response keys are unchanged. It deletes or + empties no more than its confirmation showed (#389): + - `/logs/files` rows carry `identity`, the string `"::"` (a + string: `mtime_ns` and many inodes are beyond a browser's exact integers). The + workspace sends `{"expected": [{name, identity}]}` with the active and rotated rows + its dialog was built from. Under the files lock and every handler lock each listed + rotated copy must still match (`_matches_review`) and the listed active log must be + the same inode, or nothing changes: 409 `logs-changed`. Only listed copies are + deleted; one that appeared after the confirmation is kept. A malformed list is 400. + - Without a body (the legacy admin page, whose confirm lists nothing; also the + workspace when the file list could not be read and the dialog said "deletes its + rotated copies") every rotated copy present at the locked rescan is deleted. + - Either way, before anything changes (best effort, not a cross-process lock: a + write before our own last write, or any while file logging is off here, is not + seen): a second writer of the active log (our + handler's flushed stream is behind the file's size, or its file is now a rotated + copy: another ComfyUI sharing the folder) is 409 `logs-foreign-writer`; an active + log with more than one name (`st_nlink > 1` by `lstat` or the handler's `fstat`, + NTFS included) is 409 `logs-hard-link`, never truncated (replacing it instead would + rename a file our handler holds open, which Windows refuses). Each copy is + `lstat`-checked again just before its unlink; one that changed stops the clear there + and keeps it, the copies after it and the active log, which is emptied last. + - The browser fixture grows the active log through the handler's own stream, since a + second handle appending to it is exactly what Clear refuses. - **Runtime settings** (`GET/POST /logs/config`): the level (DEBUG…CRITICAL) and console logging apply until the server restarts; the retention values are shown read-only in the workspace and the API keeps accepting them. diff --git a/py/api/logging_routes.py b/py/api/logging_routes.py index 8918986..ed13096 100644 --- a/py/api/logging_routes.py +++ b/py/api/logging_routes.py @@ -11,6 +11,11 @@ import stat from aiohttp import web +try: + from ...utils.logging_config import ClearRefused, parse_confirmed +except ImportError: # loaded as the top-level ``py`` package (tests) + from utils.logging_config import ClearRefused, parse_confirmed + # Keys PromptManagerLogger.update_config() understands. Anything else is # rejected so a client cannot inject arbitrary entries into the logging config. LOG_CONFIG_KEYS = frozenset( @@ -263,10 +268,43 @@ class LoggingRoutesMixin: ) async def truncate_logs(self, request): - """Truncate all log files.""" + """Clear all logs: what ``{"expected": [...]}`` lists, or all (#389). + + ``expected`` holds the ``{name, identity}`` rows of ``/logs/files`` the + confirmation showed. Without a body (the legacy admin page, whose + confirmation lists nothing) every rotated copy present now is deleted. + A malformed list is 400; a clear that would empty or delete what was + not confirmed changes nothing and is 409 with the reason's ``code``. + """ try: + args = () + if request.can_read_body: + data, error_response = await self._read_json_body(request) + if error_response is not None: + return error_response + if "expected" in data: + try: + parse_confirmed(data["expected"]) + except ValueError: + return web.json_response( + { + "success": False, + "error": "expected must list name and identity" + " rows from /logs/files", + }, + status=400, + ) + args = (data["expected"],) logger_manager = self._get_logger_manager() - results = await self._run_in_executor(logger_manager.truncate_logs) + try: + results = await self._run_in_executor( + logger_manager.truncate_logs, *args + ) + except ClearRefused as refused: + return web.json_response( + {"success": False, "error": str(refused), "code": refused.code}, + status=409, + ) return web.json_response( { diff --git a/tests/browser/workspace-system-diagnostics.spec.mjs b/tests/browser/workspace-system-diagnostics.spec.mjs index c0bcb96..9f81136 100644 --- a/tests/browser/workspace-system-diagnostics.spec.mjs +++ b/tests/browser/workspace-system-diagnostics.spec.mjs @@ -516,7 +516,7 @@ test('a rollover after the review deletes nothing and Activity offers Review aga test('Clear all logs states both counts, confirms first and reads everything again', async ({ page, request }) => { await seedLogs(request, LOG_FOLDER); const truncates = []; - page.on('request', item => { if (item.url().endsWith('/prompt_manager/logs/truncate')) truncates.push(item.url()); }); + page.on('request', item => { if (item.url().endsWith('/prompt_manager/logs/truncate')) truncates.push(item.postDataJSON()); }); await openDiagnostics(page); await expect(lines(page)).toContainText('Database backup verified'); const details = await openFiles(page); @@ -535,6 +535,10 @@ test('Clear all logs states both counts, confirms first and reads everything aga await dialog(page).getByRole('button', { name: 'Clear', exact: true }).click(); await expect(toast(page)).toHaveText('Logs cleared · 3 rotated copies deleted.'); expect(truncates).toHaveLength(1); + // #389: Clear sends back exactly the files the dialog was built from, each with its identity string. + expect(truncates[0].expected.map(row => row.name).sort()).toEqual(['prompt_manager.log', 'prompt_manager.log.1', + 'prompt_manager.log.2', 'prompt_manager.log.3']); + for (const row of truncates[0].expected) expect(row.identity).toMatch(/^\d+:\d+:\d+$/); // Read again: the viewer, the file line and the list. await expect(lines(page)).not.toContainText('Database backup verified'); await expect(details.locator(':scope > p.small').first()).toHaveText(/rotated copies: 0$/); @@ -564,6 +568,23 @@ test('Clear all logs reads the files again before it states what it deletes', as expect(await names(request)).toEqual(['prompt_manager.log', 'prompt_manager.log.1', 'prompt_manager.log.2', 'prompt_manager.log.3']); }); +test('a rollover while Clear all logs is open deletes nothing and says why (#389)', async ({ page, request }) => { + await seedLogs(request, { rotated: [1024, 1024], active: 100 }); + await openDiagnostics(page); + await openFiles(page); + await operation(page, 'Clear all logs').getByRole('button', { name: 'Clear all logs…', exact: true }).click(); + await expect(dialog(page).locator('#modal-body > p')).toHaveText(/^Empties prompt_manager\.log, deletes 2 rotated copies /); + // The log rolls over after the confirmation was built: the copies it listed are not the ones there now. + await expect(await request.post('/__test__/logs/rotate')).toBeOK(); + const rolled = await names(request); + const answer = page.waitForResponse(response => response.url().endsWith('/prompt_manager/logs/truncate')); + await dialog(page).getByRole('button', { name: 'Clear', exact: true }).click(); + expect((await answer).status()).toBe(409); + await expect(toast(page)).toHaveText('The log files changed since you confirmed; nothing was cleared. ' + + 'Read the list again and clear again.'); + expect(await names(request)).toEqual(rolled); +}); + test('each listed file downloads by its returned name and a link has no Download', async ({ page, request }) => { await seedLogs(request, LOG_FOLDER); await openDiagnostics(page); diff --git a/tests/browser/workspace_diagnostics_fixture.py b/tests/browser/workspace_diagnostics_fixture.py index b55cf34..bdbc119 100644 --- a/tests/browser/workspace_diagnostics_fixture.py +++ b/tests/browser/workspace_diagnostics_fixture.py @@ -123,6 +123,34 @@ def _touch(path: Path, size: int, moment: datetime.datetime) -> None: os.utime(path, (stamp, stamp)) +def _append_active(manager, log_dir: Path, size: int) -> None: + """Grow the active log as this process's handler does (#389). + + A second handle appending to the file the handler writes is what Clear + all logs refuses as another program writing to it, so the bytes go + through the handler's own stream; with file logging off, to the file. + """ + + def same(path) -> bool: + return os.path.normcase(os.path.realpath(path)) == os.path.normcase( + os.path.realpath(log_dir / ACTIVE) + ) + + for handler in manager._file_handlers(): + stream = getattr(handler, "stream", None) + if stream is None or not same(handler.baseFilename): + continue + handler.acquire() + try: + stream.write("x" * size) + stream.flush() + finally: + handler.release() + return + with open(log_dir / ACTIVE, "ab") as handle: + handle.write(b"x" * size) + + def _bounded(value, name, top=MAX_SEED_BYTES): if isinstance(value, bool) or not isinstance(value, int) or not 0 <= value <= top: raise web.HTTPBadRequest(text=f"{name} must be an integer 0..{top}") @@ -169,8 +197,7 @@ def register_diagnostics_commands(app, routes, api, root: Path): for index, (time_text, level, message) in enumerate(CONCEPT_RECORDS): record = _record(time_text, level, message, index) manager.add_to_buffer(record, record.getMessage()) - with open(log_dir / ACTIVE, "ab") as handle: - handle.write(b"x" * CONCEPT_ACTIVE) + _append_active(manager, log_dir, CONCEPT_ACTIVE) for number, size in enumerate(CONCEPT_ROTATED, start=1): moment = ROTATED_TIME - datetime.timedelta(hours=number) _touch(log_dir / f"{ACTIVE}.{number}", size, moment) @@ -194,8 +221,7 @@ def register_diagnostics_commands(app, routes, api, root: Path): manager.add_to_buffer(record, record.getMessage()) active = _bounded(data.get("active", 0), "active") if active: - with open(log_dir / ACTIVE, "ab") as handle: - handle.write(b"x" * active) + _append_active(manager, log_dir, active) rotated = data.get("rotated", []) if not isinstance(rotated, list) or len(rotated) > 20: raise web.HTTPBadRequest(text="rotated must be a list of sizes") diff --git a/tests/js/workspace-system-diagnostics.test.js b/tests/js/workspace-system-diagnostics.test.js index 65b0bdd..161c1bf 100644 --- a/tests/js/workspace-system-diagnostics.test.js +++ b/tests/js/workspace-system-diagnostics.test.js @@ -175,6 +175,28 @@ test('Clear all logs states both counts and its toast says what was done', async assert.equal(clearToast(undefined), 'Logs cleared · 0 rotated copies deleted.'); }); +test('Clear all logs sends back exactly the files its confirmation showed (#389)', async () => { + const { clearBody, clearFailureText, COPY } = await diagnostics; + const files = [ + { filename: 'prompt_manager.log', kind: 'active', identity: '10:1761000000123456789:9007199254740993' }, + { filename: 'prompt_manager.log.1', kind: 'rotated', identity: '20:1761000000123456789:42' }, + { filename: 'prompt_manager.log.4', kind: 'link', identity: '5:1:7' }, + { filename: 'prompt_manager.log.bak', kind: 'other', identity: '1:1:8' }, + { filename: 'prompt_manager.log.2', kind: 'rotated' }, + ]; + // Identities stay strings: mtime_ns and large inodes are not exact JS numbers. + assert.deepEqual(clearBody(files), { expected: [ + { name: 'prompt_manager.log', identity: '10:1761000000123456789:9007199254740993' }, + { name: 'prompt_manager.log.1', identity: '20:1761000000123456789:42' }, + ] }); + assert.deepEqual(clearBody([]), { expected: [] }); + assert.deepEqual(clearBody(null), {}); + const refused = Object.assign(new Error('The log files changed since you confirmed; nothing was cleared.'), { status: 409 }); + assert.equal(clearFailureText(refused), refused.message); + assert.equal(clearFailureText(Object.assign(new Error('boom'), { status: 500 })), COPY.clearFailed); + assert.equal(clearFailureText(undefined), COPY.clearFailed); +}); + test('the test-link dialog names the prompt and how Missing-file links removes the record', async () => { const { testLinkSentence, promptName } = await diagnostics; assert.equal(testLinkSentence({ id: 812, text: 'Misty harbor' }), 'Writes a placeholder image record ' diff --git a/tests/test_api_log_cleanup.py b/tests/test_api_log_cleanup.py index d928708..9622e59 100644 --- a/tests/test_api_log_cleanup.py +++ b/tests/test_api_log_cleanup.py @@ -415,5 +415,74 @@ class TestApply(LogCleanupTestCase): self.assertEqual(job.status_line, "The log cleanup failed.") +TRUNCATE = "/prompt_manager/logs/truncate" +FILES = "/prompt_manager/logs/files" + + +class TestClearAllLogsConfirmed(LogCleanupTestCase): + """#389: POST /logs/truncate deletes no more than the confirmation listed.""" + + async def confirmed(self): + response = await self.client.request("GET", FILES) + data = await response.json() + return [ + {"name": row["filename"], "identity": row["identity"]} + for row in data["files"] + if row["kind"] in ("active", "rotated") + ] + + def handler(self): + return next( + h + for h in self.manager.logger.handlers + if isinstance(h, logging.FileHandler) + ) + + async def test_a_rollover_after_the_confirmation_is_refused(self): + self.write("prompt_manager.log.1", b"a" * 100) + self.write("prompt_manager.log.2", b"b" * 200) + expected = await self.confirmed() + self.app_logger.info("written after the confirmation") + self.handler().doRollover() + before = self.snapshot() + body = await self.post(TRUNCATE, {"expected": expected}, 409) + self.assertEqual(body["success"], False) + self.assertEqual(body["code"], "logs-changed") + self.assertIn("nothing was cleared", body["error"]) + self.assertEqual(self.snapshot(), before) + + async def test_the_confirmed_files_are_cleared(self): + self.write("prompt_manager.log.1", b"a" * 100) + expected = await self.confirmed() + body = await self.post(TRUNCATE, {"expected": expected}, 200) + self.assertEqual( + sorted(body["results"]["truncated"]), + ["prompt_manager.log", "prompt_manager.log.1"], + ) + self.assertEqual(self.names(), ["prompt_manager.log"]) + + async def test_the_legacy_call_without_a_body_still_clears(self): + self.write("prompt_manager.log.1", b"a" * 100) + response = await self.client.request("POST", TRUNCATE) + self.assertEqual(response.status, 200, await response.text()) + self.assertEqual(self.names(), ["prompt_manager.log"]) + + async def test_a_foreign_writer_is_refused_with_a_clear_message(self): + self.write("prompt_manager.log.1", b"a" * 100) + with open(self.path("prompt_manager.log"), "ab") as other: + other.write(b"line from another ComfyUI\n") + body = await self.post(TRUNCATE, {"expected": await self.confirmed()}, 409) + self.assertEqual(body["code"], "logs-foreign-writer") + self.assertIn("Another program is writing", body["error"]) + self.assertIn("prompt_manager.log.1", self.names()) + + async def test_a_malformed_confirmation_is_400(self): + self.write("prompt_manager.log.1", b"a" * 100) + for expected in ("all", [{"name": "prompt_manager.log.1", "identity": 5}]): + with self.subTest(expected=expected): + await self.post(TRUNCATE, {"expected": expected}, 400) + self.assertIn("prompt_manager.log.1", self.names()) + + if __name__ == "__main__": unittest.main() diff --git a/tests/test_utils_logging_config.py b/tests/test_utils_logging_config.py index 3b07911..d64ee51 100644 --- a/tests/test_utils_logging_config.py +++ b/tests/test_utils_logging_config.py @@ -709,7 +709,8 @@ class TestRotatedCopyRule(IsolatedLoggerTestCase): self.assertNotEqual(link["size"], os.path.getsize(target)) for row in rows.values(): self.assertEqual( - set(row), {"filename", "path", "size", "modified", "is_main", "kind"} + set(row), + {"filename", "path", "size", "modified", "is_main", "kind", "identity"}, ) def test_an_unreadable_timestamp_does_not_break_the_scan(self): @@ -763,6 +764,217 @@ class TestRotatedCopyRule(IsolatedLoggerTestCase): self.manager.log_file_entry(name) +class TestClearOnlyWhatWasConfirmed(IsolatedLoggerTestCase): + """#389: Clear all logs empties or deletes no more than its confirmation showed.""" + + 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) + + def _read(self, path): + with open(path, "rb") as handle: + return handle.read() + + def _snapshot(self): + return {name: self._read(self._path(name)) for name in os.listdir(self.log_dir)} + + def _assert_unchanged(self, before, growing="prompt_manager.log"): + """Nothing deleted or emptied (the refusal itself logs to ``growing``).""" + after = self._snapshot() + self.assertEqual(sorted(after), sorted(before)) + for name, data in before.items(): + if name == growing: + self.assertTrue(after[name].startswith(data), name) + else: + self.assertEqual(after[name], data, name) + + def _confirmed(self): + """What the workspace dialog showed: the listed active and rotated rows.""" + return [ + {"name": row["filename"], "identity": row["identity"]} + for row in self.manager.get_log_files() + if row["kind"] in ("active", "rotated") + ] + + def _file_handler(self): + return next( + h + for h in self.manager.logger.handlers + if isinstance(h, logging.FileHandler) + ) + + def test_listed_identity_is_a_string_that_survives_json_numbers(self): + # mtime_ns (~1.7e18) and many inodes exceed 2**53: as JSON numbers a + # browser would round them and every confirmed clear would be refused. + self._write("prompt_manager.log.1") + for row in self.manager.get_log_files(): + with self.subTest(name=row["filename"]): + self.assertIsInstance(row["identity"], str) + self.assertRegex(row["identity"], r"^\d+:-?\d+:\d+$") + + def test_a_copy_dated_before_1970_can_be_confirmed(self): + self._write("prompt_manager.log.1") + try: + os.utime(self._path("prompt_manager.log.1"), ns=(0, -(10**9))) + except (OSError, OverflowError, ValueError) as error: + self.skipTest(f"this filesystem cannot store a time before 1970: {error}") + confirmed = self._confirmed() + if not any(":-" in row["identity"] for row in confirmed): + self.skipTest("the filesystem did not keep the negative time") + result = self.manager.truncate_logs(confirmed) + self.assertIn("prompt_manager.log.1", result["truncated"]) + + def test_a_rollover_after_the_confirmation_deletes_nothing(self): + self._write("prompt_manager.log.1", b"one" * 10) + self._write("prompt_manager.log.2", b"two" * 10) + confirmed = self._confirmed() + self.logger.info("written after the confirmation") + self._file_handler().doRollover() # .2 -> .3, .1 -> .2, log -> .1 + before = self._snapshot() + with self.assertRaises(logging_config.ClearRefused) as caught: + self.manager.truncate_logs(confirmed) + self.assertEqual(caught.exception.code, "logs-changed") + self._assert_unchanged(before) + + def test_a_copy_that_appeared_after_the_confirmation_is_kept(self): + self._write("prompt_manager.log.1", b"one") + confirmed = self._confirmed() + self._write("prompt_manager.log.5", b"not shown") + result = self.manager.truncate_logs(confirmed) + self.assertEqual(result["errors"], []) + self.assertEqual( + sorted(result["truncated"]), ["prompt_manager.log", "prompt_manager.log.1"] + ) + self.assertEqual( + sorted(os.listdir(self.log_dir)), + ["prompt_manager.log", "prompt_manager.log.5"], + ) + + def _clear(self, confirmed=None): + """Run a clear and return what it raised (None), so the files are + asserted first: on the old code the test fails on lost bytes.""" + try: + if confirmed is None: + self.manager.truncate_logs() # the legacy page's call + else: + self.manager.truncate_logs(confirmed) + except Exception as error: # noqa: BLE001 - asserted below + return error + return None + + def test_a_foreign_append_to_the_active_log_is_refused(self): + # A second ComfyUI sharing the folder writes the same active log. + self._write("prompt_manager.log.1") + listings = (None, "listed") + for listing in listings: + with self.subTest(listed=listing is not None): + confirmed = self._confirmed() if listing else None + with open(self._path("prompt_manager.log"), "ab") as other: + other.write(b"line from another process\n") + before = self._snapshot() + error = self._clear(confirmed) + self._assert_unchanged(before) + self.assertEqual(getattr(error, "code", None), "logs-foreign-writer") + self.logger.info("our own line") # our stream catches up again + + @unittest.skipIf(os.name == "nt", "Windows cannot rename a log that is open") + def test_a_foreign_rotation_of_our_log_is_refused(self): + # Another process rolled the shared log over: our handler still writes + # the file now named .1, and a new active log is the other's. + os.rename(self._path("prompt_manager.log"), self._path("prompt_manager.log.1")) + self._write("prompt_manager.log", b"the other process's log\n") + before = self._snapshot() + with self.assertRaises(logging_config.ClearRefused) as caught: + self.manager.truncate_logs() + self.assertEqual(caught.exception.code, "logs-foreign-writer") + # Our handler still writes the renamed file, so the refusal lands there. + self._assert_unchanged(before, growing="prompt_manager.log.1") + + def test_a_copy_that_changes_mid_clear_stops_the_clear(self): + # The identity is checked again just before each unlink: another + # process rotating while we delete stops the clear there. + for n in (1, 2): + self._write(f"prompt_manager.log.{n}", b"r" * n) + confirmed = self._confirmed() + real_unlink = os.unlink + calls = [] + + def unlink_then_rotate(path, *args, **kwargs): + real_unlink(path, *args, **kwargs) + if not calls: + with open(self._path("prompt_manager.log.2"), "ab") as handle: + handle.write(b"rotated in by another process") + calls.append(os.path.basename(path)) + + active_before = self._read(self._path("prompt_manager.log")) + with mock.patch.object(logging_config.os, "unlink", unlink_then_rotate): + result = self.manager.truncate_logs(confirmed) + self.assertEqual(calls, ["prompt_manager.log.1"]) + self.assertEqual(result["truncated"], ["prompt_manager.log.1"]) + self.assertEqual(len(result["errors"]), 1) + self.assertIn("prompt_manager.log.2", result["errors"][0]) + self.assertTrue(os.path.exists(self._path("prompt_manager.log.2"))) + # The active log is emptied last, so it is kept too. + self.assertTrue( + self._read(self._path("prompt_manager.log")).startswith(active_before) + ) + + def _require_hard_link(self, source, link): + try: + os.link(source, link) + except (OSError, NotImplementedError, AttributeError) as error: + self.skipTest(f"this filesystem cannot make hard links: {error}") + + def test_a_hard_linked_active_log_is_never_emptied(self): + other_name = os.path.join(self.outside, "kept-by-the-user.log") + self._require_hard_link(self._path("prompt_manager.log"), other_name) + kept = self._read(other_name) + self.assertTrue(kept) + for listed in (False, True): + with self.subTest(listed=listed): + error = self._clear(self._confirmed() if listed else None) + self.assertTrue(self._read(other_name).startswith(kept)) + self.assertEqual(getattr(error, "code", None), "logs-hard-link") + + def test_a_hard_linked_active_log_with_file_logging_off_is_kept(self): + self.manager.update_config({"file_logging": False}) + other_name = os.path.join(self.outside, "kept-by-the-user.log") + self._require_hard_link(self._path("prompt_manager.log"), other_name) + kept = self._read(other_name) + error = self._clear() + self.assertEqual(self._read(other_name), kept) + self.assertEqual(getattr(error, "code", None), "logs-hard-link") + + def test_a_malformed_confirmation_is_refused_before_anything_changes(self): + self._write("prompt_manager.log.1") + before = self._snapshot() + for expected in ( + "prompt_manager.log.1", + [{"name": "prompt_manager.log.1"}], + [{"name": "prompt_manager.log.1", "identity": 7}], + [{"name": "prompt_manager.log.1", "identity": "1:2"}], + [{"name": 1, "identity": "1:2:3"}], + [ + {"name": "prompt_manager.log.1", "identity": "1:2:3"}, + {"name": "prompt_manager.log.1", "identity": "1:2:3"}, + ], + ["prompt_manager.log.1"], + ): + with self.subTest(expected=expected): + with self.assertRaises(ValueError): + self.manager.truncate_logs(expected) + self._assert_unchanged(before) + + class TestConfiguration(IsolatedLoggerTestCase): def test_in_flight_record_cannot_reopen_retired_file_handler(self) -> None: handler = next( diff --git a/utils/logging_config.py b/utils/logging_config.py index 97a3763..08bb0a2 100644 --- a/utils/logging_config.py +++ b/utils/logging_config.py @@ -39,6 +39,35 @@ class RotatedChanged(Exception): self.name = name +# Clear all logs (#389): why it changed nothing, as the API and the pages say it. +CLEAR_CHANGED = ( + "The log files changed since you confirmed; nothing was cleared." + " Read the list again and clear again." +) +CLEAR_FOREIGN_WRITER = ( + "Another program is writing to prompt_manager.log, such as a second ComfyUI" + " sharing this log folder; nothing was cleared. Stop it and clear again." +) +CLEAR_HARD_LINK = ( + "prompt_manager.log has another name (a hard link); emptying it would empty" + " that file too, so nothing was cleared. Remove the other name, then clear" + " again." +) +# A confirmed row's identity: "::", a string because +# mtime_ns and many inodes are larger than a browser's exact integers. +# mtime_ns is negative for a time before 1970 (a restored archive, say). +_IDENTITY = re.compile(r"([0-9]{1,20}):(-?[0-9]{1,20}):([0-9]{1,40})") +MAX_CONFIRMED_ROWS = 10000 + + +class ClearRefused(Exception): + """Clear all logs changed nothing; ``code`` names why, the message says it.""" + + def __init__(self, code: str, message: str): + super().__init__(message) + self.code = code + + def _name_key(name: str) -> str: """How a name compares: case-folded where the filesystem folds it (Windows).""" return os.path.normcase(name) @@ -87,35 +116,37 @@ def scan_log_folder(log_dir) -> List[Dict[str, Any]]: 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 - try: - modified = datetime.fromtimestamp(st.st_mtime).isoformat() - except (OSError, OverflowError, ValueError): # a time before 1970 on Windows - modified = "" - rows.append( - { - "name": name, - "kind": kind, - "size": st.st_size, - "mtime_ns": st.st_mtime_ns, - "ino": st.st_ino, - "modified": modified, - "_dir": stat.S_ISDIR(st.st_mode) and kind != "link", - "_regular": stat.S_ISREG(st.st_mode) and kind != "link", - } - ) - return rows + return [] + rows = (scan_log_entry(log_dir, name) for name in names) + return [row for row in rows if row is not None] + + +def scan_log_entry(log_dir, name) -> Optional[Dict[str, Any]]: + """One entry's scan row (``lstat``), or None when it cannot be read.""" + path = os.path.join(log_dir, name) + try: + st = os.lstat(path) + kind = _kind(name, path, st) + except OSError: + return None + try: + modified = datetime.fromtimestamp(st.st_mtime).isoformat() + except (OSError, OverflowError, ValueError): # a time before 1970 on Windows + modified = "" + return { + "name": name, + "kind": kind, + "size": st.st_size, + "mtime_ns": st.st_mtime_ns, + "ino": st.st_ino, + "modified": modified, + "_dir": stat.S_ISDIR(st.st_mode) and kind != "link", + "_regular": stat.S_ISREG(st.st_mode) and kind != "link", + "_nlink": st.st_nlink, + } def public_row(row: Dict[str, Any]) -> Dict[str, Any]: @@ -127,6 +158,37 @@ def rotated_sort_key(row: Dict[str, Any]) -> int: return _rotated_number(row["name"]) or 0 +def file_identity(row: Dict[str, Any]) -> str: + """A listed file's identity as the client sends it back: size, mtime_ns, ino.""" + return f"{row['size']}:{row['mtime_ns']}:{row['ino']}" + + +def parse_confirmed(expected) -> List[Dict[str, Any]]: + """The rows a Clear all logs confirmation showed, as review rows. + + ``expected`` is a list of ``{name, identity}`` objects from + ``/logs/files``; anything else raises ValueError. + """ + if not isinstance(expected, list) or len(expected) > MAX_CONFIRMED_ROWS: + raise ValueError("expected must be a list of listed log files") + rows, seen = [], set() + for item in expected: + if not isinstance(item, dict): + raise ValueError("each expected file must be an object") + name, identity = item.get("name"), item.get("identity") + if not isinstance(name, str) or not isinstance(identity, str): + raise ValueError("each expected file needs a name and an identity") + match = _IDENTITY.fullmatch(identity) + if match is None: + raise ValueError("an expected file's identity is not size:mtime_ns:ino") + size, mtime_ns, ino = (int(part) for part in match.groups()) + if _name_key(name) in seen: + raise ValueError("an expected file is listed twice") + seen.add(_name_key(name)) + rows.append({"name": name, "size": size, "mtime_ns": mtime_ns, "ino": ino}) + return rows + + def log_file_entry(log_dir, name) -> Path: """The path of a downloadable log file named ``name`` (blocking). @@ -157,6 +219,11 @@ def _stream_is(stream, ino: int) -> bool: return not (ino and open_ino and open_ino != ino) +def _stream_ino_is(opened: os.stat_result, ino: int) -> bool: + """Whether a stream's ``fstat`` is the file with inode ``ino`` (0: unknown).""" + return not (ino and opened.st_ino and opened.st_ino != ino) + + def _error_text(error: BaseException) -> str: """An OSError's reason and file name, without the folder it is in.""" if isinstance(error, OSError): @@ -432,6 +499,7 @@ class PromptManagerLogger: "modified": row["modified"], "is_main": row["kind"] == "active", "kind": row["kind"], + "identity": file_identity(row), } ) @@ -530,8 +598,14 @@ class PromptManagerLogger: finally: handler.release() if not handled: - flags = os.O_WRONLY | os.O_TRUNC | getattr(os, "O_NOFOLLOW", 0) - os.close(os.open(str(log_file), flags)) + flags = os.O_WRONLY | getattr(os, "O_NOFOLLOW", 0) + fd = os.open(str(log_file), flags) + try: + if os.fstat(fd).st_nlink > 1: # emptying it would empty the other + raise ClearRefused("logs-hard-link", CLEAR_HARD_LINK) + os.ftruncate(fd, 0) + finally: + os.close(fd) def delete_rotated(self, expected: List[Dict[str, Any]]) -> Dict[str, Any]: """Delete exactly the reviewed rotated copies, or none of them (blocking). @@ -582,47 +656,126 @@ class PromptManagerLogger: ) return {"removed": removed, "failed": failed} - def truncate_logs(self) -> Dict[str, Any]: - """Empty the active log and delete its rotated copies (Rule R). + def _active_streams(self, active: Optional[Dict[str, Any]]): + """``fstat`` and offset of every handler stream writing the active name.""" + target = os.path.normcase( + os.path.realpath(os.path.join(self.log_dir, ACTIVE_LOG_NAME)) + ) + for handler in self._file_handlers(): + stream = getattr(handler, "stream", None) + base = getattr(handler, "baseFilename", None) + if stream is None or base is None: + continue + if os.path.normcase(os.path.realpath(base)) != target: + continue + try: + stream.flush() + fd = stream.fileno() + yield os.fstat(fd), os.lseek(fd, 0, os.SEEK_CUR) + except (OSError, ValueError, AttributeError): + continue - 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. + def _check_clear_is_safe(self, rows, active) -> None: + """Refuse a clear that would empty or delete what nobody confirmed. + + Called under the files lock and every handler lock, so nothing of this + process writes or rolls over meanwhile; what changes is another + program's doing. Our handler's stream is flushed: a file larger than + the stream's own offset was appended to by someone else, and a stream + whose file is now a rotated copy was rolled over by someone else. + Either is a second writer (another ComfyUI sharing the folder). This + is best effort, not a lock: writes before our own last write, or any + write while this process has file logging off, go unseen. An + active log with more than one name (a hard link) is never emptied: the + other name would be emptied too. + """ + rotated = {row["ino"] for row in rows if row["kind"] == "rotated"} + rotated.discard(0) + nlink = active["_nlink"] if active is not None else 1 + for opened, offset in self._active_streams(active): + if (opened.st_ino and opened.st_ino in rotated) or opened.st_size > offset: + raise ClearRefused("logs-foreign-writer", CLEAR_FOREIGN_WRITER) + if active is not None and _stream_ino_is(opened, active["ino"]): + nlink = max(nlink, opened.st_nlink) + if nlink > 1: + raise ClearRefused("logs-hard-link", CLEAR_HARD_LINK) + + @staticmethod + def _confirmed_targets(confirmed, current, active) -> List[Dict[str, Any]]: + """The rotated copies a confirmation listed, each as it was listed. + + Refuses (``logs-changed``) when any listed copy is missing or differs + in kind, size, ``mtime_ns`` or inode, or when the listed active log is + now another file (it was rolled over). A copy nobody listed is kept. + """ + targets = [] + for reviewed in confirmed: + key = _name_key(reviewed["name"]) + row = current.get(key) + if key == _name_key(ACTIVE_LOG_NAME): + ino = reviewed["ino"] + if active is None or (ino and active["ino"] and active["ino"] != ino): + raise ClearRefused("logs-changed", CLEAR_CHANGED) + continue + if _rotated_number(reviewed["name"]) is None: + continue # never deleted, listed or not + if not _matches_review(row, reviewed): + raise ClearRefused("logs-changed", CLEAR_CHANGED) + targets.append(row) + return targets + + def truncate_logs(self, expected=None) -> Dict[str, Any]: + """Empty the active log and delete its rotated copies (Rule R, #389). + + ``expected`` is what the confirmation showed: ``{name, identity}`` + rows of ``/logs/files`` (``parse_confirmed``; ValueError when + malformed). Then only the listed rotated copies are deleted, and only + when each still has the listed size, ``mtime_ns`` and inode and the + active log is still the listed file; otherwise ClearRefused + (``logs-changed``) with nothing changed. Without it (the legacy admin + page, whose confirmation lists nothing) every rotated copy present now + is deleted. + + Either way, a second writer of the active log (``logs-foreign-writer``) + or an active log with a hard link (``logs-hard-link``) refuses the + whole clear first. Each copy's identity is checked again just before + its unlink; one that changed (another process rolling over meanwhile) + stops the clear there, keeping it, the rest and the active log, which + is emptied last. 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 and logs only once they are released. Returns: Dictionary with: - truncated: List of successfully truncated files - errors: List of error messages for failed operations """ + confirmed = None if expected is None else parse_confirmed(expected) results = {"truncated": [], "errors": []} + refused = None with self._files_lock: held = self._acquire_file_handlers() try: 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, - ) - 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), row["ino"]) - 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() + current = {_name_key(row["name"]): row for row in rows} + active = next((row for row in rows if row["kind"] == "active"), None) + try: + if confirmed is None: + targets = [row for row in rows if row["kind"] == "rotated"] + else: + targets = self._confirmed_targets(confirmed, current, active) + self._check_clear_is_safe(rows, active) + except ClearRefused as error: + refused = error + else: + self._clear(sorted(targets, key=rotated_sort_key), active, results) finally: self._release_handlers(held) + if refused is not None: + self.logger.warning("Clear all logs refused (%s)", refused.code) + raise refused if results["truncated"]: self.logger.info("Truncated log files: %s", ", ".join(results["truncated"])) for error_msg in results["errors"]: @@ -630,6 +783,39 @@ class PromptManagerLogger: return results + def _clear(self, targets, active, results) -> None: + """Delete ``targets`` (each re-checked) then empty ``active`` (locks held).""" + for reviewed in targets: + name = reviewed["name"] + if not _matches_review(scan_log_entry(self.log_dir, name), reviewed): + results["errors"].append( + f"{name} changed while clearing (another program may be writing" + " to this log folder); it, the copies after it and the active" + " log were kept" + ) + return + try: + os.unlink(os.path.join(self.log_dir, name)) + results["truncated"].append(name) + except OSError as error: + results["errors"].append( + f"Failed to truncate {name}: {_error_text(error)}" + ) + if active is not None: + try: + self._truncate_main_log( + Path(self.log_dir, active["name"]), active["ino"] + ) + results["truncated"].append(active["name"]) + except ClearRefused as error: + results["errors"].append(str(error)) + except OSError as error: + results["errors"].append( + f"Failed to truncate {active['name']}: {_error_text(error)}" + ) + with self._buffer_lock: + self._log_buffer.clear() + def update_config(self, new_config: Dict[str, Any]): """Update logging configuration. diff --git a/web/js/workspace/system-diagnostics.mjs b/web/js/workspace/system-diagnostics.mjs index 40382ae..776be60 100644 --- a/web/js/workspace/system-diagnostics.mjs +++ b/web/js/workspace/system-diagnostics.mjs @@ -225,6 +225,23 @@ export function clearSentence(files) { return `Empties ${ACTIVE_LOG}, deletes ${number(rotated.length)} rotated ${noun(rotated.length, 'copy', 'copies')} (${sizeText(size)}) ${tail}`; } +/** + * #389: the `/logs/truncate` body for the files a confirmation showed. Their active and rotated rows go back with the + * server's `identity`, so the server deletes only those and refuses (409) when any changed meanwhile. A list that could + * not be read (`null`, the general sentence) sends no list: the server then clears what is there, as the sentence says. + */ +export function clearBody(files) { + if (!Array.isArray(files)) return {}; + const expected = files.filter(row => (row?.kind === 'active' || row?.kind === 'rotated') && typeof row.filename === 'string' + && typeof row.identity === 'string').map(row => ({ name: row.filename, identity: row.identity })); + return { expected }; +} + +/** A refused clear (409) says why in the server's words; any other failure the general line. */ +export function clearFailureText(error) { + return error?.status === 409 && typeof error.message === 'string' && error.message ? error.message : COPY.clearFailed; +} + /** CUJ 7: the toast for `/logs/truncate`'s `results` ({truncated: [names], errors: [messages]}). */ export function clearToast(results) { const truncated = Array.isArray(results?.truncated) ? results.truncated : []; @@ -469,13 +486,14 @@ function logsSurface({ api, activity, scope, drafts, navigate, notify, latestOnl const list = el('div', undefined, 'operation-list'); let listed = null; // The confirmation names what Clear deletes now: the files are read again before it opens (a read that fails - // gives the general sentence, never an old count). + // gives the general sentence, never an old count). Clear sends exactly the files the dialog was built from (#389). const clear = operationRow({ scope, title: 'Clear all logs', description: COPY.clearDescription, label: 'Clear all logs…', danger: true, onClick: button => pressing(button, async () => { await readFiles(); if (scope.signal.aborted) return; - confirmDialog({ scope, trigger: button, title: 'Clear all logs', sentence: clearSentence(listed), label: 'Clear', - danger: true, onConfirm: clearLogs }); + const shown = listed; + confirmDialog({ scope, trigger: button, title: 'Clear all logs', sentence: clearSentence(shown), label: 'Clear', + danger: true, onConfirm: () => clearLogs(shown) }); }) }); files.append(el('summary', 'Log files & retention'), line, review, retention, list, clear); const runtime = runtimeRows({ scope, drafts }); @@ -562,12 +580,12 @@ function logsSurface({ api, activity, scope, drafts, navigate, notify, latestOnl readConfig(); } - async function clearLogs() { + async function clearLogs(shown) { let answer; try { - answer = await api.post(TRUNCATE_URL, {}); - } catch { - if (!scope.signal.aborted) notify(COPY.clearFailed); + answer = await api.post(TRUNCATE_URL, clearBody(shown)); + } catch (error) { + if (!scope.signal.aborted) notify(clearFailureText(error)); } if (scope.signal.aborted) return; if (answer) notify(clearToast(answer.results));