general: cleanup logging and warnings

- handle 'from promnesia import ...' warnings properly; previously they'd always be shown
- more consistent logging in server (and slightly less)
- suppress spammy warnings in tests (via conftest)

Author: karlicoss

src/promnesia/__init__.py

@@ -1,20 +1,27 @@
-# add deprecation warning so eventually this may converted to a namespace package?
-import warnings
+def __getattr__(name: str):
+    # for backward compatibility
+    deprecated_imports = [
+        'Context',
+        'DbVisit',
+        'Loc',
+        'PathIsh',
+        'Res',
+        'Results',
+        'Source',
+        'Visit',
+        'last',
+    ]
+    if name in deprecated_imports:
+        import warnings
 
-from .common import (  # noqa: F401
-    Context,
-    DbVisit,
-    Loc,
-    PathIsh,
-    Res,
-    Results,
-    Source,
-    Visit,
-    last,
-)
+        warnings.warn(
+            "DEPRECATED! Import directly from 'promnesia.common', e.g. 'from promnesia.common import Visit, Source, Results'",
+            DeprecationWarning,
+        )
 
-# TODO think again about it -- what are the pros and cons?
-warnings.warn(
-    "DEPRECATED! Please import directly from 'promnesia.common', e.g. 'from promnesia.common import Visit, Source, Results'",
-    DeprecationWarning,
-)
+        from . import common
+
+        return getattr(common, name)
+
+    # need to raise so other imports can proceed as usual
+    raise AttributeError

src/promnesia/common.py

@@ -22,6 +22,7 @@
 
 import platformdirs
 from more_itertools import intersperse
+from typing_extensions import deprecated
 
 from .cannon import canonify
 
