From 2465fca6ca2e52b59845371d3d230367d5b45725 Mon Sep 17 00:00:00 2001 From: Delgan <4193924+Delgan@users.noreply.github.com> Date: Thu, 31 Aug 2023 15:06:05 +0200 Subject: [PATCH] Fix incorrect rotation when re-starting around midnight (#894) --- CHANGELOG.rst | 5 +- loguru/_file_sink.py | 15 +++--- tests/test_filesink_rotation.py | 92 +++++++++++++++++++++++++++++++++ 3 files changed, 101 insertions(+), 11 deletions(-) diff --git a/CHANGELOG.rst b/CHANGELOG.rst index 47ca76ea..8286a31a 100644 --- a/CHANGELOG.rst +++ b/CHANGELOG.rst @@ -2,10 +2,11 @@ ============= - Add a new ``context`` optional argument to ``logger.add()`` specifying ``multiprocessing`` context (like ``"spawn"`` or ``"fork"``) to be used internally instead of the default one (`#851 `_). -- Raise ``ValueError`` if an attempt to use nanosecond precision for time formatting is detected (`#855 `_). - Add support for true colors on Windows using ANSI/VT console when available (`#934 `_, thanks `@tunaflsh `_). -- Fix inverted ``""`` and ``""`` color tags (`#943 `_, thanks `@tunaflsh `_). +- Fix file possibly rotating too early or too late when re-starting an application around midnight (`#894 `_). +- Fix inverted ``""`` and ``""`` color tags (`#943 `_, thanks `@tunaflsh `_). - Fix possible errors raised by logging non-picklable ``Exception`` instances while using ``enqueue=True`` (`#342 `_, thanks `@ncoudene `_). +- Raise ``ValueError`` if an attempt to use nanosecond precision for time formatting is detected (`#855 `_). `0.7.0`_ (2023-04-10) diff --git a/loguru/_file_sink.py b/loguru/_file_sink.py index 35b252f9..564e93f3 100644 --- a/loguru/_file_sink.py +++ b/loguru/_file_sink.py @@ -128,15 +128,12 @@ def __call__(self, message, file): limit = start_time.astimezone(record_time.tzinfo).replace(tzinfo=None) limit = self._step_forward(limit) else: - limit = datetime.datetime( - start_time.year, - start_time.month, - start_time.day, - time_init.hour, - time_init.minute, - time_init.second, - time_init.microsecond, - record_time.tzinfo if time_init.tzinfo is None else time_init.tzinfo, + tzinfo = record_time.tzinfo if time_init.tzinfo is None else time_init.tzinfo + limit = start_time.astimezone(tzinfo).replace( + hour=time_init.hour, + minute=time_init.minute, + second=time_init.second, + microsecond=time_init.microsecond, ) if limit <= start_time: diff --git a/tests/test_filesink_rotation.py b/tests/test_filesink_rotation.py index ef211ed3..1bd09cf3 100644 --- a/tests/test_filesink_rotation.py +++ b/tests/test_filesink_rotation.py @@ -605,6 +605,98 @@ def test_time_rotation_when_timezone_changes_backward_rename_file(freeze_time, t ) +@pytest.mark.parametrize( + "rotation", + [ + "00:15", + datetime.time(0, 15, 0), + datetime.time(23, 15, 0, tzinfo=datetime.timezone.utc), + datetime.time(0, 15, 0, tzinfo=datetime.timezone(datetime.timedelta(seconds=+3600))), + datetime.time(22, 15, 0, tzinfo=datetime.timezone(datetime.timedelta(seconds=-3600))), + ], +) +def test_dont_rotate_earlier_when_utc_is_one_day_before(freeze_time, tmp_path, rotation): + with freeze_time("2018-10-24 00:30:00", ("CET", +3600)) as frozen: + logger.add(tmp_path / "test.log", format="{message}", rotation=rotation) + logger.info("First") + logger.remove() + + frozen.tick(delta=datetime.timedelta(hours=1)) + logger.add(tmp_path / "test.log", format="{message}", rotation=rotation) + logger.info("Second") + logger.remove() + + frozen.tick(delta=datetime.timedelta(hours=23)) + logger.add(tmp_path / "test.log", format="{message}", rotation=rotation) + logger.info("Third") + logger.remove() + + check_dir( + tmp_path, + files=[ + ("test.2018-10-24_00-30-00_000000.log", "First\nSecond\n"), + ("test.log", "Third\n"), + ], + ) + + +@pytest.mark.parametrize( + "rotation", + [ + "23:45", + datetime.time(23, 45, 0), + datetime.time(0, 45, 0, tzinfo=datetime.timezone.utc), + datetime.time(1, 45, 0, tzinfo=datetime.timezone(datetime.timedelta(seconds=+3600))), + datetime.time(23, 45, 0, tzinfo=datetime.timezone(datetime.timedelta(seconds=-3600))), + ], +) +def test_dont_rotate_later_when_utc_is_one_day_after(freeze_time, tmp_path, rotation): + with freeze_time("2018-10-23 23:30:00", ("CET", -3600)) as frozen: + logger.add(tmp_path / "test.log", format="{message}", rotation=rotation) + logger.info("First") + logger.remove() + + frozen.tick(delta=datetime.timedelta(hours=1)) + logger.add(tmp_path / "test.log", format="{message}", rotation=rotation) + logger.info("Second") + logger.remove() + + frozen.tick(delta=datetime.timedelta(hours=23)) + logger.add(tmp_path / "test.log", format="{message}", rotation=rotation) + logger.info("Third") + logger.remove() + + check_dir( + tmp_path, + files=[ + ("test.2018-10-23_23-30-00_000000.log", "First\n"), + ("test.log", "Second\nThird\n"), + ], + ) + + +@pytest.mark.parametrize("timezone", [("CET", +3600), ("CET", -3600), ("UTC", 0)]) +def test_rotation_at_midnight_with_date_in_filename(freeze_time, tmp_path, timezone): + with freeze_time("2018-10-23 23:55:00", timezone) as frozen: + logger.add(tmp_path / "test.{time:YYYY-MM-DD}.log", format="{message}", rotation="00:00") + logger.info("First") + logger.remove() + + frozen.tick(delta=datetime.timedelta(minutes=10)) + + logger.add(tmp_path / "test.{time:YYYY-MM-DD}.log", format="{message}", rotation="00:00") + logger.info("Second") + logger.remove() + + check_dir( + tmp_path, + files=[ + ("test.2018-10-23.log", "First\n"), + ("test.2018-10-24.log", "Second\n"), + ], + ) + + @pytest.mark.parametrize("delay", [False, True]) def test_time_rotation_reopening_native(tmp_path_local, delay): with tempfile.TemporaryDirectory(dir=str(tmp_path_local)) as test_dir: