Start on a syslog()-based logging system

svn path=/scripts/biz-certs/Bob-CA.srl; revision=1377

3 files changed, 67 insertions, 6 deletions

diff --git a/scripts/rpki/https.py b/scripts/rpki/https.py
index 38cdea2c..38c4a116 100644
--- a/scripts/rpki/https.py
+++ b/scripts/rpki/https.py
@@ -8,7 +8,7 @@ general version should use SQL anyway.
 """
 
 import httplib, BaseHTTPServer, tlslite.api, glob, traceback, urlparse, socket
-import rpki.x509, rpki.exceptions
+import rpki.x509, rpki.exceptions, rpki.log
 
 rpki_content_type = "application/x-rpki"
 
@@ -51,7 +51,7 @@ def client(msg, privateKey, certChain, x509TrustList, url, timeout = 300):
           "HTTP request failed with status %s, response %s" % (response.status, r)
 
 class requestHandler(BaseHTTPServer.BaseHTTPRequestHandler):
-  """Derived type to supply POST handler."""
+  """Derived type to supply POST handler and override logging."""
 
   rpki_handlers = None                  # Subclass must bind
 
@@ -82,6 +82,13 @@ class requestHandler(BaseHTTPServer.BaseHTTPRequestHandler):
     self.end_headers()
     self.wfile.write(rtext)
 
+  def log_message(self, format, *args):
+    """Redirect HTTP server logging into our own logging system."""
+    if args:
+      rpki.log.info(format % args)
+    else:
+      rpki.log.info(format)
+
 class httpServer(tlslite.api.TLSSocketServerMixIn, BaseHTTPServer.HTTPServer):
   """Derived type to handle TLS aspects of HTTPS."""
 
@@ -104,7 +111,7 @@ class httpServer(tlslite.api.TLSSocketServerMixIn, BaseHTTPServer.HTTPServer):
       tlsConnection.ignoreAbruptClose = True
       return True
     except tlslite.api.TLSError, error:
-      print "TLS handshake failure:", str(error)
+      rpki.log.warn("TLS handshake failure: " + str(error))
       return False
 
 def server(handlers, privateKey, certChain, port = 4433, host = ""):
diff --git a/scripts/rpki/left_right.py b/scripts/rpki/left_right.py
index eeead168..89e5fcf3 100644
--- a/scripts/rpki/left_right.py
+++ b/scripts/rpki/left_right.py
@@ -4,7 +4,7 @@
 
 import base64, lxml.etree, time, traceback, os
 import rpki.sax_utils, rpki.resource_set, rpki.x509, rpki.sql, rpki.exceptions
-import rpki.https, rpki.up_down, rpki.relaxng, rpki.sundial
+import rpki.https, rpki.up_down, rpki.relaxng, rpki.sundial, rpki.log
 
 xmlns = "http://www.hactrn.net/uris/rpki/left-right-spec/"
 
@@ -315,6 +315,8 @@ class self_elt(data_elt):
   def client_poll(self, gctx):
     """Run the regular client poll cycle with each of this self's parents in turn."""
 
+    rpki.log.trace()
+
     for parent in self.parents(gctx):
 
       # This will need a callback when we go event-driven
@@ -338,6 +340,8 @@ class self_elt(data_elt):
     resources and in expiration date.
     """
 
+    rpki.log.trace()
+
     now = rpki.sundial.datetime.utcnow()
 
     for child in self.children(gctx):
@@ -375,6 +379,8 @@ class self_elt(data_elt):
     new manifest whenever we generate a new CRL
     """
 
+    rpki.log.trace()
+
     now = rpki.sundial.datetime.utcnow()
     for parent in self.parents(gctx):
       repository = parent.repository(gctx)
