Merge branch 'rh/logging_config_leak' into 'master'

Rh/logging config leak

See merge request minknow/pod5-file-format!311

.gitlab-ci.yml

@@ -134,6 +134,32 @@ tag_version_check:
         exit 1;
       fi
 
+api_lib_version_check:
+  stage: .pre
+  needs:
+    - "prepare_version"
+  image: ${CI_REGISTRY}/minknow/images/build-x86_64-gcc9:latest
+  script:
+    - cat _version.py
+    - NO_DEV_VERSION=$(grep "__version__" _version.py | awk '{print $5}' | tr -d "'" | cut -d'+' -f1 | sed 's/\([0-9]\+\.[0-9]\+\.[0-9]\+\).*$/\1/')
+    - echo $NO_DEV_VERSION
+    - cat python/pod5/pyproject.toml
+    - echo "If this jobs fails then we have forgotten to match the api and lib version in the api python/pod5/pyproject.toml"
+    - grep "lib_pod5\s*==\s*$NO_DEV_VERSION" python/pod5/pyproject.toml
+
+docs_version_check:
+  stage: .pre
+  needs:
+    - "prepare_version"
+  image: ${CI_REGISTRY}/minknow/images/build-x86_64-gcc9:latest
+  script:
+    - cat _version.py
+    - NO_DEV_VERSION=$(grep "__version__" _version.py | awk '{print $5}' | tr -d "'" | cut -d'+' -f1 | sed 's/\([0-9]\+\.[0-9]\+\.[0-9]\+\).*$/\1/')
+    - echo $NO_DEV_VERSION
+    - cat docs/requirements.txt
+    - echo "If this jobs fails then we have forgotten to update the pod5 version in the docs/requirements.txt"
+    - grep "pod5\s*==\s*$NO_DEV_VERSION" docs/requirements.txt
+
 pre-commit checks:
     image: ${CI_REGISTRY}/traque/ont-docker-base/ont-base-python:3.10
     stage: .pre

CHANGELOG.md

