Simple logging system

.github/workflows/check.yml

@@ -8,6 +8,8 @@ jobs:
   build:
 
     runs-on: ${{ matrix.os }}
+    env:
+      AFMFORMATS_LOG_PATH: ${{ github.workspace }}/afmformats.log
     strategy:
       matrix:
         python-version: ['3.11', '3.12', '3.13']
@@ -34,5 +36,11 @@ jobs:
     - name: Test with pytest
       run: |
         coverage run --source=afmformats -m pytest tests
+    - name: Upload afmformats log artifact
+      if: always()
+      uses: actions/upload-artifact@v4
+      with:
+        name: afmformats-log-${{ matrix.os }}-py${{ matrix.python-version }}
+        path: afmformats.log
     - name: Upload coverage to Codecov
       uses: codecov/codecov-action@v3

afmformats/__init__.py

@@ -4,6 +4,7 @@
 from .afm_qmap import AFMQMap
 from .formats import find_data, load_data
 from .formats import supported_extensions
+from .logging_setup import DEFAULT_LOG_PATH, configure_logging
 from .mod_creep_compliance import AFMCreepCompliance
 from .mod_force_distance import AFMForceDistance
 from .mod_stress_relaxation import AFMStressRelaxation

afmformats/formats/__init__.py

@@ -1,5 +1,5 @@
+import logging
 import pathlib
-
 from .. import errors
 from .. import meta
 from .fmt_hdf5 import recipe_hdf5
@@ -18,11 +18,12 @@
 from ..mod_creep_compliance import AFMCreepCompliance
 from ..mod_stress_relaxation import AFMStressRelaxation
 
-
 __all__ = ["AFMFormatRecipe", "find_data", "get_recipe", "load_data",
            "default_data_classes_by_modality", "formats_available",
            "formats_by_suffix", "formats_by_modality", "supported_extensions"]
 
+logger = logging.getLogger(__name__)
+
 
 class AFMFormatRecipe(object):
     def __init__(self, recipe):
@@ -167,7 +168,7 @@ def find_data(path, modality=None):
             get_recipe(path=path, modality=modality)
         except errors.FileFormatNotSupportedError:
             # not a valid file format
-            pass
+            logger.debug("Skipping unsupported file '%s'", path)
         else:
             # valid file format
             file_list.append(path)
@@ -197,10 +198,22 @@ def get_recipe(path, modality=None):
 
     recipes = formats_by_suffix[path.suffix]
     for rec in recipes:
-        if ((modality is None or modality in rec.modalities)
-                and rec.detect(path)):
+        try:
+            supported = rec.detect(path)
+        except BaseException:
+            logger.debug(
+                "Detect failed for '%s' using recipe '%s'. Traceback follows.",
+                path, rec, exc_info=True)
+            supported = False
+        if ((modality is None or modality in rec.modalities) and supported):
             break
+        logger.debug(
+            "Recipe '%s' did not match '%s' for modality '%s'",
+            rec, path, modality)
     else:
+        logger.debug(
+            "No recipe matched '%s' for modality '%s'. Tried: %s",
+            path, modality, [r.descr for r in recipes])
         raise errors.FileFormatNotSupportedError(
             f"Could not determine file format recipe for '{path}'!")
 
