Repository: canonical/operator

Issue:
ops.lib.autoload does not log what it is doing
There are no diagnostics available for ops.lib.use failures beyond it raising an ImportError. Charm authors need to be able to discover *why* they got an ImportError. For example:

- the code they have included is for a different API version
- fails to import with an ImportError
- Requested API was not discovered by ops.lib.autoload because not found in PYTHONPATH/linked to incorrect location.

Discussion:

Patch:
diff --git a/ops/lib/__init__.py b/ops/lib/__init__.py
index b69ce0a..88e9c5b 100644
--- a/ops/lib/__init__.py
+++ b/ops/lib/__init__.py
@@ -12,16 +12,21 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 
-import sys
+import logging
 import os
 import re
+import sys
 
 from ast import literal_eval
 from importlib.util import module_from_spec
 from importlib.machinery import ModuleSpec
 from pkgutil import get_importer
 from types import ModuleType
+from typing import List
 
+__all__ = ('use', 'autoimport')
+
+logger = logging.getLogger(__name__)
 
 _libraries = None
 
@@ -101,61 +106,121 @@ def _find_all_specs(path):
             sys_dir = "."
         try:
             top_dirs = os.listdir(sys_dir)
-        except OSError:
+        except (FileNotFoundError, NotADirectoryError):
+            continue
+        except OSError as e:
+            logger.debug("Tried to look for ops.lib packages under %r: %s", sys_dir, e)
             continue
+        logger.debug("Looking for ops.lib packages under %r", sys_dir)
         for top_dir in top_dirs:
             opslib = os.path.join(sys_dir, top_dir, 'opslib')
             try:
                 lib_dirs = os.listdir(opslib)
-            except OSError:
+            except (FileNotFoundError, NotADirectoryError):
                 continue
+            except OSError as e:
+                logger.debug("  Tried %r: %s", opslib, e)  # *lots* of things checked here
+                continue
+            else:
+                logger.debug("  Trying %r", opslib)
             finder = get_importer(opslib)
-            if finder is None or not hasattr(finder, 'find_spec'):
+            if finder is None:
+                logger.debug("  Finder for %r is None", opslib)
+                continue
+            if not hasattr(finder, 'find_spec'):
+                logger.debug("  Finder for %r has no find_spec", opslib)
                 continue
             for lib_dir in lib_dirs:
-                spec = finder.find_spec("{}.opslib.{}".format(top_dir, lib_dir))
+                spec_name = "{}.opslib.{}".format(top_dir, lib_dir)
+                spec = finder.find_spec(spec_name)
                 if spec is None:
+                    logger.debug("    No spec for %r", spec_name)
                     continue
                 if spec.loader is None:
                     # a namespace package; not supported
+                    logger.debug("    No loader for %r (probably a namespace package)", spec_name)
                     continue
+
+                logger.debug("    Found %r", spec_name)
                 yield spec
 
 
 # only the first this many lines of a file are looked at for the LIB* constants
 _MAX_LIB_LINES = 99
+# these keys, with these types, are needed to have an opslib
+_NEEDED_KEYS = {'NAME': str, 'AUTHOR': str, 'API': int, 'PATCH': int}
+
+
+def _join_and(keys: List[str]) -> str:
+    if len(keys) == 0:
+        return ""
+    if len(keys) == 1:
+        return keys[0]
+    return ", ".join(keys[:-1]) + ", and " + keys[-1]
+
+
+class _Missing:
+    """A silly little helper to only work out the difference between
+    what was found and what was needed when logging"""
+
+    def __init__(self, found):
+        self._found = found
+
+    def __str__(self):
+        exp = set(_NEEDED_KEYS)
+        got = set(self._found)
+        if len(got) == 0:
+            return "missing {}".format(_join_and(sorted(exp)))
+        return "got {}, but missing {}".format(
+            _join_and(sorted(got)),
+            _join_and(sorted(exp - got)))
 
 
 def _parse_lib(spec):
     if spec.origin is None:
+        # "can't happen"
+        logger.warning("No origin for %r (no idea why; please report)", spec.name)
         return None
 
