diff --git a/TESTING.md b/TESTING.md index f8341da1..ab534f3d 100644 --- a/TESTING.md +++ b/TESTING.md @@ -3991,7 +3991,9 @@ modals use the same routes and keep working. - 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: a second writer of the active log (our + - 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`, diff --git a/tests/test_utils_logging_config.py b/tests/test_utils_logging_config.py index 728d7f52..d64ee51e 100644 --- a/tests/test_utils_logging_config.py +++ b/tests/test_utils_logging_config.py @@ -819,7 +819,19 @@ class TestClearOnlyWhatWasConfirmed(IsolatedLoggerTestCase): 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+$") + 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) @@ -847,21 +859,31 @@ class TestClearOnlyWhatWasConfirmed(IsolatedLoggerTestCase): ["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") - for confirmed in (self._confirmed(), None): - with self.subTest(listed=confirmed is not None): + 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() - with self.assertRaises(logging_config.ClearRefused) as caught: - if confirmed is None: - self.manager.truncate_logs() # the legacy page's call - else: - self.manager.truncate_logs(confirmed) - self.assertEqual(caught.exception.code, "logs-foreign-writer") + 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") @@ -917,24 +939,20 @@ class TestClearOnlyWhatWasConfirmed(IsolatedLoggerTestCase): self._require_hard_link(self._path("prompt_manager.log"), other_name) kept = self._read(other_name) self.assertTrue(kept) - for call in (lambda: self.manager.truncate_logs(), None): - with self.subTest(listed=call is None): - with self.assertRaises(logging_config.ClearRefused) as caught: - if call is None: - self.manager.truncate_logs(self._confirmed()) - else: - call() - self.assertEqual(caught.exception.code, "logs-hard-link") + 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) - with self.assertRaises(logging_config.ClearRefused): - self.manager.truncate_logs() + 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") @@ -945,6 +963,10 @@ class TestClearOnlyWhatWasConfirmed(IsolatedLoggerTestCase): [{"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): diff --git a/utils/logging_config.py b/utils/logging_config.py index cb944ad2..08bb0a26 100644 --- a/utils/logging_config.py +++ b/utils/logging_config.py @@ -50,12 +50,14 @@ CLEAR_FOREIGN_WRITER = ( ) CLEAR_HARD_LINK = ( "prompt_manager.log has another name (a hard link); emptying it would empty" - " that file too, so nothing was cleared." + " 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. -_IDENTITY = re.compile(r"([0-9]{1,20}):([0-9]{1,20}):([0-9]{1,40})") -MAX_CONFIRMED_ROWS = 1000 +# 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): @@ -169,7 +171,7 @@ def parse_confirmed(expected) -> List[Dict[str, Any]]: """ if not isinstance(expected, list) or len(expected) > MAX_CONFIRMED_ROWS: raise ValueError("expected must be a list of listed log files") - rows = [] + rows, seen = [], set() for item in expected: if not isinstance(item, dict): raise ValueError("each expected file must be an object") @@ -180,6 +182,9 @@ def parse_confirmed(expected) -> List[Dict[str, Any]]: 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 @@ -678,7 +683,9 @@ class PromptManagerLogger: 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). An + 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. """