@@ -577,6 +583,9 @@ class parent_elt(data_elt):
 
     For now, keep this dead simple lock step, rewrite it later.
     """
+
+    rpki.log.trace()
+
     bsc = self.bsc(gctx)
     if bsc is None:
       raise rpki.exceptions.BSCNotFound, "Could not find BSC %s" % self.bsc_id
@@ -661,6 +670,9 @@ class child_elt(data_elt):
 
   def serve_up_down(self, gctx, query):
     """Outer layer of server handling for one up-down PDU from this child."""
+
+    rpki.log.trace()
+
     bsc = self.bsc(gctx)
     if bsc is None:
       raise rpki.exceptions.BSCNotFound, "Could not find BSC %s" % self.bsc_id
@@ -744,6 +756,7 @@ class repository_elt(data_elt):
   @classmethod
   def object_write(cls, base, uri, obj):
     """Write an object to disk. [TEMPORARY]"""
+    rpki.log.trace()
     filename = cls.uri_to_filename(base, uri)
     dirname = os.path.dirname(filename)
     if not os.path.isdir(dirname):
@@ -755,18 +768,21 @@ class repository_elt(data_elt):
   @classmethod
   def object_delete(cls, base, uri):
     """Delete an object from disk. [TEMPORARY]"""
+    rpki.log.trace()
     os.remove(cls.uri_to_filename(base, uri))
 
   def publish(self, gctx, *things):
     """Placeholder for publication operation. [TEMPORARY]"""
+    rpki.log.trace()
     for obj, uri in things:
-      print "Pretending to publish %s to repository %s at %s" % (repr(obj), repr(self), repr(uri))
+      rpki.log.info("Pretending to publish %s to repository %s at %s" % (repr(obj), repr(self), repr(uri)))
       self.object_write(gctx.publication_kludge_base, uri, obj)
 
   def withdraw(self, gctx, *things):
     """Placeholder for publication withdrawal operation. [TEMPORARY]"""
+    rpki.log.trace()
     for obj, uri in things:
-      print "Pretending to withdraw %s from repository %s at %s" % (repr(obj), repr(self), repr(uri))
+      rpki.log.info("Pretending to withdraw %s from repository %s at %s" % (repr(obj), repr(self), repr(uri)))
       self.object_delete(gctx.publication_kludge_base, uri)
 
 class route_origin_elt(data_elt):
@@ -944,6 +960,8 @@ def irdb_query(gctx, self_id, child_id = None):
   that this function will need to become.
   """
 
+  rpki.log.trace()
+
   q_msg = msg()
   q_msg.append(list_resources_elt())
   q_msg[0].type = "query"
diff --git a/scripts/rpki/log.py b/scripts/rpki/log.py
new file mode 100644
index 00000000..f8a0844b
--- /dev/null
+++ b/scripts/rpki/log.py
@@ -0,0 +1,36 @@
+# $Id$
+
+"""Logging facilities for RPKI libraries.
+"""
+
+import syslog, traceback
+
+def init(ident = "rpki"):
+  """Initialize logging system."""
+  return syslog.openlog(ident, syslog.LOG_PID | syslog.LOG_PERROR, syslog.LOG_DAEMON)
+
+class logger(object):
+  """Closure for logging."""
+
+  def __init__(self, priority):
+    self.set_priority(priority)
+
+  def set_priority(self, priority):
+    self.priority = priority
+
+  def __call__(self, message):
+    return syslog.syslog(self.priority, message)
+
+error   = logger(syslog.LOG_ERR)
+warning = logger(syslog.LOG_WARNING)
+notice  = logger(syslog.LOG_NOTICE)
+info    = logger(syslog.LOG_INFO)
+debug   = logger(syslog.LOG_DEBUG)
+
+enable_trace = True
+
+def trace():
+  """Execution trace -- where are we now, and whence came we here?"""
+  if enable_trace:
+    bt = traceback.extract_stack(limit = 3)
+    return debug("[%s() at %s:%d from %s:%d]" % (bt[1][2], bt[1][0], bt[1][1], bt[0][0], bt[0][1]))