-    _expected = {'NAME': str, 'AUTHOR': str, 'API': int, 'PATCH': int}
+    logger.debug("    Parsing %r", spec.name)
 
     try:
         with open(spec.origin, 'rt', encoding='utf-8') as f:
             libinfo = {}
             for n, line in enumerate(f):
-                if len(libinfo) == len(_expected):
+                if len(libinfo) == len(_NEEDED_KEYS):
                     break
                 if n > _MAX_LIB_LINES:
+                    logger.debug(
+                        "      Missing opslib metadata after reading to line %d: %s",
+                        _MAX_LIB_LINES, _Missing(libinfo))
                     return None
                 m = _libline_re.match(line)
                 if m is None:
                     continue
                 key, value = m.groups()
-                if key in _expected:
+                if key in _NEEDED_KEYS:
                     value = literal_eval(value)
-                    if not isinstance(value, _expected[key]):
+                    if not isinstance(value, _NEEDED_KEYS[key]):
+                        logger.debug(
+                            "      Bad type for %s: expected %s, got %s",
+                            key, _NEEDED_KEYS[key].__name__, type(value).__name__)
                         return None
                     libinfo[key] = value
             else:
-                if len(libinfo) != len(_expected):
+                if len(libinfo) != len(_NEEDED_KEYS):
+                    logger.debug(
+                        "      Missing opslib metadata after reading to end of file: %s",
+                        _Missing(libinfo))
                     return None
-    except Exception:
+    except Exception as e:
+        logger.debug("      Failed: %s", e)
         return None
 
-    return _Lib(spec, libinfo['NAME'], libinfo['AUTHOR'], libinfo['API'], libinfo['PATCH'])
+    lib = _Lib(spec, libinfo['NAME'], libinfo['AUTHOR'], libinfo['API'], libinfo['PATCH'])
+    logger.debug("    Success: found library %s", lib)
+
+    return lib
 
 
 class _Lib:
@@ -170,7 +235,10 @@ class _Lib:
         self._module = None
 
     def __repr__(self):
-        return "<_Lib {0.name} by {0.author}, API {0.api}, patch {0.patch}>".format(self)
+        return "<_Lib {}>".format(self)
+
+    def __str__(self):
+        return "{0.name} by {0.author}, API {0.api}, patch {0.patch}".format(self)
 
     def import_module(self) -> ModuleType:
         if self._module is None:


Test patch:
diff --git a/test/test_lib.py b/test/test_lib.py
index 6aa5b06..c4a1a49 100644
--- a/test/test_lib.py
+++ b/test/test_lib.py
@@ -24,6 +24,8 @@ from random import shuffle
 from shutil import rmtree
 from textwrap import dedent
 
+import logassert
+
 import ops.lib
 
 
@@ -60,6 +62,9 @@ def _flatten(specgen):
 
 
 class TestLibFinder(TestCase):
+    def setUp(self):
+        logassert.setup(self, 'ops.lib')
+
     def _mkdtemp(self) -> str:
         tmpdir = mkdtemp()
         self.addCleanup(rmtree, tmpdir)
@@ -69,12 +74,14 @@ class TestLibFinder(TestCase):
         tmpdir = self._mkdtemp()
 
         self.assertEqual(list(ops.lib._find_all_specs([tmpdir])), [])
+        self.assertLoggedDebug('Looking for ops.lib packages under', tmpdir)
 
         _mklib(tmpdir, "foo", "bar").write_text("")
 
         self.assertEqual(
             _flatten(ops.lib._find_all_specs([tmpdir])),
             [tmpdir + '/foo/opslib/bar'])
+        self.assertLoggedDebug("Found", "foo.opslib.bar")
 
     def test_multi(self):
         tmpdirA = self._mkdtemp()
@@ -172,6 +179,9 @@ class TestLibParser(TestCase):
         os.close(fd)
         return ModuleSpec(name=name, loader=None, origin=fname)
 