@@ -255,19 +268,35 @@ def load_data(path, meta_override=None, modality=None,
             afm_data_class = data_classes_by_modality[modality]
         else:
             afm_data_class = default_data_classes_by_modality[modality]
-        for dd in loader(path,
-                         callback=callback,
-                         meta_override=meta_override):
-            dd["metadata"]["format"] = "{} ({})".format(cur_recipe["maker"],
-                                                        cur_recipe["descr"])
-            if fix_modality and dd["metadata"]["imaging mode"] != modality:
-                # The user explicitly requested this modality.
-                continue
-            ddi = afm_data_class(data=dd["data"],
-                                 metadata=dd["metadata"],
-                                 diskcache=diskcache)
-            afmdata.append(ddi)
+        try:
+            for dd in loader(path,
+                             callback=callback,
+                             meta_override=meta_override):
+                dd["metadata"]["format"] = "{} ({})".format(
+                    cur_recipe["maker"], cur_recipe["descr"])
+                if fix_modality and dd["metadata"]["imaging mode"] != modality:
+                    # The user explicitly requested this modality.
+                    logger.debug(
+                        "Skipping dataset with modality '%s' (expected '%s') "
+                        "from '%s'",
+                        dd["metadata"]["imaging mode"], modality, path)
+                    continue
+                ddi = afm_data_class(data=dd["data"],
+                                     metadata=dd["metadata"],
+                                     diskcache=diskcache)
+                afmdata.append(ddi)
+        except BaseException:
+            logger.exception(
+                "Loader failed for '%s' using recipe '%s'. Traceback follows.",
+                path, cur_recipe)
+            raise
+        logger.debug(
+            "Loaded %d dataset(s) from '%s' using '%s'",
+            len(afmdata), path, cur_recipe.descr)
     else:
+        logger.debug(
+            "Loader failed for '%s' as the extension '%s' is not recognised.",
+            path, path.suffix)
         raise ValueError("Unsupported file extension: '{}'!".format(path))
     return afmdata
 

afmformats/logging_setup.py

@@ -0,0 +1,64 @@
+"""Package-wide logging configuration."""
+
+import logging
+import os
+import pathlib
+import sys
+import tempfile
+from typing import Optional
+
+__all__ = [
+    "DEFAULT_LOG_PATH",
+    "configure_logging",
+]
+
+DEFAULT_LOG_PATH = os.path.join(tempfile.gettempdir(), "afmformats.log")
+
+
+def configure_logging(log_path: Optional[str] = DEFAULT_LOG_PATH,
+                      console_logging_level: bool | int = 0) -> str:
+    """Ensure afmformats writes debug logs to a file.
+
+    Returns the log path used so CI pipelines can publish it as an artifact.
+    """
+    path = log_path
+    path = str(pathlib.Path(path))
+    logger = logging.getLogger("afmformats")
+    logger.setLevel(logging.DEBUG)
+    logger.propagate = False
+
+    handler_exists = any(
+        isinstance(h, logging.FileHandler)
+        and getattr(h, "baseFilename", None) == path
+        for h in logger.handlers
+    )
+    if not handler_exists:
+        pathlib.Path(path).parent.mkdir(parents=True, exist_ok=True)
+        fh = logging.FileHandler(path, encoding="utf-8")
+        fh.setLevel(logging.DEBUG)
+        formatter = logging.Formatter(
+            "%(asctime)s %(levelname)s %(name)s: %(message)s"
+        )
+        fh.setFormatter(formatter)
+        logger.addHandler(fh)
+        logger.debug("afmformats logging initialized at %s", path)
+    if console_logging_level:
+        configure_console_logging(console_logging_level)
+    return path
+
+
+def configure_console_logging(level: int = logging.DEBUG) -> None:
+    """Mirror afmformats log output to the terminal."""
+    logger = logging.getLogger("afmformats")
+    handler_exists = any(
+        isinstance(h, logging.StreamHandler)
+        and not isinstance(h, logging.FileHandler)
+        and getattr(h, "stream", None) is sys.stderr
+        for h in logger.handlers
+    )
+    if not handler_exists:
+        handler = logging.StreamHandler()
+        handler.setLevel(level)
+        handler.setFormatter(logging.Formatter(
+            "%(levelname)s:%(name)s:%(message)s"))
+        logger.addHandler(handler)

docs/sec_advanced_usage.rst

@@ -28,4 +28,51 @@ functionalities:
     # You can also extract a subgroup that matches a certin path
     In [6]: subgroup = group.subgroup_with_path("data/force-map2x2-example.jpk-force-map")
 
-    In [7]: print(subgroup)
+    In [7]: print(subgroup)
+
+
+Logging (for developers)
+========================
+``afmformats`` has a simple logging system. When loading data in a script
+or in the console, debug-level logs can be written to `afmformats.log` in
+your machine's temp folder if you call
+:func:`afmformats.configure_logging()<afmformats.logging_setup.configure_logging>`.
+When running tests via ``pytest``, the logs will be written to a temp directory
+as defined in :func:`tests.conftest.pytest_configure`.
+
+.. code-block:: python
+
+    import pathlib
+    import afmformats
+
+    data_path = pathlib.Path("tests/data")
+
+    # write logs to tmp/afmformats.log
+    afmformats.configure_logging()
+
+    afmformats.load_data(data_path / "fmt-hdf5-fd_version_0.13.3.h5")
+
+
+If you would like the logs also to be output to the terminal when running
+scripts you can set the logging level:
+
+.. code-block:: python
+
+    import pathlib
+    import afmformats
+    import logging
+
+    data_path = pathlib.Path("tests/data")
+
+    # write logs to tmp/afmformats.log and to terminal
+    afmformats.configure_logging(console_logging_level=logging.DEBUG)
+
+    afmformats.load_data(data_path / "fmt-hdf5-fd_version_0.13.3.h5")
+
+
+Output of the above script:
+
+.. code-block::
+
+    DEBUG:afmformats.formats:Loaded 1 dataset(s) from '...\afmformats\tests\data\fmt-hdf5-fd_version_0.13.3.h5' using 'HDF5-based'
+    Process finished with exit code 0

tests/conftest.py

@@ -1,9 +1,15 @@
+import os
 import shutil
 import tempfile
 import time
+from pathlib import Path
+
+import afmformats
+import pytest
 
 TMPDIR = tempfile.mkdtemp(prefix=time.strftime(
     "afmformats_test_%H.%M_"))
+LOG_PATH_KEY = pytest.StashKey[Path]()
 
 
 def pytest_configure(config):
@@ -13,10 +19,23 @@ def pytest_configure(config):
     file after command line options have been parsed.
     """
     tempfile.tempdir = TMPDIR
+    # deal with logging directory
+    ci_log_path = os.getenv("AFMFORMATS_LOG_PATH")
+    if ci_log_path:
+        log_path = ci_log_path
+    else:
+        log_path = os.path.join(TMPDIR, "afmformats.log")
+    configured_log_path = afmformats.configure_logging(log_path)
+    config.stash[LOG_PATH_KEY] = Path(configured_log_path)
 
 
 def pytest_unconfigure(config):
     """
     called before test process is exited.
     """
     shutil.rmtree(TMPDIR, ignore_errors=True)
+
+
+@pytest.fixture
+def afmformats_log_path(pytestconfig):
+    return pytestconfig.stash[LOG_PATH_KEY]

tests/test_logger.py

@@ -0,0 +1,41 @@
+import pathlib
+import pytest
+
+import afmformats
+
+data_path = pathlib.Path(__file__).resolve().parent / "data"
+
+
+def test_logger_load_data_success(afmformats_log_path):
+    path = data_path / "fmt-tab-fd_version_0.13.3.tab"
+    log_path = pathlib.Path(afmformats_log_path)
+
+    afmdata = afmformats.load_data(path)
+    assert len(afmdata) == 1
+
+    with log_path.open(encoding="utf-8") as fd:
+        new_output = fd.read()
+
+    assert "afmformats logging initialized" in new_output
+    assert "Loaded 1 dataset(s)" in new_output
+    assert str(path) in new_output
+    assert "tab-separated values" in new_output
+
+
+@pytest.mark.parametrize(
+    "file_name",
+    ["fmt-tab-fd_version_0.13.3.slab"])
+def test_logger_load_data_failure_bad_extension(
+        afmformats_log_path, file_name):
+    path = data_path / file_name
+    log_path = pathlib.Path(afmformats_log_path)
+
+    with pytest.raises(ValueError,
+                       match=r"Unsupported file extension"):
+        _ = afmformats.load_data(path)
+
+    with log_path.open(encoding="utf-8") as fd:
+        new_output = fd.read()
+
+    assert "afmformats logging initialized" in new_output
+    assert "Loader failed" in new_output