Debug updates

osxphotos/__init__.py

@@ -1,5 +1,8 @@
+import logging
+
 from ._constants import AlbumSortOrder
 from ._version import __version__
+from .debug import is_debug, set_debug
 from .exiftool import ExifTool
 from .export_db import ExportDB
 from .fileutil import FileUtil, FileUtilNoOp
@@ -14,13 +17,14 @@ from .placeinfo import PlaceInfo
 from .queryoptions import QueryOptions
 from .scoreinfo import ScoreInfo
 from .searchinfo import SearchInfo
-from .utils import _debug, _get_logger, _set_debug
+from .utils import _get_logger
+
+if not is_debug():
+    logging.disable(logging.DEBUG)
 
 __all__ = [
     "__version__",
-    "_debug",
     "_get_logger",
-    "_set_debug",
     "AlbumSortOrder",
     "CommentInfo",
     "ExifTool",
@@ -30,6 +34,7 @@ __all__ = [
     "ExportResults",
     "FileUtil",
     "FileUtilNoOp",
+    "is_debug",
     "LikeInfo",
     "MomentInfo",
     "PersonInfo",
@@ -41,4 +46,5 @@ __all__ = [
     "QueryOptions",
     "ScoreInfo",
     "SearchInfo",
+    "set_debug",
 ]

osxphotos/cli/__init__.py

@@ -7,7 +7,8 @@ from rich.traceback import install as install_traceback
 from osxphotos.debug import (
     debug_breakpoint,
     debug_watch,
-    get_debug_args,
+    get_debug_flags,
+    get_debug_options,
     set_debug,
     wrap_function,
 )
@@ -19,7 +20,7 @@ from osxphotos.debug import (
 # to wrap 'osxphotos.exiftool.ExifTool.asdict', the original ExifTool.asdict will be
 # wrapped but the caller will have a reference to the function before it was wrapped
 # reference: https://github.com/GrahamDumpleton/wrapt/blob/develop/blog/13-ordering-issues-when-monkey-patching-in-python.md
-args = get_debug_args(["--watch", "--breakpoint"], sys.argv)
+args = get_debug_options(["--watch", "--breakpoint"], sys.argv)
 for func_name in args.get("--watch", []):
     try:
         wrap_function(func_name, debug_watch)
@@ -36,6 +37,10 @@ for func_name in args.get("--breakpoint", []):
         print(f"{func_name} does not exist")
         sys.exit(1)
 
+args = get_debug_flags(["--debug"], sys.argv)
+if args.get("--debug", False):
+    set_debug(True)
+    print("Debugging enabled")
 
 from .about import about
 from .albums import albums

osxphotos/cli/cli.py

@@ -31,8 +31,6 @@ from .uuid import uuid
 # Click CLI object & context settings
 class CLI_Obj:
     def __init__(self, db=None, json=False, debug=False, group=None):
-        if debug:
-            osxphotos._set_debug(True)
         self.db = db
         self.json = json
         self.group = group

osxphotos/cli/export.py

@@ -802,7 +802,6 @@ def export(
 
     if debug:
         set_debug(True)
-        osxphotos._set_debug(True)
 
     if profile:
         click.echo("Profiling...")

osxphotos/cli/query.py

@@ -149,17 +149,13 @@ def query(
     query_eval,
     query_function,
     add_to_album,
-    debug,
+    debug,  # handled in cli/__init__.py
 ):
     """Query the Photos database using 1 or more search options;
     if more than one option is provided, they are treated as "AND"
     (e.g. search for photos matching all options).
     """
 
-    if debug:
-        set_debug(True)
-        osxphotos._set_debug(True)
-
     # if no query terms, show help and return
     # sanity check input args
     nonexclusive = [

osxphotos/debug.py

@@ -1,7 +1,9 @@
 """Utilities for debugging"""
 
+import logging
 import pdb
 import sys
+import time
 from datetime import datetime
 from typing import Dict, List
 
@@ -17,6 +19,7 @@ def set_debug(debug: bool):
     """set debug flag"""
     global DEBUG
     DEBUG = debug
+    logging.disable(logging.NOTSET if debug else logging.DEBUG)
 
 
 def is_debug():
@@ -32,8 +35,10 @@ def debug_watch(wrapped, instance, args, kwargs):
     print(
         f"{timestamp} {name} called from {caller} with args: {args} and kwargs: {kwargs}"
     )
+    start_t = time.perf_counter()
     rv = wrapped(*args, **kwargs)
-    print(f"{timestamp} {name} returned: {rv}")
+    stop_t = time.perf_counter()
+    print(f"{timestamp} {name} returned: {rv}, elapsed time: {stop_t - start_t} sec")
     return rv
 
 
@@ -52,12 +57,12 @@ def wrap_function(function_path, wrapper):
         raise AttributeError(f"{module}.{name} does not exist") from e
 
 
-def get_debug_args(arg_names: List, argv: List) -> Dict:
+def get_debug_options(arg_names: List, argv: List) -> Dict:
-    """Get the arguments for the debug options; 
+    """Get the options for the debug options;
     Some of the debug options like --watch and --breakpoint need to be processed before any other packages are loaded
     so they can't be handled in the normal click argument processing, thus this function is called
     from osxphotos/cli/__init__.py
-    
+
     Assumes multi-valued options are OK and that all options take form of --option VALUE or --option=VALUE
     """
     # argv[0] is the program name
@@ -83,3 +88,17 @@ def get_debug_args(arg_names: List, argv: List) -> Dict:
                 except IndexError as e:
                     raise ValueError(f"Missing value for {arg}") from e
     return args
+
+
+def get_debug_flags(arg_names: List, argv: List) -> Dict:
+    """Get the flags for the debug options;
+    Processes flags like --debug that resolve to True or False
+    """
+    # argv[0] is the program name
+    # argv[1] is the command
+    # argv[2:] are the arguments
+    args = {arg_name: False for arg_name in arg_names}
+    for arg_name in arg_names:
+        if arg_name in argv[1:]:
+            args[arg_name] = True
+    return args

osxphotos/photoinfo.py

@@ -54,7 +54,7 @@ from .scoreinfo import ScoreInfo
 from .searchinfo import SearchInfo
 from .text_detection import detect_text
 from .uti import get_preferred_uti_extension, get_uti_for_extension
-from .utils import _debug, _get_resource_loc, list_directory, _debug
+from .utils import _get_resource_loc, list_directory
 
 __all__ = ["PhotoInfo", "PhotoInfoNone"]
 

osxphotos/photosdb/photosdb.py

@@ -50,6 +50,7 @@ from .._constants import (
 from .._version import __version__
 from ..albuminfo import AlbumInfo, FolderInfo, ImportInfo, ProjectInfo
 from ..datetime_utils import datetime_has_tz, datetime_naive_to_local
+from ..debug import is_debug
 from ..fileutil import FileUtil
 from ..personinfo import PersonInfo
 from ..photoinfo import PhotoInfo
@@ -58,7 +59,6 @@ from ..queryoptions import QueryOptions
 from ..utils import (
     _check_file_exists,
     _db_is_locked,
-    _debug,
     _get_os_version,
     _open_sql_file,
     get_last_library_path,
@@ -264,7 +264,7 @@ class PhotosDB:
         # key is Z_PK of ZMOMENT table and values are the moment info
         self._db_moment_pk = {}
 
-        if _debug():
+        if is_debug():
             logging.debug(f"dbfile = {dbfile}")
 
         if dbfile is None:
@@ -281,7 +281,7 @@ class PhotosDB:
         if not _check_file_exists(dbfile):
             raise FileNotFoundError(f"dbfile {dbfile} does not exist", dbfile)
 
-        if _debug():
+        if is_debug():
             logging.debug(f"dbfile = {dbfile}")
 
         # init database names
@@ -321,7 +321,7 @@ class PhotosDB:
                     verbose(f"Database locked, creating temporary copy.")
                     self._tmp_db = self._copy_db_file(self._dbfile_actual)
 
-            if _debug():
+            if is_debug():
                 logging.debug(
                     f"_dbfile = {self._dbfile}, _dbfile_actual = {self._dbfile_actual}"
                 )
@@ -336,7 +336,7 @@ class PhotosDB:
             masters_path = os.path.join(library_path, "originals")
             self._masters_path = masters_path
 
-        if _debug():
+        if is_debug():
             logging.debug(f"library = {library_path}, masters = {masters_path}")
 
         if int(self._db_version) <= int(_PHOTOS_4_VERSION):
@@ -592,7 +592,7 @@ class PhotosDB:
             print(f"Error copying{fname} to {dest_path}", file=sys.stderr)
             raise Exception
 
-        if _debug():
+        if is_debug():
             logging.debug(dest_path)
 
         return dest_path
@@ -619,7 +619,7 @@ class PhotosDB:
     #         print("Error linking " + fname + " to " + dest_path, file=sys.stderr)
     #         raise Exception
 
-    #     if _debug():
+    #     if is_debug():
     #         logging.debug(dest_path)
 
     #     return dest_path
@@ -1079,7 +1079,7 @@ class PhotosDB:
                 self._dbphotos[uuid]["type"] = _MOVIE_TYPE
             else:
                 # unknown
-                if _debug():
+                if is_debug():
                     logging.debug(f"WARNING: {uuid} found unknown type {row[21]}")
                 self._dbphotos[uuid]["type"] = None
 
@@ -1302,7 +1302,7 @@ class PhotosDB:
                         and row[6] == 2
                     ):
                         if "edit_resource_id" in self._dbphotos[uuid]:
-                            if _debug():
+                            if is_debug():
                                 logging.debug(
                                     f"WARNING: found more than one edit_resource_id for "
                                     f"UUID {row[0]},adjustmentUUID {row[1]}, modelID {row[2]}"
@@ -1581,7 +1581,7 @@ class PhotosDB:
         but it works so don't touch it.
         """
 
-        if _debug():
+        if is_debug():
             logging.debug(f"_process_database5")
         verbose = self._verbose
         verbose(f"Processing database.")
@@ -1603,7 +1603,7 @@ class PhotosDB:
         hdr_type_column = _DB_TABLE_NAMES[photos_ver]["HDR_TYPE"]
 
         # Look for all combinations of persons and pictures
-        if _debug():
+        if is_debug():
             logging.debug(f"Getting information about persons")
 
         # get info to associate persons with photos
@@ -2012,7 +2012,7 @@ class PhotosDB:
             elif row[17] == 1:
                 info["type"] = _MOVIE_TYPE
             else:
-                if _debug():
+                if is_debug():
                     logging.debug(f"WARNING: {uuid} found unknown type {row[17]}")
                 info["type"] = None
 
@@ -2211,7 +2211,7 @@ class PhotosDB:
             if uuid in self._dbphotos:
                 self._dbphotos[uuid]["extendedDescription"] = normalize_unicode(row[1])
             else:
-                if _debug():
+                if is_debug():
                     logging.debug(
                         f"WARNING: found description {row[1]} but no photo for {uuid}"
                     )
@@ -2230,7 +2230,7 @@ class PhotosDB:
             if uuid in self._dbphotos:
                 self._dbphotos[uuid]["adjustmentFormatID"] = row[2]
             else:
-                if _debug():
+                if is_debug():
                     logging.debug(
                         f"WARNING: found adjustmentformatidentifier {row[2]} but no photo for uuid {row[0]}"
                     )

osxphotos/utils.py

@@ -20,8 +20,6 @@ from plistlib import load as plistload
 from typing import Callable, List, Union, Optional
 
 import CoreFoundation
-import objc
-from Foundation import NSFileManager, NSPredicate, NSString
 
 from ._constants import UNICODE_FORMAT
 
@@ -41,17 +39,12 @@ __all__ = [
     "normalize_unicode",
 ]
 
-_DEBUG = False
-
 
 logging.basicConfig(
     level=logging.DEBUG,
     format="%(asctime)s - %(levelname)s - %(filename)s - %(lineno)d - %(message)s",
 )
 
-if not _DEBUG:
-    logging.disable(logging.DEBUG)
-
 
 def _get_logger():
     """Used only for testing
@@ -62,21 +55,6 @@ def _get_logger():
     return logging.Logger(__name__)
 
 
-def _set_debug(debug):
-    """Enable or disable debug logging"""
-    global _DEBUG
-    _DEBUG = debug
-    if debug:
-        logging.disable(logging.NOTSET)
-    else:
-        logging.disable(logging.DEBUG)
-
-
-def _debug():
-    """returns True if debugging turned on (via _set_debug), otherwise, false"""
-    return _DEBUG
-
-
 def noop(*args, **kwargs):
     """do nothing (no operation)"""
     pass
@@ -270,8 +248,7 @@ def list_photo_libraries():
     )
 
     # On older OS, may not get all libraries so make sure we get the last one
-    last_lib = get_last_library_path()
+    if last_lib := get_last_library_path():
-    if last_lib:
         lib_list.append(last_lib)
 
     output = subprocess.check_output(
@@ -279,8 +256,7 @@ def list_photo_libraries():
     ).splitlines()
     for lib in output:
         lib_list.append(lib.decode("utf-8"))
-    lib_list = list(set(lib_list))
+    lib_list = sorted(set(lib_list))
-    lib_list.sort()
     return lib_list
 
 
@@ -505,8 +481,11 @@ def load_function(pyfile: str, function_name: str) -> Callable:
 
     try:
         func = getattr(module, function_name)
-    except AttributeError:
+    except AttributeError as e:
-        raise ValueError(f"'{function_name}' not found in module '{module_name}'")
+        raise ValueError(
+            f"'{function_name}' not found in module '{module_name}'"
+        ) from e
+
     finally:
         # restore sys.path
         sys.path = syspath

tests/test_debug.py

@@ -0,0 +1,20 @@
+"""Test debug"""
+
+import logging
+
+import osxphotos
+from osxphotos.debug import is_debug, set_debug
+
+
+def test_debug_enable():
+    set_debug(True)
+    logger = osxphotos._get_logger()
+    assert logger.isEnabledFor(logging.DEBUG)
+    assert is_debug()
+
+
+def test_debug_disable():
+    set_debug(False)
+    logger = osxphotos._get_logger()
+    assert not logger.isEnabledFor(logging.DEBUG)
+    assert not is_debug()

tests/test_utils.py

@@ -21,18 +21,6 @@ from osxphotos.utils import (
 )
 
 
-def test_debug_enable():
-    osxphotos._set_debug(True)
-    logger = osxphotos._get_logger()
-    assert logger.isEnabledFor(logging.DEBUG)
-
-
-def test_debug_disable():
-    osxphotos._set_debug(False)
-    logger = osxphotos._get_logger()
-    assert not logger.isEnabledFor(logging.DEBUG)
-
-
 def test_dd_to_dms():
     # expands coverage for edge case in _dd_to_dms