Merge pull request #5 from facundobatista/log-to-a-file--3

Provide a log filepath that complies with our requirements (CRAFT-96).

craft_cli/messages.py

@@ -17,13 +17,15 @@
 """Support for all messages, ok or after errors, to screen and log file."""
 
 import enum
+import pathlib
 import shutil
 import sys
-import tempfile
 from dataclasses import dataclass, field
 from datetime import datetime
 from typing import Optional, TextIO, Union
 
+import appdirs
+
 
 @dataclass
 class _MessageInfo:
@@ -39,23 +41,51 @@ class _MessageInfo:
 # the different modes the Emitter can be set
 EmitterMode = enum.Enum("EmitterMode", "QUIET NORMAL VERBOSE TRACE")
 
+# the limit to how many log files to have
+_MAX_LOG_FILES = 5
+
 
-def get_terminal_width() -> int:
+def _get_terminal_width() -> int:
     """Return the number of columns of the terminal."""
     return shutil.get_terminal_size().columns
 
 
-def get_log_filepath(appname):
-    """Provide a filepath for logging into."""
-    # XXX Facundo 2021-09-03: this will change heavily in next couple of branches
-    _, filepath = tempfile.mkstemp(prefix=f"{appname}-")
-    return filepath
+def _get_log_filepath(appname: str) -> pathlib.Path:
+    """Provide a unique filepath for logging.
+
+    The app name is used for both the directory where the logs are located and each log name.
+
+    Rules:
+    - use an appdirs provided directory
+    - base filename is <appname>.<timestamp with microseconds>.log
+    - it rotates until it gets to reaches :data:`._MAX_LOG_FILES`
+    - after limit is achieved, remove the exceeding files
+    - ignore other non-log files in the directory
+
+    Existing files are not renamed (no need, as each name is unique) nor gzipped (they may
+    be currently in use by another process).
+    """
+    basedir = pathlib.Path(appdirs.user_log_dir()) / appname
+    filename = f"{appname}-{datetime.now():%Y%m%d-%H%M%S.%f}.log"
+
+    # ensure the basedir is there
+    basedir.mkdir(exist_ok=True)
+
+    # check if we have too many logs in the dir, and remove the exceeding ones (note
+    # that the defined limit includes the about-to-be-created file, that's why the "-1")
+    present_files = list(basedir.glob(f"{appname}-*.log"))
+    limit = _MAX_LOG_FILES - 1
+    if len(present_files) > limit:
+        for fpath in sorted(present_files)[:-limit]:
+            fpath.unlink()
+
+    return basedir / filename
 
 
 class _Printer:
     """Handle writing the different messages to the different outputs (out, err and log)."""
 
-    def __init__(self, log_filepath: str) -> None:
+    def __init__(self, log_filepath: pathlib.Path) -> None:
         # holder of the previous message
         self.prv_msg: Optional[_MessageInfo] = None
 
@@ -80,7 +110,7 @@ def _write_line(self, message: _MessageInfo) -> None:
 
         # fill with spaces until the very end, on one hand to clear a possible previous message,
         # but also to always have the cursor at the very end
-        width = get_terminal_width()
+        width = _get_terminal_width()
         usable = width - 1  # the 1 is the cursor itself
         cleaner = " " * (usable - len(text) % width)
 
@@ -176,7 +206,7 @@ def init(self, mode: EmitterMode, appname: str, greeting: str):
 
         # create a log file, bootstrap the printer, and before anything else send the greeting
         # to the file
-        self.log_filepath = get_log_filepath(appname)
+        self.log_filepath = _get_log_filepath(appname)
         self.printer = _Printer(self.log_filepath)
         self.printer.show(None, greeting)
 

requirements-dev.txt

@@ -1,33 +1,34 @@
 alabaster==0.7.12
 appdirs==1.4.4
-astroid==2.6.6
+appdirs-stubs==0.1.0
+astroid==2.7.3
 attrs==21.2.0
 autoflake==1.4
 Babel==2.9.1
 backports.entry-points-selectable==1.1.0
-black==21.7b0
-bleach==4.0.0
+black==21.8b0
+bleach==4.1.0
 certifi==2021.5.30
 cffi==1.14.6
 charset-normalizer==2.0.4
 click==8.0.1
 codespell==2.1.0
 colorama==0.4.4
 coverage==5.5
-cryptography==3.4.7
+cryptography==3.4.8
 distlib==0.3.2
 docutils==0.16
 filelock==3.0.12
 flake8==3.9.2
 idna==3.2
 imagesize==1.2.0
-importlib-metadata==4.6.3
+importlib-metadata==4.8.1
 iniconfig==1.1.1
 isort==5.9.3
 jeepney==0.7.1
 Jinja2==3.0.1
 jsonpointer==2.1