@@ -338,8 +339,8 @@ def __init__(self, ff: PreSource, *args, src: SourceName = '', name: SourceName
         self.args = args
         self.kwargs = kwargs
         self.extractor: Extractor = lambda: self.ff(*self.args, **self.kwargs)
-        if src is not None:
-            warnings.warn("'src' argument is deprecated, please use 'name' instead", DeprecationWarning)
+        if src != '':
+            warnings.warn("'src' argument is deprecated, use 'name' instead", DeprecationWarning)
         if name != '':
             self.name = name
         elif src != '':
@@ -357,8 +358,8 @@ def description(self) -> str:
         return f'{getattr(self.ff, "__module__", None)}:{getattr(self.ff, "__name__", None)} {self.args} {self.kwargs}'
 
     @property
+    @deprecated("'src' property is deprecated, use 'name' instead")
     def src(self) -> str:
-        # TODO deprecated!
         return self.name
 
 
@@ -609,7 +610,8 @@ def measure(tag: str = '', *, logger: logging.Logger, unit: str = 'ms'):
     secs = after - before
     mult = {'s': 1, 'ms': 10**3, 'us': 10**6}[unit]
     xx = secs * mult
-    logger.debug(f'[{tag}]: {xx:.1f}{unit} elapsed')
+    if secs > 1:
+        logger.warning(f'[{tag}]: {xx:.1f}{unit} elapsed')
 
 
 def is_sqlite_db(x: Path) -> bool:

src/promnesia/server.py

@@ -130,10 +130,13 @@ def get_db_path(*, check: bool = True) -> Path:
     return db
 
 
+# NOTE:
+# - this logging might appear multiple times in the logs for the same db/mtime because server uses multiple threads
+# - lru cache isn't ideal perhaps because there is no cleanup happening? but hasn't caused any issues so far
 @lru_cache(1)
 # PathWithMtime aids lru_cache in reloading the sqlalchemy binder
 def _get_stuff(db_path: PathWithMtime) -> DbStuff:
-    get_logger().debug('Reloading DB: %s', db_path)
+    get_logger().debug(f'reloading db: {db_path}')
     return get_db_stuff(db_path=db_path.path)
 
 
@@ -169,12 +172,11 @@ def search_common(url: str, where: Where) -> VisitsResponse:
     logger = get_logger()
     config = EnvConfig.get()
 
-    logger.info('url: %s', url)
     original_url = url and url.strip()
     url = canonify(original_url)
     if not url:  # Don't eliminate a "#tag" query.
         url = original_url
-    logger.info('normalised url: %s', url)
+    logger.debug(f'normalised url {original_url!r} to {url!r}')
 
     engine, table = get_stuff()
 
@@ -192,7 +194,7 @@ def search_common(url: str, where: Where) -> VisitsResponse:
                 # return result
             raise
 
-    logger.debug('got %d visits from db', len(visits))
+    logger.debug(f'got {len(visits)} visits from db, responding')
 
     vlist: list[DbVisit] = []
     for vis in visits:
@@ -202,7 +204,6 @@ def search_common(url: str, where: Where) -> VisitsResponse:
             vis = vis._replace(dt=dt)
         vlist.append(vis)
 
-    logger.debug('responding with %d visits', len(vlist))
     # TODO respond with normalised result, then frontent could choose how to present children/siblings/whatever?
     return VisitsResponse(
         original_url=original_url,
@@ -215,32 +216,34 @@ def search_common(url: str, where: Where) -> VisitsResponse:
 # perhasp should switch to get for most endpoint
 @app.get ('/status', response_model=Json)  # fmt: skip
 @app.post('/status', response_model=Json)  # fmt: skip
-def status() -> Json:
+def status(fastapi_request: fastapi.Request) -> Json:
     '''
     Ideally, status will always respond, regardless the internal state of the backend?
     '''
-    logger = get_logger()
+    get_logger().debug(f'{fastapi_request.url.path}')
 
     db = get_db_path(check=False)
-    try:
-        assert db.exists(), db
+    db_exists: bool = db.exists()
+    if db_exists:
         db_path = str(db)
-    except Exception as e:
-        logger.exception(e)
-        db_path = f'ERROR: db not found/unreadable (expected path {db}). You probably forgot to run indexer first. See https://github.com/karlicoss/promnesia/blob/master/doc/TROUBLESHOOTING.org'
+    else:
+        db_path = f'ERROR: db not found/unreadable (expected path {db}). You likely forgot to run indexer first. See https://github.com/karlicoss/promnesia/blob/master/doc/TROUBLESHOOTING.org.'
 
     stats: Json
-    try:
-        stats = db_stats(db)
-    except Exception as e:
-        logger.exception(e)
-        stats = {'ERROR': str(e)}
+    if db_exists:
+        try:
+            stats = db_stats(db)
+        except Exception as e:
+            stats = {'ERROR': str(e)}
+    else:
+        stats = {'ERROR': 'db file does not exist'}
 
     version: str | None
     try:
         version = get_version()
     except Exception as e:
-        logger.exception(e)
+        # this shouldn't really fail at all, so fine to log exception always
+        get_logger().exception(e)
         version = None
 
     return {
@@ -257,11 +260,10 @@ class VisitsRequest:
 
 @app.get ('/visits', response_model=VisitsResponse)  # fmt: skip
 @app.post('/visits', response_model=VisitsResponse)  # fmt: skip
-def visits(request: VisitsRequest) -> VisitsResponse:
-    url = request.url
-    get_logger().info('/visited %s', url)
+def visits(request: VisitsRequest, fastapi_request: fastapi.Request) -> VisitsResponse:
+    get_logger().debug(f'{fastapi_request.url.path} {request}')
     return search_common(
-        url=url,
+        url=request.url,
         # odd, doesn't work just with: x or (y and z)
         where=lambda table, url: or_(
             # exact match
@@ -279,21 +281,18 @@ class SearchRequest:
 
 @app.get ('/search', response_model=VisitsResponse)  # fmt: skip
 @app.post('/search', response_model=VisitsResponse)  # fmt: skip
-def search(request: SearchRequest) -> VisitsResponse:
-    url = request.url
-    get_logger().info('/search %s', url)
-    # fmt: off
+def search(request: SearchRequest, fastapi_request: fastapi.Request) -> VisitsResponse:
+    get_logger().debug(f'{fastapi_request.url.path} {request}')
     return search_common(
-        url=url,
+        url=request.url,
         where=lambda table, url: or_(
             # todo hmm. think about it, not sure if I need proper indexer for fuzzy search etc?
             table.c.norm_url     .contains(url, autoescape=True),
             table.c.orig_url     .contains(url, autoescape=True),
             table.c.context      .contains(url, autoescape=True),
             table.c.locator_title.contains(url, autoescape=True),
         ),
-    )
-    # fmt: on
+    )  # fmt: skip
 
 
 @dataclass
@@ -303,10 +302,9 @@ class SearchAroundRequest:
 
 @app.get ('/search_around', response_model=VisitsResponse)  # fmt: skip
 @app.post('/search_around', response_model=VisitsResponse)  # fmt: skip
-def search_around(request: SearchAroundRequest) -> VisitsResponse:
-    timestamp = request.timestamp
-    get_logger().info('/search_around %s', timestamp)
-    utc_timestamp = timestamp  # old 'timestamp' name is legacy
+def search_around(request: SearchAroundRequest, fastapi_request: fastapi.Request) -> VisitsResponse:
+    get_logger().debug(f'{fastapi_request.url.path} {request}')
+    utc_timestamp = request.timestamp  # old 'timestamp' name is legacy
 
     # TODO meh. use count/pagination instead?
     delta_back = timedelta(hours=3).total_seconds()
@@ -366,14 +364,12 @@ class VisitedRequest:
 
 @app.get ('/visited', response_model=VisitedResponse)  # fmt: skip
 @app.post('/visited', response_model=VisitedResponse)  # fmt: skip
-def visited(request: VisitedRequest) -> VisitedResponse:
-    # TODO instead switch logging to fastapi
+def visited(request: VisitedRequest, fastapi_request: fastapi.Request) -> VisitedResponse:
+    get_logger().debug(f'{fastapi_request.url.path} {request}')
+
     urls = request.urls
     client_version = request.client_version
 
-    logger = get_logger()
-    logger.info('/visited %s %s', urls, client_version)
-
     _version = as_version(client_version)  # todo use it?
 
     nurls = [canonify(u) for u in urls]

src/promnesia/sources/browser_legacy.py

@@ -5,7 +5,7 @@
 from pathlib import Path
 from urllib.parse import unquote
 
-from promnesia import config
+import promnesia.config as config
 from promnesia.common import Loc, PathIsh, Results, Second, Visit, is_sqlite_db, logger
 
 try:

src/promnesia/sources/takeout_legacy.py

@@ -35,7 +35,7 @@ def index() -> Results:
 
 from more_itertools import unique_everseen
 
-from promnesia import config
+import promnesia.config as config
 
 try:
     from cachew import cachew

tests/addon.py

@@ -4,6 +4,7 @@
 
 from __future__ import annotations
 
+import functools
 import json
 from collections.abc import Iterator, Sequence
 from contextlib import contextmanager
@@ -27,12 +28,8 @@
 from .common import logger
 from .webdriver_utils import frame_context, is_visible, wait_for_alert
 
-
-@contextmanager
-def measure(*args, **kwargs):
-    kwargs['logger'] = logger
-    with measure_orig(*args, **kwargs) as m:
-        yield m
+# logger is a required arg there, so need to pass it..
+measure = functools.partial(measure_orig, logger=logger)  # type: ignore[arg-type]
 
 
 @pytest.fixture
@@ -174,8 +171,7 @@ def set_checkbox(cid: str, value: bool) -> None:  # noqa: FBT001
             if selected != value:
                 cb.click()
 
-        # TODO log properly
-        print(f"Setting: port {port}, show_dots {show_dots}")
+        logger.debug(f"setting: {port=}, {show_dots=}")
 
         self.open()
 

tests/conftest.py

@@ -0,0 +1,19 @@
+import warnings
+
+import pytest
+
+
+@pytest.fixture(autouse=True)
+def ignore_warnings():
+    ## This is coming from HPI since we use tmp_config stuff
+    # Hmm looking at it, the whole thing is pretty annoying...
+    # I think maybe instead what should happen is
+    # - if my.config is already present _and_ it's not the stub config, just use it
+    # - only otherwise try messing with it
+    warnings.filterwarnings("ignore", message="'my.config' package isn't found!")
+    ##
+    ## These are coming from hypothesis data access layer, doesn't matter for tests
+    warnings.filterwarnings("ignore", message="You might want to 'pip install colorlog'")
+    warnings.filterwarnings("ignore", message="recommended to 'pip install ijson'")
+    warnings.filterwarnings("ignore", message="recommended to 'pip install orjson'")
+    ##

tests/demos.py

@@ -10,14 +10,11 @@
 from .common import uses_x
 from .record import CURSOR_SCRIPT, SELECT_SCRIPT, hotkeys, record
 from .test_end2end import (  # type: ignore[attr-defined]
-    CHROME,
-    FIREFOX,
     _test_helper,  # ty: ignore[unresolved-import]
-    browsers,
     configure_extension,  # ty: ignore[unresolved-import]
     confirm,
 )
-from .webdriver_utils import get_webdriver
+from .webdriver_utils import CHROME, FIREFOX, browsers, get_webdriver
 
 
 def real_db():