CP-29955: Log failures in key lookup plugins

- Previously we did not log anything in the plugin manager when key
  lookup plugins were invoked or when they failed with an exception.  So
  now I have added debug logs to the plugin manager that are written to
  SMlog.
- Fixed how modules in the plugins directory are loaded. To avoid
  loading itself, the plugin manager compared each filename in its
  directory to the __file__ variable. However, sometimes this variable
  was __init__.pyc, not __init__.py, so the comparison returned false,
  and the key manager loaded itself recursively, which in turn tried to
  load the plugins again, but failed.
- I've also removed some pylint warnings: I've converted the Logger
  class into a function, fixed indentation, and removed trailing
  whitespace.

Signed-off-by: Gabor Igloi <gabor.igloi@citrix.com>

drivers/plugins/__init__.py

@@ -1,32 +1,54 @@
 import glob
 import importlib
+import logging
+import logging.handlers
 import os
 import re
 import sys
+import traceback
+
+import util
 
 plugindir = os.path.dirname(__file__)
 
 plugins = []
 
+def _log_exn_backtrace():
+    for line in traceback.format_exc().splitlines():
+        util.SMlog(line)
+
 for file_name in glob.glob(os.path.join(plugindir, '*.py')):
-    if file_name == __file__:
+    # Avoid recursively loading this module again. The __file__ variable might
+    # have a .pyc extension, so we have to compare the filenames without
+    # extension:
+    if os.path.splitext(file_name)[0] == os.path.splitext(__file__)[0]:
         continue
     module_name = os.path.splitext(os.path.split(file_name)[-1])[0]
     try:
         module = importlib.import_module('{}.{}'.format(__name__, module_name))
         plugins.append(module)
+        util.SMlog('Loaded key lookup plugin {}'.format(module_name))
     except:
-        # ignore module import errors
-        pass
+        # ignore and log module import errors
+        util.SMlog('Failed to load key lookup plugin {}'.format(module_name))
+        _log_exn_backtrace()
 
 def load_key(key_hash, vdi_uuid):
     for plugin in plugins:
         try:
             key = plugin.load_key(key_hash, vdi_uuid)
             if key:
+                util.SMlog('Loaded key with hash {} for VDI {} using plugin {}'.format(
+                    key_hash, vdi_uuid, plugin.__name__))
                 return key
+            else:
+                util.SMlog('Plugin {} did not return a key for key hash {} and VDI {}'.format(
+                    plugin.__name__, key_hash, vdi_uuid))
         except:
-            # ignore plugin failures
-            pass
+            # ignore and log plugin failures
+            util.SMlog('Key lookup plugin {} failed while loading key'
+                       ' with hash {} for VDI {}'.format(
+                           plugin.__name__, key_hash, vdi_uuid))
+            _log_exn_backtrace()
 
     return None

drivers/plugins/keymanagerutil.py

@@ -15,25 +15,27 @@
 import json
 import argparse
 import string
-from random import SystemRandom 
+from random import SystemRandom
 
 import XenAPI
 
+PROGRAM_NAME = 'keymanagerutil'
+
 def load_key(key_hash, vdi_uuid):
     """
     load_key is called by SM plugin when it needs to find the key for
     specified key_hash from the key store
     """
+    _check_key(key_hash, vdi_uuid)
     try:
-        check_key(key_hash, vdi_uuid)
         key = KeyManager(key_hash=key_hash).get_key(log_key_info=False)
         return key
-    except Exception:
+    except KeyLookUpError:
         return None
 
-def check_key(key_hash, vdi_uuid):
+def _check_key(key_hash, vdi_uuid):
     session = XenAPI.xapi_local()
-    session.xenapi.login_with_password('root', '', '', 'keymanagerutil')
+    session.xenapi.login_with_password('root', '', '', PROGRAM_NAME)
     try:
         vdi = session.xenapi.VDI.get_by_uuid(vdi_uuid)
         sm_config = session.xenapi.VDI.get_sm_config(vdi)
@@ -57,26 +59,22 @@ def __init__(self, message):
 
 
 class KeyLookUpError(Exception):
+    """Raised when the key / key hash we've requested is not in the keystore"""
     def __init__(self, message):
         super(KeyLookUpError, self).__init__(message)
 
 
-class Logger(object):
-    def __init__(self, key=None, key_hash=None):
-        self.key = key
-        self.key_hash = key_hash
-
-    def log_key_info(self):
-        data = {}
-        if self.key:
-            data['key_base64'] = base64.b64encode(self.key)
-        if self.key_hash:
-            data['key_hash'] = self.key_hash
-        print(json.dumps(data))
-
-    def log_message(self, message):
-        print(message)
-
+def _print_key_info(key=None, key_hash=None):
+    """
+    Output the key details as JSON to the standard output. This output
+    will be interpreted by XenRT.
+    """
+    data = {}
+    if key:
+        data['key_base64'] = base64.b64encode(key)
+    if key_hash:
+        data['key_hash'] = key_hash
+    print(json.dumps(data))
 
 KEYSTORE_PATH = '/tmp/keystore.json'
 
@@ -155,8 +153,7 @@ def generate(self):
         """
         self.key = _get_key_generator(key_length=self.key_length, key_type=self.key_type).generate()
         self.key_hash = self.__hash_key()
-        logger = Logger(self.key, self.key_hash)
-        logger.log_key_info()
+        _print_key_info(key=self.key, key_hash=self.key_hash)
         self.__add_to_keystore()
 
     def get_key(self, log_key_info=True):
@@ -167,8 +164,7 @@ def get_key(self, log_key_info=True):
         key_store = _read_keystore()
         key = key_store.get(self.key_hash, None)
         if key and log_key_info:
-            logger = Logger(key=key)
-            logger.log_key_info()
+            _print_key_info(key=key)
         if not key:
             raise KeyLookUpError("No keys in the keystore which matches the given key hash")
 
@@ -181,8 +177,7 @@ def get_keyhash(self):
         key_store = _read_keystore()
         try:
             key_hash = key_store.keys()[key_store.values().index(self.key)]
-            logger = Logger(key_hash=key_hash)
-            logger.log_key_info()
+            _print_key_info(key_hash=key_hash)
         except ValueError:
             raise KeyLookUpError("No key hash in the keystore which matches the given key")