First cut at fully configurable logging system. Still a bit raw, and

not yet documented, but allows detailed logging configuration down to
the class level, and flexible enough to allow runtime configuration if
we decide we need that.

svn path=/trunk/; revision=5860

4 files changed, 67 insertions, 26 deletions

diff --git a/rpki/__init__.py b/rpki/__init__.py
index 9e090f63..53a32337 100644
--- a/rpki/__init__.py
+++ b/rpki/__init__.py
@@ -1,2 +1,26 @@
-# This file exists to tell Python that this the content of this
-# directory constitute a Python package.
+# $Id$
+
+# Copyright (C) 2014  Dragon Research Labs ("DRL")
+#
+# Permission to use, copy, modify, and distribute this software for any
+# purpose with or without fee is hereby granted, provided that the above
+# copyright notice and this permission notice appear in all copies.
+#
+# THE SOFTWARE IS PROVIDED "AS IS" AND DRL DISCLAIMS ALL WARRANTIES WITH
+# REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
+# AND FITNESS.  IN NO EVENT SHALL DRL BE LIABLE FOR ANY SPECIAL, DIRECT,
+# INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
+# LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE
+# OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
+# PERFORMANCE OF THIS SOFTWARE.
+
+# This file exists primarily to tell Python that this the content of
+# this directory constitute a Python package, but while we're here,
+# create a logger object that programs can use to control logging in
+# all of the rpki libraries at once.
+
+import logging
+
+logger = logging.getLogger(__name__)
+
+del logging                             # Cleanup
diff --git a/rpki/config.py b/rpki/config.py
index ad87239b..f38427c4 100644
--- a/rpki/config.py
+++ b/rpki/config.py
@@ -120,20 +120,19 @@ class parser(object):
     """
     Parse OpenSSL-style foo.0, foo.1, ... subscripted options.
 
-    Returns a list of values matching the specified option name.
+    Returns iteration of values matching the specified option name.
     """
 
     matches = []
     if section is None:
       section = self.default_section
     if self.cfg.has_option(section, option):
-      matches.append((-1, self.get(option, section = section)))
-    for key in self.cfg.options(section):
-      s = key.rsplit(".", 1)
-      if len(s) == 2 and s[0] == option and s[1].isdigit():
-        matches.append((int(s[1]), self.get(option, section = section)))
+      yield self.cfg.get(section, option)
+    option += "."
+    matches = [o for o in self.cfg.options(section) if o.startswith(option) and o[len(option):].isdigit()]
     matches.sort()
-    return [match[1] for match in matches]
+    for option in matches:
+      yield self.cfg.get(section, option)
 
   _regexp = re.compile("\\${(.*?)::(.*?)}")
 
@@ -203,10 +202,12 @@ class parser(object):
     import rpki.log
     import rpki.daemonize
 
-    try:
-      rpki.http.debug_http = self.getboolean("debug_http")
-    except ConfigParser.NoOptionError:
-      pass
+    for line in self.multiget("configure_logger"):
+      try:
+        name, level = line.split()
+        logging.getLogger(name).setLevel(getattr(logging, level.upper()))
+      except Exception, e:
+        logger.warning("Could not process configure_logger line %r: %s", line, e)
 
     try:
       rpki.http.want_persistent_client = self.getboolean("want_persistent_client")
diff --git a/rpki/http.py b/rpki/http.py
index ed9be5f4..546dd310 100644
--- a/rpki/http.py
+++ b/rpki/http.py
@@ -42,10 +42,6 @@ logger = logging.getLogger(__name__)
 # HTTP content type used for all RPKI messages.
 rpki_content_type = "application/x-rpki"
 
-## @var debug_http
-# Verbose chatter about HTTP streams.
-debug_http = False
-
 ## @var want_persistent_client
 # Whether we want persistent HTTP client streams, when server also supports them.
 want_persistent_client = False
@@ -295,11 +291,15 @@ def addr_to_string(addr):
     return "%s.%d" % (addr[0], addr[1])
   raise TypeError
 
+@rpki.log.class_logger(logger)
 class http_stream(asynchat.async_chat):
   """
   Virtual class representing an HTTP message stream.
   """
 
+  # Keep pylint happy; @class_logger overwrites this.
+  logger = None
+
   def __repr__(self):
     status = ["connected"] if self.connected else []
     try:
@@ -309,7 +309,7 @@ class http_stream(asynchat.async_chat):
     return rpki.log.log_repr(self, *status)
 
   def __init__(self, sock = None):
-    self.logger = logging.LoggerAdapter(logger, dict(context = self))
+    self.logger = logging.LoggerAdapter(self.logger, dict(context = self))
     asynchat.async_chat.__init__(self, sock)
     self.buffer = []
     self.timer = rpki.async.timer(self.handle_timeout)
@@ -471,6 +471,7 @@ class http_stream(asynchat.async_chat):
     self.timer.cancel()
     asynchat.async_chat.handle_close(self)
 
+@rpki.log.class_logger(logger)
 class http_server(http_stream):
   """
   HTTP server stream.
@@ -570,6 +571,7 @@ class http_server(http_stream):
       self.logger.debug("Listening for next message")
       self.restart()
 
+@rpki.log.class_logger(logger)
 class http_listener(asyncore.dispatcher):
   """
   Listener for incoming HTTP connections.
@@ -583,7 +585,7 @@ class http_listener(asyncore.dispatcher):
     return rpki.log.log_repr(self, *status)
 
   def __init__(self, handlers, addrinfo):
-    self.logger = logging.LoggerAdapter(logger, dict(context = self))
+    self.logger = logging.LoggerAdapter(self.logger, dict(context = self))
     asyncore.dispatcher.__init__(self)
     self.handlers = handlers
     try:
@@ -629,6 +631,7 @@ class http_listener(asyncore.dispatcher):
       raise
     self.logger.exception("Error in HTTP listener")
 
+@rpki.log.class_logger(logger)
 class http_client(http_stream):
   """
   HTTP client stream.
@@ -815,6 +818,7 @@ class http_client(http_stream):
     http_stream.handle_error(self)
     self.queue.return_result(self, edata, detach = True)
 
+@rpki.log.class_logger(logger)
 class http_queue(object):
   """
   Queue of pending HTTP requests for a single destination.  This class
@@ -826,7 +830,7 @@ class http_queue(object):
     return rpki.log.log_repr(self, addr_to_string(self.hostport))
 
   def __init__(self, hostport):
-    self.logger = logging.LoggerAdapter(logger, dict(context = self))
+    self.logger = logging.LoggerAdapter(self.logger, dict(context = self))
     self.hostport = hostport
     self.client = None
     self.logger.debug("Created")
@@ -948,8 +952,7 @@ def client(msg, url, callback, errback):
       u.fragment != ""):
     raise rpki.exceptions.BadClientURL("Unusable URL %s" % url)
 
-  if debug_http:
-    logger.debug("Contacting %s", url)
+  logger.debug("Contacting %s", url)
 
   request = http_request(
     cmd                 = "POST",
@@ -962,8 +965,7 @@ def client(msg, url, callback, errback):
 
   hostport = (u.hostname or "localhost", u.port or default_tcp_port)
 
-  if debug_http:
-    logger.debug("Created request %r for %s", request, addr_to_string(hostport))
+  logger.debug("Created request %r for %s", request, addr_to_string(hostport))
   if hostport not in client_queues:
     client_queues[hostport] = http_queue(hostport)
   client_queues[hostport].request(request)
@@ -971,8 +973,7 @@ def client(msg, url, callback, errback):
   # Defer connection attempt until after we've had time to process any
   # pending I/O events, in case connections have closed.
 
-  if debug_http:
-    logger.debug("Scheduling connection startup for %r", request)
+  logger.debug("Scheduling connection startup for %r", request)
   rpki.async.event_defer(client_queues[hostport].restart)
 
 def server(handlers, port, host = ""):
diff --git a/rpki/log.py b/rpki/log.py
index 32ded80f..2abb3b2c 100644
--- a/rpki/log.py
+++ b/rpki/log.py
@@ -219,6 +219,21 @@ def init(ident = None, args = None):
       setproctitle.setproctitle(ident)
 
 
+def class_logger(module_logger, attribute = "logger"):
+  """
+  Class decorator to add a class-level Logger object as a class
+  attribute.  This allows control of debugging messages at the class
+  level rather than just the module level.
+
+  This decorator takes the module logger as an argument.
+  """
+
+  def decorator(cls):
+    setattr(cls, attribute, module_logger.getChild(cls.__name__))
+    return cls
+  return decorator
+
+
 def log_repr(obj, *tokens):
   """
   Constructor for __repr__() strings, handles suppression of Python