-keyring==23.0.1
+keyring==23.1.0
 lazy-object-proxy==1.6.0
 MarkupSafe==2.0.1
 mccabe==0.6.1
@@ -36,26 +37,26 @@ mypy-extensions==0.4.3
 packaging==21.0
 pathspec==0.9.0
 pkginfo==1.7.1
-platformdirs==2.2.0
-pluggy==0.13.1
+platformdirs==2.3.0
+pluggy==1.0.0
 py==1.10.0
 pycodestyle==2.7.0
 pycparser==2.20
 pydantic==1.8.2
 pydocstyle==6.1.1
 pyflakes==2.3.1
-Pygments==2.9.0
-pylint==2.9.6
+Pygments==2.10.0
+pylint==2.10.2
 pylint-fixme-info==1.0.2
 pylint-pytest==1.1.2
 pyparsing==2.4.7
-pytest==6.2.4
+pytest==6.2.5
 pytest-mock==3.6.1
 pytest-subprocess==1.1.2
 pytz==2021.1
 PyYAML==5.4.1
 readme-renderer==29.0
-regex==2021.8.3
+regex==2021.8.28
 requests==2.26.0
 requests-toolbelt==0.9.1
 rfc3986==1.5.0
@@ -75,15 +76,15 @@ sphinxcontrib-qthelp==1.0.3
 sphinxcontrib-serializinghtml==1.1.5
 toml==0.10.2
 tomli==1.2.1
-tox==3.24.1
-tqdm==4.62.0
+tox==3.24.3
+tqdm==4.62.2
 twine==3.4.2
-types-PyYAML==5.4.6
+types-PyYAML==5.4.10
 types-requests==2.25.6
 types-setuptools==57.0.2
-typing-extensions==3.10.0.0
+typing-extensions==3.10.0.2
 urllib3==1.26.6
-virtualenv==20.7.1
+virtualenv==20.7.2
 webencodings==0.5.1
 wrapt==1.12.1
 zipp==3.5.0

requirements.txt

@@ -1,3 +1,4 @@
+appdirs==1.4.4
 pydantic==1.8.2
 PyYAML==5.4.1
-typing-extensions==3.10.0.0
+typing-extensions==3.10.0.2

setup.cfg

@@ -28,6 +28,7 @@ include_package_data = True
 packages = find:
 zip_safe = False
 install_requires =
+    appdirs
     pydantic
     pyyaml
 
@@ -44,9 +45,10 @@ release =
     twine
     wheel
 test =
-    coverage
+    appdirs-stubs
     black
     codespell
+    coverage
     flake8
     isort
     mypy
@@ -58,9 +60,9 @@ test =
     pytest-mock
     pytest-subprocess
     tox
+    types-pyyaml
     types-requests
     types-setuptools
-    types-pyyaml
 dev =
     autoflake
     %(doc)s

tests/unit/test_messages_emitter.py

