Allow logging hookpoint intialization

The hook points are applied prior to any logging configuration. This
makes it difficult for a hook author to ensure that the correct
configuration and package entry points have been added. This patch takes
the log messages and buffers them for replay after the logging has been
configure. The replay function is then called in each of the commands
after the configuration has been read.

Closes-Bug: #1465731
Change-Id: Ia5cc2dba53056c55017b3a104a1f4e22e6594ae0

designate/cmd/agent.py

@@ -18,6 +18,7 @@ import sys
 from oslo_config import cfg
 from oslo_log import log as logging
 
+from designate import hookpoints
 from designate import service
 from designate import utils
 from designate.agent import service as agent_service
@@ -33,6 +34,8 @@ def main():
     logging.setup(CONF, 'designate')
     utils.setup_gmr(log_dir=cfg.CONF.log_dir)
 
+    hookpoints.log_hook_setup()
+
     server = agent_service.Service(threads=CONF['service:agent'].threads)
     service.serve(server, workers=CONF['service:agent'].workers)
     service.wait()

designate/cmd/api.py

@@ -19,6 +19,7 @@ from oslo_config import cfg
 from oslo_log import log as logging
 from oslo_service import service
 
+from designate import hookpoints
 from designate import utils
 from designate.api import service as api_service
 
@@ -33,6 +34,8 @@ def main():
     logging.setup(CONF, 'designate')
     utils.setup_gmr(log_dir=cfg.CONF.log_dir)
 
+    hookpoints.log_hook_setup()
+
     server = api_service.Service(threads=CONF['service:api'].threads)
     launcher = service.launch(CONF, server, CONF['service:api'].workers)
     launcher.wait()

designate/cmd/central.py

@@ -18,6 +18,7 @@ import sys
 from oslo_config import cfg
 from oslo_log import log as logging
 
+from designate import hookpoints
 from designate import service
 from designate import utils
 from designate.central import service as central
@@ -33,6 +34,8 @@ def main():
     logging.setup(CONF, 'designate')
     utils.setup_gmr(log_dir=cfg.CONF.log_dir)
 
+    hookpoints.log_hook_setup()
+
     server = central.Service(threads=CONF['service:central'].threads)
     service.serve(server, workers=CONF['service:central'].workers)
     service.wait()

designate/cmd/manage.py

@@ -23,6 +23,7 @@ from oslo_config import cfg
 from oslo_log import log as logging
 from stevedore.extension import ExtensionManager
 
+from designate import hookpoints
 from designate import utils
 from designate.i18n import _
 
@@ -120,6 +121,9 @@ def main():
         sys.exit(2)
 
     utils.setup_gmr(log_dir=cfg.CONF.log_dir)
+
+    hookpoints.log_hook_setup()
+
     fn = CONF.category.action_fn
 
     fn_args = fetch_func_args(fn)

designate/cmd/mdns.py

@@ -18,6 +18,7 @@ import sys
 from oslo_config import cfg
 from oslo_log import log as logging
 
+from designate import hookpoints
 from designate import service
 from designate import utils
 from designate.mdns import service as mdns_service
@@ -33,6 +34,8 @@ def main():
     logging.setup(CONF, 'designate')
     utils.setup_gmr(log_dir=cfg.CONF.log_dir)
 
+    hookpoints.log_hook_setup()
+
     server = mdns_service.Service(threads=CONF['service:mdns'].threads)
     service.serve(server, workers=CONF['service:mdns'].workers)
     service.wait()

designate/cmd/pool_manager.py

@@ -20,6 +20,7 @@ from oslo_log import log as logging
 
 from designate import service
 from designate import utils
+from designate import hookpoints
 from designate.pool_manager import service as pool_manager_service
 
 