@@ -7,7 +7,14 @@ All notable changes, updates, and fixes to pod5 will be documented here
 The format is based on [Keep a Changelog](http://keepachangelog.com/en/1.0.0/)
 and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
 
-## Unreleased
+
+## [0.3.1] 2023-11-10
+
+### Fixed
+
+- Logging no longer calls `basicConfig` which may unintentionally edit users logging configuration
+
+## [0.3.0] 2023-11-07
 
 ### Changed
 

docs/docs/install.rst

@@ -28,7 +28,7 @@ Developing with Conan
 
 For this development process you will need `conan <https://conan.io/>`_ installed.
 You can install ``conan<2`` using ``pip`` or your platforms' package manager (e.g. ``brew``)
-You will also need the python ``setuptools_scm`` package to manage pod5 versioning:
+You will also need the python ``setuptools_scm==7.1.0`` package to manage pod5 versioning:
 
 .. code-block:: console
 
@@ -47,7 +47,7 @@ You will also need the python ``setuptools_scm`` package to manage pod5 versioni
 .. code-block:: console
 
    # Creates _version.py and cmake/POD5Version.cmake which are ignored by git
-   $ pip install setuptools_scm
+   $ pip install setuptools_scm==7.1.0
    $ python -m setuptools_scm
    $ python -m pod5_make_version
 

docs/requirements.txt

@@ -2,4 +2,4 @@ sphinx-rtd-theme
 sphinx==v5.3.0
 myst-parser
 # Paths are relative to project root for ReadTheDocs and docs/Makefile
-pod5==0.3.0
+pod5==0.3.1

python/pod5/pyproject.toml

@@ -22,7 +22,7 @@ classifiers=[
 ]
 
 dependencies = [
-    "lib_pod5 == 0.2.9",
+    "lib_pod5 == 0.3.1",
     "iso8601",
     'importlib-metadata; python_version<"3.8"',
     "more_itertools",

python/pod5/src/pod5/tools/pod5_filter.py

@@ -100,7 +100,7 @@ def filter_reads(dest: Path, sources: pl.DataFrame, duplicate_ok: bool) -> None:
 
             while repacker.currently_open_file_reader_count >= active_limit:
                 pbar.update(repacker.reads_completed - pbar.n)
-                sleep(0.05)
+                sleep(0.2)
 
             with p5.Reader(src) as reader:
                 repacker.add_selected_reads_to_output(output, reader, read_ids)
@@ -109,7 +109,7 @@ def filter_reads(dest: Path, sources: pl.DataFrame, duplicate_ok: bool) -> None:
         repacker.set_output_finished(output)
         while repacker.currently_open_file_reader_count > 0:
             pbar.update(repacker.reads_completed - pbar.n)
-            sleep(0.05)
+            sleep(0.1)
 
         repacker.finish()
         pbar.close()

python/pod5/src/pod5/tools/pod5_merge.py

@@ -52,6 +52,7 @@ def merge_pod5(
     )
 
     print(f"Merging reads from {len(_inputs)} files")
+    logger.debug(f"Merging reads from {len(_inputs)} files into {output.absolute()}")
 
     # Open the output file writer
     with p5.Writer(output.absolute()) as writer:
@@ -62,31 +63,36 @@ def merge_pod5(
         pbar = tqdm(
             total=len(_inputs),
             desc="Merging",
-            unit="Files",
+            unit="File",
             leave=True,
             position=0,
             **PBAR_DEFAULTS,
         )
 
         active_limit = max(readers, 1)
+        logger.debug(f"{active_limit=}")
+
         opened_readers = 0
         active = 0
-
         while _inputs or active > 0:
             pbar.update(opened_readers - active - pbar.n)
 
             active = repacker.currently_open_file_reader_count
-            if active < active_limit:
-                if _inputs:
-                    with p5.Reader(_inputs.pop()) as reader:
-                        opened_readers += 1
-                        repacker.add_all_reads_to_output(repacker_output, reader)
-                        continue
-                else:
-                    repacker.set_output_finished(repacker_output)
+            if _inputs and (active < active_limit):
+                next_input = _inputs.pop()
+                logger.debug(f"submitting: {next_input=}")
+                with p5.Reader(next_input) as reader:
+                    opened_readers += 1
+                    repacker.add_all_reads_to_output(repacker_output, reader)
                     continue
 
-            sleep(0.05)
+            if not _inputs:
+                logger.debug("no inputs remaining - finishing")
+                repacker.set_output_finished(repacker_output)
+                break
+
+            sleep(0.2)
+            logger.debug(f"{len(_inputs)=}, {active=}, {active>0=}")
 
         repacker.finish()
         del repacker

python/pod5/src/pod5/tools/pod5_subset.py

@@ -525,7 +525,6 @@ def subset_reads(
         unit="Reads",
         leave=False,
         position=process,
-        delay=2,
         **PBAR_DEFAULTS,
     )
 
@@ -538,7 +537,7 @@ def subset_reads(
         for source, reads in sources.group_by(PL_SRC_FNAME):
             while repacker.currently_open_file_reader_count >= active_limit:
                 pbar.update(repacker.reads_completed - pbar.n)
-                sleep(0.05)
+                sleep(0.2)
 
             read_ids = reads.get_column(PL_READ_ID).unique().to_list()
             logger.debug(f"Subsetting: {source} - n_reads: {len(read_ids)}")

python/pod5/src/pod5/tools/utils.py

@@ -24,44 +24,48 @@ def init_logging():
     if not is_pod5_debug():
         logger = logging.getLogger("pod5")
         logger.addHandler(logging.NullHandler())
+        return logger
+
+    datetime_now = datetime.datetime.now().strftime("%Y-%m-%d--%H-%M-%S")
+    if mp.current_process().name == "MainProcess":
+        pid = "main"
     else:
-        datetime_now = datetime.datetime.now().strftime("%Y-%m-%d--%H-%M-%S")
-        if mp.current_process().name == "MainProcess":
-            pid = "main"
-        else:
-            pid = f"p-{os.getpid()}"
-        logging.basicConfig(
-            level=logging.DEBUG,
-            filename=f"{datetime_now}-{pid}-pod5.log",
-            format="%(asctime)s %(levelname)s %(message)s",
-        )
-        logger = logging.getLogger("pod5")
+        pid = f"p-{os.getpid()}"
+
+    logger = logging.getLogger("pod5")
+    logger.setLevel(logging.DEBUG)
+    file_handler = logging.FileHandler(filename=f"{datetime_now}-{pid}-pod5.log")
+    file_handler.setFormatter(
+        logging.Formatter("%(asctime)s %(levelname)s %(message)s")
+    )
+    file_handler.setLevel(logging.DEBUG)
+    logger.addHandler(file_handler)
     return logger
 
 
 def logged(log_return: bool = False, log_args: bool = False, log_time: bool = False):
     """Logging parameterised decorator"""
-    log_fn = logging.debug
 
     def decorator(func):
         @functools.wraps(func)
         def wrapper(*args, **kwargs):
+            logger = logging.getLogger("pod5")
             uid = f"{str(uuid.uuid4())[:2]}:'{func.__name__}'"
             if log_args:
-                log_fn("{0}:{1}, {2}".format(uid, args, kwargs))
+                logger.debug("{0}:{1}, {2}".format(uid, args, kwargs))
             else:
-                log_fn("{0}".format(uid))
+                logger.debug("{0}".format(uid))
             try:
                 started = perf_counter()
                 ret = func(*args, **kwargs)
             except Exception as exc:
-                log_fn("{0}:Exception:{1}".format(uid, exc))
+                logger.debug("{0}:Exception:{1}".format(uid, exc))
                 raise exc
             if log_time:
                 duration_s = perf_counter() - started
-                log_fn("{0}:Done:{1:.3f}s".format(uid, duration_s))
+                logger.debug("{0}:Done:{1:.3f}s".format(uid, duration_s))
             if log_return:
-                log_fn("{0}:Returned:{1}".format(uid, ret))
+                logger.debug("{0}:Returned:{1}".format(uid, ret))
             return ret
 
         return wrapper