@@ -45,7 +45,7 @@ def get_initiated_emitter(tmp_path, monkeypatch):
     It's used almost in all tests (except those that test the init call).
     """
     fake_logpath = str(tmp_path / "fakelog.log")
-    monkeypatch.setattr(messages, "get_log_filepath", lambda appname: fake_logpath)
+    monkeypatch.setattr(messages, "_get_log_filepath", lambda appname: fake_logpath)
     with patch("craft_cli.messages._Printer", autospec=True) as mock_printer:
 
         def func(mode, greeting="default greeting"):
@@ -72,7 +72,7 @@ def test_init_quietish(mode, tmp_path, monkeypatch):
     """Init the class in some quiet-ish mode."""
     # avoid using a real log file
     fake_logpath = str(tmp_path / "fakelog.log")
-    monkeypatch.setattr(messages, "get_log_filepath", lambda appname: fake_logpath)
+    monkeypatch.setattr(messages, "_get_log_filepath", lambda appname: fake_logpath)
 
     greeting = "greeting"
     emitter = Emitter()
@@ -97,7 +97,7 @@ def test_init_verboseish(mode, tmp_path, monkeypatch):
     """Init the class in some verbose-ish mode."""
     # avoid using a real log file
     fake_logpath = str(tmp_path / "fakelog.log")
-    monkeypatch.setattr(messages, "get_log_filepath", lambda appname: fake_logpath)
+    monkeypatch.setattr(messages, "_get_log_filepath", lambda appname: fake_logpath)
 
     greeting = "greeting"
     emitter = Emitter()

tests/unit/test_messages_helpers.py

@@ -0,0 +1,129 @@
+#
+# Copyright 2021 Canonical Ltd.
+#
+# This program is free software; you can redistribute it and/or
+# modify it under the terms of the GNU Lesser General Public
+# License version 3 as published by the Free Software Foundation.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+# Lesser General Public License for more details.
+#
+# You should have received a copy of the GNU Lesser General Public License
+# along with this program; if not, write to the Free Software Foundation,
+# Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301, USA.
+
+"""Tests that check the different helpers in the messages module."""
+
+import datetime
+import re
+
+import appdirs
+import pytest
+
+from craft_cli import messages
+from craft_cli.messages import _get_log_filepath
+
+# -- tests for the log filepath provider
+
+
+@pytest.fixture
+def test_log_dir(tmp_path, monkeypatch):
+    """Provide a test log filepath, also fixing appdirs to use a temp dir."""
+    dirpath = tmp_path / "testlogdir"
+    dirpath.mkdir()
+    monkeypatch.setattr(appdirs, "user_log_dir", lambda: dirpath)
+    return dirpath
+
+
+def test_getlogpath_firstcall(test_log_dir):
+    """The very first call."""
+    before = datetime.datetime.now()
+    fpath = _get_log_filepath("testapp")
+    after = datetime.datetime.now()
+
+    # check the file is inside the proper dir and that it exists
+    assert fpath.parent == test_log_dir / "testapp"
+    assert fpath.parent.exists
+
+    # check the file name format
+    match = re.match(r"testapp-(\d+-\d+\.\d+).log", fpath.name)
+    assert match
+    timestamp = datetime.datetime.strptime(match.groups()[0], "%Y%m%d-%H%M%S.%f")
+    assert before < timestamp < after
+
+
+def test_getlogpath_directory_empty(test_log_dir):
+    """Works with the directory already created."""
+    parent = test_log_dir / "testapp"
+    parent.mkdir()
+    fpath = _get_log_filepath("testapp")
+    assert fpath.parent == parent
+
+
+def test_getlogpath_one_file_already_present(test_log_dir):
+    """There's already one file in the destination dir."""
+    previous_fpath = _get_log_filepath("testapp")
+    previous_fpath.touch()
+    new_fpath = _get_log_filepath("testapp")
+    new_fpath.touch()
+    present_logs = sorted((test_log_dir / "testapp").iterdir())
+    assert present_logs == [previous_fpath, new_fpath]
+
+
+def test_getlogpath_several_files_already_present(test_log_dir, monkeypatch):
+    """There are several files in the destination dir."""
+    monkeypatch.setattr(messages, "_MAX_LOG_FILES", 100)
+    previous_fpath = _get_log_filepath("testapp")
+    previous_fpath.touch()
+    new_fpath = _get_log_filepath("testapp")
+    new_fpath.touch()
+    present_logs = sorted((test_log_dir / "testapp").iterdir())
+    assert present_logs == [previous_fpath, new_fpath]
+
+
+def test_getlogpath_hit_rotation_limit(test_log_dir, monkeypatch):
+    """The rotation limit is hit."""
+    monkeypatch.setattr(messages, "_MAX_LOG_FILES", 3)
+    previous_fpaths = [_get_log_filepath("testapp") for _ in range(2)]
+    for fpath in previous_fpaths:
+        fpath.touch()
+    new_fpath = _get_log_filepath("testapp")
+    new_fpath.touch()
+    present_logs = sorted((test_log_dir / "testapp").iterdir())
+    assert present_logs == previous_fpaths + [new_fpath]
+
+
+def test_getlogpath_exceeds_rotation_limit(test_log_dir, monkeypatch):
+    """The rotation limit is exceeded."""
+    monkeypatch.setattr(messages, "_MAX_LOG_FILES", 3)
+    previous_fpaths = [_get_log_filepath("testapp") for _ in range(3)]
+    for fpath in previous_fpaths:
+        fpath.touch()
+    new_fpath = _get_log_filepath("testapp")
+    new_fpath.touch()
+    present_logs = sorted((test_log_dir / "testapp").iterdir())
+    assert present_logs == previous_fpaths[1:] + [new_fpath]
+
+
+def test_getlogpath_ignore_other_files(test_log_dir, monkeypatch):
+    """Only affect logs of the given app."""
+    monkeypatch.setattr(messages, "_MAX_LOG_FILES", 3)
+
+    # old files to trigger some removal
+    previous_fpaths = [_get_log_filepath("testapp") for _ in range(3)]
+    for fpath in previous_fpaths:
+        fpath.touch()
+
+    # other stuff that should not be removed
+    parent = test_log_dir / "testapp"
+    f_aaa = parent / "aaa"
+    f_aaa.touch()
+    f_zzz = parent / "zzz"
+    f_zzz.touch()
+
+    new_fpath = _get_log_filepath("testapp")
+    new_fpath.touch()
+    present_logs = sorted((test_log_dir / "testapp").iterdir())
+    assert present_logs == [f_aaa] + previous_fpaths[1:] + [new_fpath, f_zzz]