+    def setUp(self):
+        logassert.setup(self, 'ops.lib')
+
     def test_simple(self):
         """Check that we can load a reasonably straightforward lib"""
         m = self._mkmod('foo', '''
@@ -186,6 +196,8 @@ class TestLibParser(TestCase):
         self.assertEqual(lib, ops.lib._Lib(None, "foo", "alice@example.com", 2, 42))
         # also check the repr while we're at it
         self.assertEqual(repr(lib), '<_Lib foo by alice@example.com, API 2, patch 42>')
+        self.assertLoggedDebug("Parsing", "foo")
+        self.assertLoggedDebug("Success")
 
     def test_libauthor_has_dashes(self):
         m = self._mkmod('foo', '''
@@ -234,6 +246,11 @@ class TestLibParser(TestCase):
         LIBPATCH = 42
         ''')
         self.assertIsNone(ops.lib._parse_lib(m))
+        self.assertLoggedDebug("Parsing", "foo")
+        self.assertLoggedDebug(
+            "Missing opslib metadata after reading to end of file:"
+            " got API, NAME, and PATCH, but missing AUTHOR")
+        self.assertNotLogged("Success")
 
     def test_too_long(self):
         """Check that if the file is too long, nothing is returned"""
@@ -244,6 +261,11 @@ class TestLibParser(TestCase):
         LIBAUTHOR = "alice@example.com"
         ''')
         self.assertIsNone(ops.lib._parse_lib(m))
+        self.assertLoggedDebug("Parsing", "foo")
+        self.assertLoggedDebug(
+            "Missing opslib metadata after reading to line 99:"
+            " missing API, AUTHOR, NAME, and PATCH")
+        self.assertNotLogged("Success")
 
     def test_no_origin(self):
         """Check that _parse_lib doesn't choke when given a spec with no origin"""
@@ -267,6 +289,9 @@ class TestLibParser(TestCase):
         LIBAUTHOR = "alice@example.com"
         ''')
         self.assertIsNone(ops.lib._parse_lib(m))
+        self.assertLoggedDebug("Parsing", "foo")
+        self.assertLoggedDebug("Failed")
+        self.assertNotLogged("Success")
 
     def test_name_is_number(self):
         """Check our behaviour when the name in the lib is a number"""
@@ -277,6 +302,9 @@ class TestLibParser(TestCase):
         LIBAUTHOR = "alice@example.com"
         ''')
         self.assertIsNone(ops.lib._parse_lib(m))
+        self.assertLoggedDebug("Parsing", "foo")
+        self.assertLoggedDebug("Bad type for NAME: expected str, got int")
+        self.assertNotLogged("Success")
 
     def test_api_is_string(self):
         """Check our behaviour when the api in the lib is a string"""
@@ -287,6 +315,9 @@ class TestLibParser(TestCase):
         LIBAUTHOR = "alice@example.com"
         ''')
         self.assertIsNone(ops.lib._parse_lib(m))
+        self.assertLoggedDebug("Parsing", "foo")
+        self.assertLoggedDebug("Bad type for API: expected int, got str")
+        self.assertNotLogged("Success")
 
     def test_patch_is_string(self):
         """Check our behaviour when the patch in the lib is a string"""
@@ -297,6 +328,9 @@ class TestLibParser(TestCase):
         LIBAUTHOR = "alice@example.com"
         ''')
         self.assertIsNone(ops.lib._parse_lib(m))
+        self.assertLoggedDebug("Parsing", "foo")
+        self.assertLoggedDebug("Bad type for PATCH: expected int, got str")
+        self.assertNotLogged("Success")
 
     def test_author_is_number(self):
         """Check our behaviour when the author in the lib is a number"""
@@ -307,6 +341,9 @@ class TestLibParser(TestCase):
         LIBAUTHOR = 43
         ''')
         self.assertIsNone(ops.lib._parse_lib(m))
+        self.assertLoggedDebug("Parsing", "foo")
+        self.assertLoggedDebug("Bad type for AUTHOR: expected str, got int")
+        self.assertNotLogged("Success")
 
     def test_other_encoding(self):
         """Check that we don't crash when a library is not UTF-8"""
@@ -320,6 +357,9 @@ class TestLibParser(TestCase):
             LIBANANA = "Ñoño"
             '''))
         self.assertIsNone(ops.lib._parse_lib(m))
+        self.assertLoggedDebug("Parsing", "foo")
+        self.assertLoggedDebug("Failed", "can't decode")
+        self.assertNotLogged("Success")
 
 
 class TestLib(TestCase):