@@ -32,10 +33,16 @@ CONF.import_opt('threads', 'designate.pool_manager',
 
 def main():
     utils.read_config('designate', sys.argv)
+
     logging.setup(CONF, 'designate')
+
     utils.setup_gmr(log_dir=cfg.CONF.log_dir)
 
     server = pool_manager_service.Service(
-        threads=CONF['service:pool_manager'].threads)
+        threads=CONF['service:pool_manager'].threads
+    )
+
+    hookpoints.log_hook_setup()
+
     service.serve(server, workers=CONF['service:pool_manager'].workers)
     service.wait()

designate/cmd/sink.py

@@ -18,6 +18,7 @@ import sys
 from oslo_config import cfg
 from oslo_log import log as logging
 
+from designate import hookpoints
 from designate import service
 from designate import utils
 from designate.sink import service as sink_service
@@ -33,6 +34,8 @@ def main():
     logging.setup(CONF, 'designate')
     utils.setup_gmr(log_dir=cfg.CONF.log_dir)
 
+    hookpoints.log_hook_setup()
+
     server = sink_service.Service(threads=CONF['service:sink'].threads)
     service.serve(server, workers=CONF['service:sink'].workers)
     service.wait()

designate/hookpoints.py

@@ -13,14 +13,56 @@
 # WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
 # License for the specific language governing permissions and limitations
 # under the License.
+import sys
 import functools
+import logging as logmodule
 
+import pkg_resources
 from oslo_config import cfg
 from oslo_log import log as logging
 from stevedore import hook
 
 
-LOG = logging.getLogger(__name__)
+class HookLog(object):
+    """Since logs are applied at import time, we record the log
+    messages for later use.
+    """
+    LVLS = dict(
+        debug=logmodule.DEBUG,
+        info=logmodule.INFO,
+        warning=logmodule.WARNING,
+        error=logmodule.ERROR,
+        critical=logmodule.CRITICAL,
+        exception=logmodule.ERROR,
+    )
+
+    def __init__(self):
+        self.messages = []
+
+    def log(self, logger=None):
+        logger = logging.getLogger(__name__)
+        for level, msg, args, kw in self.messages:
+            logger.log(level, msg, *args, **kw)
+
+    __call__ = log
+
+    def capture(self, lvl, msg, *args, **kw):
+        self.messages.append((lvl, msg, args, kw))
+
+    def __getattr__(self, name):
+        if name in self.LVLS:
+            return functools.partial(self.capture, self.LVLS[name])
+
+LOG = HookLog()
+
+
+def log_hook_setup():
+    """Replay the log messages during the hook point initialization.
+
+    Logging isn't configured when we set up the hook points, so this
+    will replay the log once the config has been loaded.
+    """
+    LOG()
 
 
 class BaseHook(object):
@@ -53,9 +95,11 @@ class BaseHook(object):
 
 class hook_point(object):
     NAMESPACE = 'designate.hook_point'
+    LOG_LEVEL = logmodule.INFO
 
     def __init__(self, name=None):
         self._name = name
+        self.log = []
 
     def update_config_opts(self, group, hooks):
         hooks_found = False
@@ -95,6 +139,7 @@ class hook_point(object):
         Try to inspect the function for a hook target path if one
         wasn't passed in and set up the necessary config options.
         """
+        LOG.debug('Initializing hook: %s', f)
         self.name = self.find_name(f)
         self.group = 'hook_point:%s' % self.name
         self.hooks = self.hook_manager(self.name)
@@ -119,3 +164,20 @@ class hook_point(object):
         for h in self.hooks:
             f = self.enable_hook(h, f)
         return f
+
+
+if __name__ == '__main__':
+    # Use this script to find existing hook points.
+    hook_names = sys.argv[1:]
+
+    print('Using namespace: %s' % hook_point.NAMESPACE)
+
+    print('pkg_resources has the following entry points:')
+    for ep in pkg_resources.iter_entry_points(hook_point.NAMESPACE):
+        print(ep)
+
+    print()
+    print('stevedore found the following hooks:')
+    for name in hook_names:
+        for hp in hook.HookManager(hook_point.NAMESPACE, name):
+            print(hp)