From 6a821c1dfb09872f6113ac711a046c857787a15b Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Edwin=20Carre=C3=B1o?= <ecarrenolozano@gmail.com>
Date: Mon, 9 Mar 2026 11:37:47 +0100
Subject: [PATCH] fix: implement logging messages using the built-in logging
 library.

---
 cache_manager/__init__.py   |   2 +-
 cache_manager/_cache.py     | 125 +++++++++++++++++++++++-------------
 cache_manager/_freshness.py |  21 +++---
 cache_manager/_item.py      |   5 ++
 cache_manager/_lock.py      |   5 ++
 cache_manager/_metadata.py  |   4 ++
 cache_manager/_open.py      |  28 ++++----
 cache_manager/_session.py   |   8 ++-
 cache_manager/_status.py    |   8 ++-
 cache_manager/utils.py      |   4 ++
 10 files changed, 138 insertions(+), 72 deletions(-)

diff --git a/cache_manager/__init__.py b/cache_manager/__init__.py
index 6929ead..b7c6f72 100644
--- a/cache_manager/__init__.py
+++ b/cache_manager/__init__.py
@@ -4,6 +4,6 @@
 
 from ._metadata import __version__, __author__, __license__
 from ._metadata import metadata as _metadata
-from ._session import log, _log, session
+from ._session import session
 from ._cache import Cache
 from . import _data as data
diff --git a/cache_manager/_cache.py b/cache_manager/_cache.py
index 831cdb6..d7faeba 100644
--- a/cache_manager/_cache.py
+++ b/cache_manager/_cache.py
@@ -15,6 +15,7 @@
 import datetime
 import functools as ft
 import collections
+import logging
 from collections.abc import Mapping
 
 from pypath_common import _misc
@@ -22,7 +23,6 @@
 
 from cache_manager._item import CacheItem
 from cache_manager._status import Status
-from cache_manager._session import _log
 import cache_manager.utils as _utils
 from . import _data
 from ._lock import Lock
@@ -40,6 +40,9 @@
     'tuple': 'TEXT',
 }
 
+#--- Module logger 
+logger = logging.getLogger(__name__)
+logger.addHandler(logging.NullHandler())
 
 class Cache:
     """
@@ -80,7 +83,8 @@ def __del__(self):
 
         if hasattr(self, 'con'):
 
-            _log(f'Closing SQLite database path: {self.path}')
+
+            logger.debug(f'Closing SQLite database path: {self.path}')
             self.con.close()
 
 
@@ -111,7 +115,8 @@ def autoclean(self):
         deletes anything else in the cache registry.
         """
 
-        _log('Auto cleaning cache.')
+
+        logger.debug('Auto cleaning cache.')
         items = collections.defaultdict(set)
         best = dict()
 
@@ -134,11 +139,13 @@ def autoclean(self):
             for it in v - _misc.to_set(best.get(k, []))
         ]
 
-        _log(f'Deleting {len(to_remove)} records.')
+
+        logger.debug(f'Deleting {len(to_remove)} records.')
 
         self._delete_records(to_remove)
         self.clean_disk()
