Fix error during rotation if renamed dest file exists (#179)

CHANGELOG.rst

@@ -4,18 +4,19 @@
 - Add support for coroutine functions used as sinks and add the new ``logger.complete()`` asynchronous method to ``await`` them (`#171 <https://github.com/Delgan/loguru/issues/171>`_).
 - Add a way to filter logs using one level per module in the form of a ``dict`` passed to the ``filter`` argument (`#148 <https://github.com/Delgan/loguru/issues/148>`_).
 - Add type hints to annotate the public methods using a ``.pyi`` stub file (`#162 <https://github.com/Delgan/loguru/issues/162>`_).
+- Add support for ``copy.deepcopy()`` of the ``logger`` allowing multiple independent loggers with separate set of handlers (`#72 <https://github.com/Delgan/loguru/issues/72>`_).
+- Add the possibility to convert ``datetime`` to UTC before formatting (in logs and filenames) by adding ``"!UTC"`` at the end of the time format specifier (`#128 <https://github.com/Delgan/loguru/issues/128>`_).
+- Add the level ``name`` as the first argument of namedtuple returned by the ``.level()`` method.
 - Remove ``class`` objects from the list of supported sinks and restrict usage of ``**kwargs`` in ``.add()`` to file sink only. User is in charge of instantiating sink and wrapping additional keyword arguments if needed, before passing it to the ``.add()`` method.
 - Rename the ``logger.configure()`` keyword argument ``patch`` to ``patcher`` so it better matches the signature of ``logger.patch()``.
 - Fix incompatibility with ``multiprocessing`` on Windows by entirely refactoring the internal structure of the ``logger`` so it can be inherited by child processes along with added handlers (`#108 <https://github.com/Delgan/loguru/issues/108>`_).
-- Fix an error using a ``filter`` function "by name" while receiving a log with ``record["name"]`` equals to ``None``.
-- Fix incorrect record displayed while handling errors (if ``catch=True``) occurring because of non-picklable objects (if ``enqueue=True``).
 - Fix ``AttributeError`` while using a file sink on some distributions (like Alpine Linux) missing the ``os.getxattr`` and ``os.setxattr`` functions (`#158 <https://github.com/Delgan/loguru/pull/158>`_, thanks `@joshgordon <https://github.com/joshgordon>`_).
 - Fix values wrongly displayed for keyword arguments during exception formatting with ``diagnose=True`` (`#144 <https://github.com/Delgan/loguru/issues/144>`_).
 - Fix logging messages wrongly chopped off at the end while using standard ``logging.Handler`` sinks with ``.opt(raw=True)`` (`#136 <https://github.com/Delgan/loguru/issues/136>`_).
-- Add support for ``copy.deepcopy()`` of the ``logger`` allowing multiple independent loggers with separate set of handlers (`#72 <https://github.com/Delgan/loguru/issues/72>`_).
+- Fix potential errors during rotation if destination file exists due to large resolution clock on Windows (`#179 <https://github.com/Delgan/loguru/issues/179>`_).
+- Fix an error using a ``filter`` function "by name" while receiving a log with ``record["name"]`` equals to ``None``.
+- Fix incorrect record displayed while handling errors (if ``catch=True``) occurring because of non-picklable objects (if ``enqueue=True``).
 - Prevent hypothetical ``ImportError`` if a Python installation is missing the built-in ``distutils`` module (`#118 <https://github.com/Delgan/loguru/issues/118>`_).
-- Add the possibility to convert ``datetime`` to UTC before formatting (in logs and filenames) by adding ``"!UTC"`` at the end of the time format specifier (`#128 <https://github.com/Delgan/loguru/issues/128>`_).
-- Add the level ``name`` as the first argument of namedtuple returned by the ``.level()`` method.
 - Raise ``TypeError`` instead of ``ValueError`` when a ``logger`` method is called with argument of invalid type.
 - Raise ``ValueError`` if the built-in ``format()`` and ``filter()`` functions are respectively used as ``format`` and ``filter`` arguments of the ``add()`` method. This helps the user to understand the problem, as such a mistake can quite easily occur (`#177 <https://github.com/Delgan/loguru/issues/177>`_).
 - Remove inheritance of some record dict attributes to ``str`` (for ``"level"``, ``"file"``, ``"thread"`` and ``"process"``).

loguru/_file_sink.py

@@ -13,6 +13,22 @@
 from ._datetime import aware_now, datetime
 
 
+def generate_rename_path(root, ext):
+    path_to_rename = root + ext
+    creation_time = get_ctime(path_to_rename)
+    creation_datetime = datetime.fromtimestamp(creation_time)
+    date = FileDateFormatter(creation_datetime)
+
+    renamed_path = "{}.{}{}".format(root, date, ext)
+    counter = 1
+
+    while os.path.exists(renamed_path):
+        counter += 1
+        renamed_path = "{}.{}.{}{}".format(root, date, counter, ext)
+
+    return renamed_path
+
+
 class FileDateFormatter:
     def __init__(self, datetime=None):
         self.datetime = datetime or aware_now()
@@ -42,13 +58,10 @@ def copy_compress(path_in, path_out, opener, **kwargs):
 
     @staticmethod
     def compression(path_in, ext, compress_function):
-        path_out = "{}.{}".format(path_in, ext)
+        path_out = "{}{}".format(path_in, ext)
         if os.path.isfile(path_out):
-            creation_time = get_ctime(path_out)
-            creation_datetime = datetime.fromtimestamp(creation_time)
-            date = FileDateFormatter(creation_datetime)
             root, ext_before = os.path.splitext(path_in)
-            renamed_path = "{}.{}{}.{}".format(root, date, ext_before, ext)
+            renamed_path = generate_rename_path(root, ext_before + ext)
             os.rename(path_out, renamed_path)
         compress_function(path_in, path_out)
         os.remove(path_in)
@@ -171,11 +184,8 @@ def _initialize_file(self, *, rename_existing):
         os.makedirs(new_dir, exist_ok=True)
 
         if rename_existing and os.path.isfile(new_path):
-            creation_time = get_ctime(new_path)
-            creation_datetime = datetime.fromtimestamp(creation_time)
-            date = FileDateFormatter(creation_datetime)
             root, ext = os.path.splitext(new_path)
-            renamed_path = "{}.{}{}".format(root, date, ext)
+            renamed_path = generate_rename_path(root, ext)
             os.rename(new_path, renamed_path)
 
         self._file_path = new_path
@@ -311,7 +321,7 @@ def _make_compression_function(compression):
             else:
                 raise ValueError("Invalid compression format: '%s'" % ext)
 
-            return partial(Compression.compression, ext=ext, compress_function=compress)
+            return partial(Compression.compression, ext="." + ext, compress_function=compress)
         elif callable(compression):
             return compression
         else:

tests/test_filesink_compression.py

@@ -80,6 +80,48 @@ def creation_time(filepath):
     assert tmpdir.join("test.2018-01-01_00-00-00_000000.log.tar.gz").check(exists=1)
 
 
+def test_renaming_compression_dest_exists(monkeypatch, monkeypatch_date, tmpdir):
+    date = (2019, 1, 2, 3, 4, 5, 6)
+    timestamp = datetime.datetime(*date).timestamp()
+    monkeypatch_date(*date)
+    monkeypatch.setattr(loguru._file_sink, "get_ctime", lambda _: timestamp)
+
+    for i in range(4):
+        logger.add(str(tmpdir.join("rotate.log")), compression=".tar.gz", format="{message}")
+        logger.info(str(i))
+        logger.remove()
+
+    assert len(tmpdir.listdir()) == 4
+    assert tmpdir.join("rotate.log.tar.gz").check(exists=1)
+    assert tmpdir.join("rotate.2019-01-02_03-04-05_000006.log.tar.gz").check(exists=1)
+    assert tmpdir.join("rotate.2019-01-02_03-04-05_000006.2.log.tar.gz").check(exists=1)
+    assert tmpdir.join("rotate.2019-01-02_03-04-05_000006.3.log.tar.gz").check(exists=1)
+
+
+def test_renaming_compression_dest_exists_with_time(monkeypatch, monkeypatch_date, tmpdir):
+    date = (2019, 1, 2, 3, 4, 5, 6)
+    timestamp = datetime.datetime(*date).timestamp()
+    monkeypatch_date(*date)
+    monkeypatch.setattr(loguru._file_sink, "get_ctime", lambda _: timestamp)
+
+    for i in range(4):
+        logger.add(str(tmpdir.join("rotate.{time}.log")), compression=".tar.gz", format="{message}")
+        logger.info(str(i))
+        logger.remove()
+
+    assert len(tmpdir.listdir()) == 4
+    assert tmpdir.join("rotate.2019-01-02_03-04-05_000006.log.tar.gz").check(exists=1)
+    assert tmpdir.join(
+        "rotate.2019-01-02_03-04-05_000006.2019-01-02_03-04-05_000006.log.tar.gz"
+    ).check(exists=1)
+    assert tmpdir.join(
+        "rotate.2019-01-02_03-04-05_000006.2019-01-02_03-04-05_000006.2.log.tar.gz"
+    ).check(exists=1)
+    assert tmpdir.join(
+        "rotate.2019-01-02_03-04-05_000006.2019-01-02_03-04-05_000006.3.log.tar.gz"
+    ).check(exists=1)
+
+
 @pytest.mark.parametrize("compression", [0, True, os, object(), {"zip"}])
 def test_invalid_compression(compression):
     with pytest.raises(TypeError):

tests/test_filesink_rotation.py

@@ -490,6 +490,54 @@ def creation_time(filepath):
     assert tmpdir.join("test.2018-01-01_00-00-00_000000.log").check(exists=1)
 
 
+def test_renaming_rotation_dest_exists(monkeypatch, monkeypatch_date, tmpdir):
+    date = (2019, 1, 2, 3, 4, 5, 6)
+    timestamp = datetime.datetime(*date).timestamp()
+    monkeypatch_date(*date)
+    monkeypatch.setattr(loguru._file_sink, "get_ctime", lambda _: timestamp)
+
+    def rotate(file, msg):
+        return True
+
+    logger.add(str(tmpdir.join("rotate.log")), rotation=rotate, format="{message}")
+    logger.info("A")
+    logger.info("B")
+    logger.info("C")
+    assert len(tmpdir.listdir()) == 4
+    assert tmpdir.join("rotate.log").read() == "C\n"
+    assert tmpdir.join("rotate.2019-01-02_03-04-05_000006.log").read() == ""
+    assert tmpdir.join("rotate.2019-01-02_03-04-05_000006.2.log").read() == "A\n"
+    assert tmpdir.join("rotate.2019-01-02_03-04-05_000006.3.log").read() == "B\n"
+
+
+def test_renaming_rotation_dest_exists_with_time(monkeypatch, monkeypatch_date, tmpdir):
+    date = (2019, 1, 2, 3, 4, 5, 6)
+    timestamp = datetime.datetime(*date).timestamp()
+    monkeypatch_date(*date)
+    monkeypatch.setattr(loguru._file_sink, "get_ctime", lambda _: timestamp)
+
+    def rotate(file, msg):
+        return True
+
+    logger.add(str(tmpdir.join("rotate.{time}.log")), rotation=rotate, format="{message}")
+    logger.info("A")
+    logger.info("B")
+    logger.info("C")
+    assert len(tmpdir.listdir()) == 4
+    assert tmpdir.join("rotate.2019-01-02_03-04-05_000006.log").read() == "C\n"
+    assert (
+        tmpdir.join("rotate.2019-01-02_03-04-05_000006.2019-01-02_03-04-05_000006.log").read() == ""
+    )
+    assert (
+        tmpdir.join("rotate.2019-01-02_03-04-05_000006.2019-01-02_03-04-05_000006.2.log").read()
+        == "A\n"
+    )
+    assert (
+        tmpdir.join("rotate.2019-01-02_03-04-05_000006.2019-01-02_03-04-05_000006.3.log").read()
+        == "B\n"
+    )
+
+
 @pytest.mark.parametrize(
     "rotation", [object(), os, datetime.date(2017, 11, 11), datetime.datetime.now(), 1j]
 )