Start on a syslog()-based logging system

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

9 files changed, 90 insertions, 15 deletions

diff --git a/scripts/biz-certs/Bob-CA.srl b/scripts/biz-certs/Bob-CA.srl
index 65a08007..7ef55b1e 100644
--- a/scripts/biz-certs/Bob-CA.srl
+++ b/scripts/biz-certs/Bob-CA.srl
@@ -1 +1 @@
-90801F1ED1945520
+90801F1ED1945526
diff --git a/scripts/irbe-cli.py b/scripts/irbe-cli.py
index 0c3fce1c..63935162 100755
--- a/scripts/irbe-cli.py
+++ b/scripts/irbe-cli.py
@@ -7,7 +7,7 @@ The query back-channel is handled by a separate program.
 """
 
 import getopt, sys, lxml.etree, lxml.sax
-import rpki.left_right, rpki.relaxng, rpki.cms, rpki.https, rpki.x509, rpki.config
+import rpki.left_right, rpki.relaxng, rpki.cms, rpki.https, rpki.x509, rpki.config, rpki.log
 
 pem_out = None
 
@@ -116,6 +116,8 @@ def usage(code=1):
 
 # Main program
 
+rpki.log.init("irbe-cli")
+
 cfg = rpki.config.parser("irbe.conf")
 cfg_section = "irbe-cli"
 
diff --git a/scripts/irbe-setup.py b/scripts/irbe-setup.py
index 49ec32eb..71023b5f 100644
--- a/scripts/irbe-setup.py
+++ b/scripts/irbe-setup.py
@@ -6,7 +6,10 @@ engine for every registrant object in the IRDB.
 """
 
 import os, MySQLdb, getopt, sys, lxml.etree, lxml.sax
-import rpki.left_right, rpki.relaxng, rpki.cms, rpki.https, rpki.x509, rpki.config
+import rpki.left_right, rpki.relaxng, rpki.cms, rpki.https
+import rpki.x509, rpki.config, rpki.log
+
+rpki.log.init("irbe-setup")
 
 cfg = rpki.config.parser("irbe.conf")
 
@@ -24,9 +27,8 @@ https_tas   = rpki.x509.X509_chain(Auto_files = cfg.multiget("irbe-cli", "https-
 https_url   = cfg.get(                                       "irbe-cli", "https-url")
 
 def call_rpkid(pdu):
-  """Hand a PDU to rpkid and get back the response.  Should be able to
-  steal most of this code from irbe-cli.  Just throw an exception if
-  anything bad happens, no fancy error handling.
+  """Hand a PDU to rpkid and get back the response.  Just throw an
+  exception if anything bad happens, no fancy error handling.
   """
 
   pdu.type = "query"
diff --git a/scripts/irdb.py b/scripts/irdb.py
index 101f3f4e..c8c32e6a 100755
--- a/scripts/irdb.py
+++ b/scripts/irdb.py
@@ -1,7 +1,8 @@
 # $Id$
 
 import tlslite.api, MySQLdb, urlparse, traceback, lxml.etree
-import rpki.https, rpki.config, rpki.resource_set, rpki.cms, rpki.relaxng, rpki.exceptions, rpki.left_right
+import rpki.https, rpki.config, rpki.resource_set, rpki.cms, rpki.relaxng
+import rpki.exceptions, rpki.left_right, rpki.log
 
 def handler(query, path):
   try:
@@ -43,6 +44,8 @@ def handler(query, path):
     traceback.print_exc()
     return 500, "Unhandled exception %s" % data
 
+rpki.log.init("irdb")
+
 cfg = rpki.config.parser("irbe.conf")
 cfg_section = "irdb"
 
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]))
diff --git a/scripts/rpkid.py b/scripts/rpkid.py
index d12fc5bf..0c0f8788 100755
--- a/scripts/rpkid.py
+++ b/scripts/rpkid.py
@@ -10,10 +10,11 @@ Default configuration file is rpkid.conf, override with --config option.
 
 import traceback, os, time, getopt, sys, MySQLdb, lxml.etree
 import rpki.resource_set, rpki.up_down, rpki.left_right, rpki.x509
-import rpki.https, rpki.config, rpki.cms, rpki.exceptions, rpki.relaxng
+import rpki.https, rpki.config, rpki.cms, rpki.exceptions, rpki.relaxng, rpki.log
 
 def left_right_handler(query, path):
   """Process one left-right PDU."""
+  rpki.log.trace()
   try:
     q_elt = rpki.cms.xml_verify(query, gctx.cms_ta_irbe)
     rpki.relaxng.left_right.assertValid(q_elt)
@@ -34,6 +35,7 @@ def left_right_handler(query, path):
 
 def up_down_handler(query, path):
   """Process one up-down PDU."""
+  rpki.log.trace()
   try:
     child_id = path.partition("/up-down/")[2]
     if not child_id.isdigit():
@@ -52,6 +54,7 @@ def cronjob_handler(query, path):
   this up into separate handlers later.
   """
 
+  rpki.log.trace()
   for s in rpki.left_right.self_elt.sql_fetch_all(gctx):
     s.client_poll(gctx)
     s.update_children(gctx)
@@ -87,6 +90,8 @@ class global_context(object):
 os.environ["TZ"] = "UTC"
 time.tzset()
 
+rpki.log.init("rpkid")
+
 cfg_file = "rpkid.conf"
 
 opts,argv = getopt.getopt(sys.argv[1:], "c:h?", ["config=", "help"])
diff --git a/scripts/testroot.py b/scripts/testroot.py
index 3efd1c77..5d9d5496 100755
--- a/scripts/testroot.py
+++ b/scripts/testroot.py
@@ -13,7 +13,7 @@ Default configuration file is testroot.conf, override with --config option.
 import traceback, os, time, getopt, sys, lxml
 import rpki.resource_set, rpki.up_down, rpki.left_right, rpki.x509
 import rpki.https, rpki.config, rpki.cms, rpki.exceptions, rpki.relaxng
-import rpki.sundial
+import rpki.sundial, rpki.log
 
 root_name = "wombat"
 root_base = "rsync://" + root_name + ".invalid/"
@@ -140,6 +140,8 @@ def up_down_handler(query, path):
 os.environ["TZ"] = "UTC"
 time.tzset()
 
+rpki.log.init("testroot")
+
 cfg_file = "testroot.conf"
 
 opts,argv = getopt.getopt(sys.argv[1:], "c:h?", ["config=", "help"])