-        _log('Auto clean complete.')
+
+        logger.debug('Auto clean complete.')
 
 
     def best(
@@ -196,11 +203,12 @@ def best(
 
         if items:
 
-            _log(f'Best matching version: {items[-1].version}')
+            logger.debug(f'Best matching version: {items[-1].version}')
 
             return items[-1]
 
-        _log('No version found matching criteria')
+
+        logger.debug('No version found matching criteria')
 
 
     def best_or_new(
@@ -323,7 +331,7 @@ def by_attrs(self, attrs: dict) -> set[int]:
             {1, 2}
         """
 
-        _log(f'Searching by attributes: {attrs}')
+        logger.debug(f'Searching by attributes: {attrs}')
         result = []
 
         op = set.intersection if attrs.pop('__and', True) else set.union
@@ -362,7 +370,7 @@ def by_key(self, key: str, version: int) -> CacheItem:
             CacheItem[foo V:1 UNINITIALIZED]
         """
 
-        _log(f'Looking up key: {key}')
+        logger.debug(f'Looking up key: {key}')
 
         return _misc.first(self.search(key=key, version=version))
 
@@ -373,7 +381,8 @@ def clean_db(self):
         corresponding file on the cache disk directory.
         """
 
-        _log('Cleaning cache database: removing records without file on disk.')
+
+        logger.debug('Cleaning cache database: removing records without file on disk.')
 
         items = {
             item
@@ -381,10 +390,12 @@ def clean_db(self):
             if (item := it['item'])
             and not os.path.exists(it['item'].path)
         }
-        _log(f'Deleting {len(items)} records.')
+
+        logger.debug(f'Deleting {len(items)} records.')
 
         self._delete_records(items)
-        _log('Cleaning cache database complete.')
+
+        logger.debug('Cleaning cache database complete.')
 
 
     def clean_disk(self):
@@ -393,7 +404,8 @@ def clean_disk(self):
         record in the database registry.
         """
 
-        _log('Cleaning disk: removing items without DB record.')
+
+        logger.debug('Cleaning disk: removing items without DB record.')
 
         fnames = {
             os.path.join(self.dir, fname)
@@ -402,14 +414,17 @@ def clean_disk(self):
             and not item.get('status', False)
         }
 
-        _log(f'Deleting {len(fnames)} files.')
+
+        logger.debug(f'Deleting {len(fnames)} files.')
 
         for file in fnames:
 
-            _log(f'Deleting from disk: `{file}`.')
+
+            logger.debug(f'Deleting from disk: `{file}`.')
             os.remove(file)
 
-        _log('Cleaning disk complete.')
+
+        logger.debug('Cleaning disk complete.')
 
 
     def contents(self) -> dict[str, dict[str, int | str | CacheItem]]:
@@ -509,16 +524,19 @@ def create(
 
         self._ensure_sqlite()
 
-        _log(f'CREATE {uri}')
+
+        logger.debug(f'CREATE {uri}')
         args = locals()
         args.pop('self')
         param_str = _utils.serialize(args)
 
-        _log(f'Creating new version for item {param_str}')
+
+        logger.debug(f'Creating new version for item {param_str}')
 
         with Lock(self.con):
 
-            _log(f'Looking up existing versions of item `{uri}`')
+
+            logger.debug(f'Looking up existing versions of item `{uri}`')
             items = self.search(
                 uri=uri,
                 params=params,
@@ -528,11 +546,13 @@ def create(
 
             if last_version == 0:
 
-                _log('No existing version found.')
+
+                logger.debug('No existing version found.')
 
             else:
 
-                _log(f'Latest version: `{last_version}`')
+
+                logger.debug(f'Latest version: `{last_version}`')
 
             new = CacheItem.new(
                 uri,
@@ -546,7 +566,8 @@ def create(
                 cache=self,
             )
 
-            _log(f'Next version: {new.key}-{new.version}')
+
+            logger.debug(f'Next version: {new.key}-{new.version}')
 
             self._execute(f'''
                 INSERT INTO
@@ -587,7 +608,8 @@ def create(
 
             for actual_typ in ATTR_TYPES:
 
-                _log(f'Creating attributes in attr_{actual_typ}')
+
+                logger.debug(f'Creating attributes in attr_{actual_typ}')
 
                 # BEWARE
                 useattrs = [
@@ -623,9 +645,9 @@ def create(
 
                 self._execute(q)
 
-            _log(f'Successfully created: {new.version_id}')
+            logger.debug(f'Successfully created: {new.version_id}')
 
-        _log('END CREATE')
+        logger.debug('END CREATE')
 
         return new
 
@@ -700,7 +722,7 @@ def move_in(
 
         item = self.create(**args)
         
-        _log(f'Copying `{path}` to `{item.path}`.')
+        logger.debug(f'Copying `{path}` to `{item.path}`.')
         shutil.copy(path, item.path)
 
         return item
@@ -899,11 +921,11 @@ def search(
             [CacheItem[foo V:1 UNINITIALIZED]]
         """
 
-        _log('SEARCH')
+        logger.debug('SEARCH')
         args = locals()
         args.pop('self')
         param_str = _utils.serialize(args)
-        _log(f'Searching cache: {param_str}')
+        logger.debug(f'Searching cache: {param_str}')
         attrs = args.pop('attrs') or {}
         ids = self.by_attrs(attrs)
         where = self._where(**args)
@@ -940,7 +962,8 @@ def search(
 
                 self._execute(q)
 
-                _log(f'Fetching results from attr_{actual_typ}')
+
+                logger.debug(f'Fetching results from attr_{actual_typ}')
 
                 for row in self.cur.fetchall():
 
@@ -954,7 +977,8 @@ def search(
 
                     if verid not in results:
 
-                        _log(f'Found version: `{verid}`')
+
+                        logger.debug(f'Found version: `{verid}`')
 
                         results[verid] = CacheItem(
                             key=row['item_id'],
@@ -1000,8 +1024,8 @@ def search(
                 )
                 self._execute(update_q)
 
-        _log(f'Retrieved {len(results)} results')
-        _log('END SEARCH')
+        logger.debug(f'Retrieved {len(results)} results')
+        logger.debug('END SEARCH')
 
         return list(results.values())
 
@@ -1093,7 +1117,8 @@ def update(
 
             # Updating elements in main table
             ids = [it._id for it in items]
-            _log(f'Updating {len(ids)} items')
+
+            logger.debug(f'Updating {len(ids)} items')
             where = f' WHERE id IN ({", ".join(map(str, ids))})'
 
             if main:
@@ -1104,7 +1129,8 @@ def update(
             # Updating elements in attribute tables
             for actual_typ in ATTR_TYPES:
 
-                _log(f'Updating attributes in attr_{actual_typ}')
+
+                logger.debug(f'Updating attributes in attr_{actual_typ}')
 
                 useattrs = [
                     (
@@ -1164,7 +1190,7 @@ def update(
                     )
                     self._execute(new_q)
 
-            _log(f'Finished updating attributes')
+            logger.debug('Finished updating attributes')
 
 
     def update_status(
@@ -1304,11 +1330,13 @@ def _create_schema(self):
 
         self._ensure_sqlite()
 
-        _log(f'Initializing database')
+
+        logger.debug('Initializing database')
 
         fields = ', '.join(f'{k} {v}' for k, v in self._table_fields().items())
 
-        _log(f'Ensuring main table exists')
+
+        logger.debug('Ensuring main table exists')
         self._execute(f'''
             CREATE TABLE IF NOT EXISTS
             main (
@@ -1318,7 +1346,8 @@ def _create_schema(self):
 
         for typ in ATTR_TYPES:
 
-            _log(f'Ensuring attr_{typ} table exists')
+
+            logger.debug(f'Ensuring attr_{typ} table exists')
             self._execute(
                 '''
                 CREATE TABLE IF NOT EXISTS
@@ -1350,7 +1379,8 @@ def _delete_files(self, items: list[int, CacheItem]):
 
             if os.path.exists(item.path):
 
-                _log(f'Deleting from disk: `{item.path}`.')
+
+                logger.debug(f'Deleting from disk: `{item.path}`.')
                 os.remove(item.path)
 
 
@@ -1369,14 +1399,15 @@ def _delete_records(self, items: list[int, CacheItem]):
 
             where = ','.join(str(getattr(i, '_id', i)) for i in items)
             where = f' WHERE id IN ({where})'
-            _log(f'_delete_records: {len(items)} IDs to be deleted.')
+
+            logger.debug(f'_delete_records: {len(items)} IDs to be deleted.')
             n_before = len(self)
 
             for actual_typ in ATTR_TYPES:
 
                 attr_table = f'attr_{actual_typ}'
 
-                _log(f'Deleting attributes from {attr_table}')
+                logger.debug(f'Deleting attributes from {attr_table}')
 
                 q = f'DELETE FROM {attr_table} {where}'
 
@@ -1387,7 +1418,8 @@ def _delete_records(self, items: list[int, CacheItem]):
 
             self._execute(q)
 
-            _log(f'Deleted {n_before - len(self)} records.')
+
+            logger.debug(f'Deleted {n_before - len(self)} records.')
 
 
     def _ensure_sqlite(self):
@@ -1410,7 +1442,8 @@ def _execute(self, query: str):
         """
 
         query = re.sub(r'\s+', ' ', query)
-        _log(f'Executing query: {query}')
+
+        logger.debug(f'Executing query: {query}')
         self.cur.execute(query)
         self.con.commit()
 
@@ -1420,7 +1453,8 @@ def _open_sqlite(self):
         Opens the cache registry (SQL database) connection.
         """
 
-        _log(f'Opening SQLite database: {self.path}')
+
+        logger.debug(f'Opening SQLite database: {self.path}')
         self.con = sqlite3.connect(self.path)
         self.cur = self.con.cursor()
         self._create_schema()
@@ -1464,7 +1498,8 @@ def _set_path(self, path: str | None, pkg: str | None = None):
 
             path = os.path.join(path, 'cache.sqlite')
 
-        _log(f'Setting SQLite database path: {path}')
+
+        logger.debug(f'Setting SQLite database path: {path}')
         self.path = path
         self.dir = os.path.dirname(self.path)
 
diff --git a/cache_manager/_freshness.py b/cache_manager/_freshness.py
index c3855cc..97c28c7 100644
--- a/cache_manager/_freshness.py
+++ b/cache_manager/_freshness.py
@@ -6,14 +6,17 @@
 
 import os
 import hashlib
+import logging
 from email.utils import parsedate_to_datetime
 from typing import TYPE_CHECKING
 
 if TYPE_CHECKING:
     from pathlib import Path
 
-from cache_manager._session import _log
 
+#--- Module logger 
+logger = logging.getLogger(__name__)
+logger.addHandler(logging.NullHandler())
 
 def metadata_from_item(item) -> dict:
     """
@@ -92,7 +95,7 @@ def _check_etag(remote_headers: dict, local_metadata: dict) -> tuple[bool, str]:
         return False, 'no local etag stored'
 
     is_current = remote_etag == local_etag
-    _log(f'ETag check: remote={remote_etag}, local={local_etag}, current={is_current}')
+    logger.debug(f'ETag check: remote={remote_etag}, local={local_etag}, current={is_current}')
     return is_current, 'etag match' if is_current else 'etag mismatch'
 
 
@@ -116,10 +119,10 @@ def _check_last_modified(
         remote_dt = parsedate_to_datetime(remote_modified)
         local_dt = parsedate_to_datetime(local_modified)
         is_current = local_dt >= remote_dt
-        _log(f'Last-Modified check: remote={remote_dt}, local={local_dt}, current={is_current}')
+        logger.debug(f'Last-Modified check: remote={remote_dt}, local={local_dt}, current={is_current}')
         return is_current, 'not modified' if is_current else 'modified'
     except (ValueError, TypeError) as e:
-        _log(f'Error parsing dates: {e}')
+        logger.warning(f'Error parsing dates: {e}')
         return False, f'date parse error: {e}'
 
 
@@ -134,7 +137,7 @@ def _check_hash(
     if remote_md5:
         local_md5 = _compute_hash(local_path, 'md5')
         is_current = remote_md5 == local_md5
-        _log(f'MD5 check: remote={remote_md5}, local={local_md5}, current={is_current}')
+        logger.debug(f'MD5 check: remote={remote_md5}, local={local_md5}, current={is_current}')
         return is_current, 'md5 match' if is_current else 'md5 mismatch'
 
     local_sha256 = local_metadata.get('sha256')
@@ -155,10 +158,10 @@ def _check_size(local_path: str | Path, remote_headers: dict) -> tuple[bool, str
         remote_size = int(remote_size)
         local_size = os.path.getsize(local_path)
         is_current = local_size == remote_size
-        _log(f'Size check: remote={remote_size}, local={local_size}, current={is_current}')
+        logger.debug(f'Size check: remote={remote_size}, local={local_size}, current={is_current}')
         return is_current, 'size match' if is_current else 'size mismatch'
     except (ValueError, OSError) as e:
-        _log(f'Error checking size: {e}')
+        logger.warning(f'Error checking size: {e}')
         return False, f'size check error: {e}'
 
 
@@ -177,8 +180,8 @@ def get_remote_headers(url: str, **kwargs) -> dict:
 
     try:
         response = requests.head(url, allow_redirects=True, **kwargs)
-        _log(f'HEAD request to {url}: status={response.status_code}')
+        logger.debug(f'HEAD request to {url}: status={response.status_code}')
         return dict(response.headers)
     except Exception as e:
-        _log(f'Error getting remote headers: {e}')
+        logger.warning(f'Error getting remote headers: {e}')
         return {}
diff --git a/cache_manager/_item.py b/cache_manager/_item.py
index 02f1602..3f53011 100644
--- a/cache_manager/_item.py
+++ b/cache_manager/_item.py
@@ -7,6 +7,7 @@
 from typing import IO, Type
 import os
 import datetime
+import logging
 
 from pypath_common import _misc
 
@@ -15,6 +16,10 @@
 import cache_manager
 import cache_manager.utils as _utils
 
+#--- Module logger 
+logger = logging.getLogger(__name__)
+logger.addHandler(logging.NullHandler())
+
 
 class CacheItem:
     """
diff --git a/cache_manager/_lock.py b/cache_manager/_lock.py
index 9620b79..7ccd6b6 100644
--- a/cache_manager/_lock.py
+++ b/cache_manager/_lock.py
@@ -5,6 +5,11 @@
 ]
 
 import sqlite3
+import logging
+
+#--- Module logger 
+logger = logging.getLogger(__name__)
+logger.addHandler(logging.NullHandler())
 
 locked_connections = {}
 
diff --git a/cache_manager/_metadata.py b/cache_manager/_metadata.py
index a6d080d..aebf0ca 100644
--- a/cache_manager/_metadata.py
+++ b/cache_manager/_metadata.py
@@ -22,11 +22,15 @@
 import os
 import pathlib
 import importlib.metadata
+import logging
 
 import toml
 
 _VERSION = '0.1.1'
 
+#--- Module logger 
+logger = logging.getLogger(__name__)
+logger.addHandler(logging.NullHandler())
 
 def get_metadata():
     """
diff --git a/cache_manager/_open.py b/cache_manager/_open.py
index aa63022..7c6b841 100644
--- a/cache_manager/_open.py
+++ b/cache_manager/_open.py
@@ -13,11 +13,15 @@
 import struct
 import tarfile
 import zipfile
+import logging
 
 from pypath_common import _misc as _common
 from pypath_common import _constants as _const
 
-from cache_manager._session import _log
+
+#--- Module logger 
+logger = logging.getLogger(__name__)
+logger.addHandler(logging.NullHandler())
 
 COMPRESSED =  {'gz', 'xz', 'bz2'}
 ARCHIVES = {'zip', 'tar', 'tar.gz', 'tar.bz2', 'tar.xz'}
@@ -155,7 +159,7 @@ def open(self):
         if not os.path.exists(self.path):
 
             msg = f'No such file: `{self.path}`.'
-            _log(msg)
+            logger.warning(msg)
 
             raise FileNotFoundError(msg)
 
@@ -173,7 +177,7 @@ def open_gz(self):
         attribute `result`.
         """
 
-        _log(f'Opening gzip file: {self.path}')
+        logger.debug(f'Opening gzip file: {self.path}')
 
         self.fileobj.seek(-4, 2)
         self.size = struct.unpack('I', self.fileobj.read(4))[0]
@@ -192,13 +196,13 @@ def open_gz(self):
                 if self.default_mode == 'rb'
                 else self._gzfile_mode_r,
             )
-            _log(f'Result is an iterator over the lines of {self.path}')
+            logger.debug(f'Result is an iterator over the lines of {self.path}')
 
         else:
 
             self.result = self.gzfile.read()
             self.gzfile.close()
-            _log(
+            logger.debug(
                 f'Data has been read from gzip file {self.path}. The file has '
                 'been closed.',
             )
@@ -210,7 +214,7 @@ def open_plain(self):
         `result`.
         """
 
-        _log(f'Opening plain text file {self.path}')
+        logger.debug(f'Opening plain text file {self.path}')
 
         self.size = os.path.getsize(self.fileobj.name)
 
@@ -222,7 +226,7 @@ def open_plain(self):
 
             self.result = self.fileobj.read()
             self.fileobj.close()
-            _log(
+            logger.debug(
                 f'Contents of {self.path} has been read and the file has been '
                 'closed.',
             )
@@ -234,7 +238,7 @@ def open_tar(self):
         attribute `result`.
         """
 
-        _log(f'Opening tar file: {self.path}')
+        logger.debug(f'Opening tar file: {self.path}')
 
         self._files = {}
         self.sizes = {}
@@ -263,14 +267,14 @@ def open_tar(self):
 
                 else:
 
-                    _log(f'Reading contents of file from archive: `{m.name}`.')
+                    logger.debug(f'Reading contents of file from archive: `{m.name}`.')
                     self._files[m.name] = this_file.read()
                     this_file.close()
 
         if not self.large:
 
             self.tarfile.close()
-            _log(f'File closed: `{self.path}`.')
+            logger.debug(f'File closed: `{self.path}`.')
 
         self.result = self._files
 
@@ -281,7 +285,7 @@ def open_zip(self):
         attribute `result`.
         """
 
-        _log(f'Opening zip file {self.path}')
+        logger.debug(f'Opening zip file {self.path}')
 
         self._files_multipart = {}
         self.sizes = {}
@@ -319,7 +323,7 @@ def open_zip(self):
         if not self.large:
 
             self.zipfile.close()
-            _log(
+            logger.debug(
                 f'Data has been read from zip file {self.path}. File has been '
                 'closed',
             )
diff --git a/cache_manager/_session.py b/cache_manager/_session.py
index 4fc54d2..26255e3 100644
--- a/cache_manager/_session.py
+++ b/cache_manager/_session.py
@@ -1,11 +1,13 @@
 import functools as _ft
+import logging
 
-from pypath_common import log as _read_log
 from pypath_common import session as _session
 
+#--- Module logger 
+logger = logging.getLogger(__name__)
+logger.addHandler(logging.NullHandler())
 
 _get_session = _ft.partial(_session, 'cache_manager')
-log = _ft.partial(_read_log, 'cache_manager')
+
 
 session = _get_session()
-_log = session._logger.msg
diff --git a/cache_manager/_status.py b/cache_manager/_status.py
index 85eb4c5..6608b8b 100644
--- a/cache_manager/_status.py
+++ b/cache_manager/_status.py
@@ -1,11 +1,15 @@
 from __future__ import annotations
 
+import logging
+import enum
+
 __all__ = [
     'Status',
 ]
 
-import enum
-
+#--- Module logger 
+logger = logging.getLogger(__name__)
+logger.addHandler(logging.NullHandler())
 
 class Status(enum.Enum):
     """
diff --git a/cache_manager/utils.py b/cache_manager/utils.py
index 944ed99..f0879e2 100644
--- a/cache_manager/utils.py
+++ b/cache_manager/utils.py
@@ -14,10 +14,14 @@
 import hashlib
 import datetime
 import collections
+import logging
 
 from pypath_common import _misc
 import dateutil
 
+#--- Module logger 
+logger = logging.getLogger(__name__)
+logger.addHandler(logging.NullHandler())
 
 def hash(value: Any) -> str:
     """