Clean up and consolidate traceback. Add methods to hide (some of the)

mucking about with msg.type variables.  Include query PDU tags in
reply <report_error/> PDUs.

svn path=/rpkid/irbe-setup.py; revision=2571

14 files changed, 82 insertions, 66 deletions

diff --git a/rpkid/irbe-setup.py b/rpkid/irbe-setup.py
index 765cdd42..a7e8c441 100644
--- a/rpkid/irbe-setup.py
+++ b/rpkid/irbe-setup.py
@@ -51,8 +51,7 @@ def call_rpkid(pdu):
   exception if anything bad happens, no fancy error handling.
   """
 
-  msg = rpki.left_right.msg((pdu,))
-  msg.type = "query"
+  msg = rpki.left_right.msg.query((pdu,))
   cms = rpki.left_right.cms_msg.wrap(msg, irbe_key, irbe_cert)
   der = rpki.https.client(client_key   = irbe_key,
                           client_cert  = irbe_cert,
diff --git a/rpkid/irbe_cli.py b/rpkid/irbe_cli.py
index 578fecd8..d3078a79 100755
--- a/rpkid/irbe_cli.py
+++ b/rpkid/irbe_cli.py
@@ -282,11 +282,8 @@ if not argv:
 
 cfg = rpki.config.parser(cfg_file, "irbe_cli")
 
-q_msg_left_right = left_right_msg()
-q_msg_left_right.type = "query"
-
-q_msg_publication = publication_msg()
-q_msg_publication.type = "query"
+q_msg_left_right  = left_right_msg.query()
+q_msg_publication = publication_msg.query()
 
 while argv:
   if argv[0] in left_right_msg.pdus:
diff --git a/rpkid/irdbd.py b/rpkid/irdbd.py
index 346485dc..584e7454 100755
--- a/rpkid/irdbd.py
+++ b/rpkid/irdbd.py
@@ -36,7 +36,7 @@ OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 PERFORMANCE OF THIS SOFTWARE.
 """
 
-import sys, os, time, getopt, urlparse, traceback, MySQLdb
+import sys, os, time, getopt, urlparse, MySQLdb
 import rpki.https, rpki.config, rpki.resource_set, rpki.relaxng
 import rpki.exceptions, rpki.left_right, rpki.log, rpki.x509
 
@@ -116,8 +116,7 @@ def handler(query, path, cb):
     if not isinstance(q_msg, rpki.left_right.msg) or q_msg.type != "query":
       raise rpki.exceptions.BadQuery, "Unexpected %s PDU" % repr(q_msg)
 
-    r_msg = rpki.left_right.msg()
-    r_msg.type = "reply"
+    r_msg = rpki.left_right.msg.reply()
 
     for q_pdu in q_msg:
 
@@ -128,8 +127,8 @@ def handler(query, path, cb):
           raise rpki.exceptions.BadQuery, "Unexpected %s PDU" % repr(q_pdu)
 
       except Exception, data:
-        rpki.log.error(traceback.format_exc())
-        r_msg.append(rpki.left_right.report_error_elt.from_exception(data, q_pdu.self_handle))
+        rpki.log.traceback()
+        r_msg.append(rpki.left_right.report_error_elt.from_exception(data, q_pdu.self_handle, q_pdu.tag))
 
     cb(200, rpki.left_right.cms_msg.wrap(r_msg, irdbd_key, irdbd_cert))
 
@@ -137,7 +136,7 @@ def handler(query, path, cb):
     raise
 
   except Exception, data:
-    rpki.log.error(traceback.format_exc())
+    rpki.log.traceback()
 
     # We only get here in cases where we couldn't or wouldn't generate
     # <report_error/>, so just return HTTP failure.
diff --git a/rpkid/pubd.py b/rpkid/pubd.py
index 33261737..4af6b55a 100755
--- a/rpkid/pubd.py
+++ b/rpkid/pubd.py
@@ -38,7 +38,7 @@ OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 PERFORMANCE OF THIS SOFTWARE.
 """
 
-import traceback, os, time, getopt, sys, re
+import os, time, getopt, sys, re
 import rpki.resource_set, rpki.up_down, rpki.left_right, rpki.x509, rpki.sql
 import rpki.https, rpki.config, rpki.exceptions, rpki.relaxng, rpki.log
 import rpki.publication
@@ -90,7 +90,7 @@ class pubd_context(object):
     except (rpki.async.ExitNow, SystemExit):
       raise
     except Exception, data:
-      rpki.log.error(traceback.format_exc())
+      rpki.log.traceback()
       cb(500, "Unhandled exception %s" % data)
 
   client_url_regexp = re.compile("/client/([-A-Z0-9_]+)$", re.I)
@@ -120,7 +120,7 @@ class pubd_context(object):
     except (rpki.async.ExitNow, SystemExit):
       raise
     except Exception, data:
-      rpki.log.error(traceback.format_exc())
+      rpki.log.traceback()
       cb(500, "Could not process PDU: %s" % data)
 
   ## @var https_ta_cache
diff --git a/rpkid/rootd.py b/rpkid/rootd.py
index aa2e7c2a..6479b70a 100755
--- a/rpkid/rootd.py
+++ b/rpkid/rootd.py
@@ -38,7 +38,7 @@ OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 PERFORMANCE OF THIS SOFTWARE.
 """
 
-import traceback, os, time, getopt, sys
+import os, time, getopt, sys
 import rpki.resource_set, rpki.up_down, rpki.left_right, rpki.x509
 import rpki.https, rpki.config, rpki.exceptions, rpki.relaxng
 import rpki.sundial, rpki.log
@@ -205,7 +205,7 @@ def up_down_handler(query, path, cb):
   except (rpki.async.ExitNow, SystemExit):
     raise
   except Exception, data:
-    rpki.log.error(traceback.format_exc())
+    rpki.log.traceback()
     return cb(400, "Could not process PDU: %s" % data)
 
   def done(r_msg):
@@ -217,13 +217,13 @@ def up_down_handler(query, path, cb):
   except (rpki.async.ExitNow, SystemExit):
     raise
   except Exception, data:
-    rpki.log.error(traceback.format_exc())
+    rpki.log.traceback()
     try:
       done(q_msg.serve_error(data))
     except (rpki.async.ExitNow, SystemExit):
       raise
     except Exception, data:
-      rpki.log.error(traceback.format_exc())
+      rpki.log.traceback()
       cb(500, "Could not process PDU: %s" % data)
 
 os.environ["TZ"] = "UTC"
diff --git a/rpkid/rpki/async.py b/rpkid/rpki/async.py
index 18ed2a2e..a3847823 100644
--- a/rpkid/rpki/async.py
+++ b/rpkid/rpki/async.py
@@ -156,7 +156,7 @@ class timer(object):
     Error callback.  May be overridden, or set with set_errback().
     """
     rpki.log.error("Unhandled exception from timer: %s" % e)
-    rpki.log.error(traceback.format_exc())
+    rpki.log.traceback()
 
   def set_errback(self, errback):
     """Set a timer's errback.  Like set_handler(), for errbacks."""
diff --git a/rpkid/rpki/https.py b/rpkid/rpki/https.py
index 3b1a609c..e27c353b 100644
--- a/rpkid/rpki/https.py
+++ b/rpkid/rpki/https.py
@@ -36,7 +36,7 @@ OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 PERFORMANCE OF THIS SOFTWARE.
 """
 
-import time, socket, asyncore, asynchat, traceback, urlparse, sys
+import time, socket, asyncore, asynchat, urlparse, sys
 import rpki.async, rpki.sundial, rpki.x509, rpki.exceptions, rpki.log
 import POW
 
@@ -270,7 +270,7 @@ class http_stream(asynchat.async_chat):
       raise
     else:
       self.log("Error in HTTP stream handler")
-      print traceback.format_exc()
+      rpki.log.traceback()
       self.log("Closing due to error")
       self.close()
 
@@ -427,7 +427,7 @@ class http_server(http_stream):
       except (rpki.async.ExitNow, SystemExit):
         raise
       except Exception, edata:
-        print traceback.format_exc()
+        rpki.log.traceback()
         self.send_error(500, "Unhandled exception %s" % edata)
     else:
       self.send_error(code = error[0], reason = error[1])
@@ -491,7 +491,7 @@ class http_listener(asyncore.dispatcher):
       raise
     else:
       self.log("Error in HTTP listener")
-      print traceback.format_exc()
+      rpki.log.traceback()
 
 class http_client(http_stream):
 
@@ -673,7 +673,7 @@ class http_queue(object):
       raise
     except:
       self.log("Unhandled exception from callback")
-      rpki.log.error(traceback.format_exc())
+      rpki.log.traceback()
 
     self.log("Queue: %r" % self.queue)
 
diff --git a/rpkid/rpki/left_right.py b/rpkid/rpki/left_right.py
index 95073151..47454b1c 100644
--- a/rpkid/rpki/left_right.py
+++ b/rpkid/rpki/left_right.py
@@ -32,7 +32,6 @@ OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 PERFORMANCE OF THIS SOFTWARE.
 """
 
-import traceback
 import rpki.resource_set, rpki.x509, rpki.sql, rpki.exceptions, rpki.xml_utils
 import rpki.https, rpki.up_down, rpki.relaxng, rpki.sundial, rpki.log, rpki.roa
 import rpki.publication, rpki.async
@@ -229,12 +228,12 @@ class self_elt(data_elt):
         def class_loop(class_iterator, rc):
 
           def class_update_failed(e):
-            rpki.log.error(traceback.format_exc())
+            rpki.log.traceback()
             rpki.log.warn("Couldn't update class, skipping: %s" % e)
             class_iterator()
 
           def class_create_failed(e):
-            rpki.log.error(traceback.format_exc())
+            rpki.log.traceback()
             rpki.log.warn("Couldn't create class, skipping: %s" % e)
             class_iterator()
 
@@ -259,7 +258,7 @@ class self_elt(data_elt):
         rpki.async.iterator(r_msg.payload.classes, class_loop, class_done)
 
       def list_failed(e):
-        rpki.log.error(traceback.format_exc())
+        rpki.log.traceback()
         rpki.log.warn("Couldn't get resource class list from parent %r, skipping: %s" % (parent, e))
 
       rpki.up_down.list_pdu.query(parent, got_list, list_failed)
@@ -295,7 +294,7 @@ class self_elt(data_elt):
               rpki.log.debug("Need to reissue child certificate SKI %s" % child_cert.cert.gSKI())
 
               def reissue_failed(e):
-                rpki.log.error(traceback.format_exc())
+                rpki.log.traceback()
                 rpki.log.warn("Couldn't reissue child_cert %r, skipping: %s" % (child_cert, e))
                 iterator2()
 
@@ -318,12 +317,12 @@ class self_elt(data_elt):
                 repository.withdraw(child_cert.cert, child_cert.uri(ca), iterator2, withdraw_failed)
 
               def manifest_failed(e):
-                rpki.log.error(traceback.format_exc())
+                rpki.log.traceback()
                 rpki.log.warn("Couldn't reissue manifest for %r, skipping: %s" % (ca_detail, e))
                 iterator2()
 
               def withdraw_failed(e):
-                rpki.log.error(traceback.format_exc())
+                rpki.log.traceback()
                 rpki.log.warn("Couldn't withdraw old child_cert %r, skipping: %s" % (child_cert, e))
                 iterator2()
 
@@ -335,7 +334,7 @@ class self_elt(data_elt):
         rpki.async.iterator(child_certs, loop2, iterator1)
 
       def irdb_lookup_failed(e):
-        rpki.log.error(traceback.format_exc())
+        rpki.log.traceback()
         rpki.log.warn("Couldn't look up child's resources in IRDB, skipping child %r: %s" % (child, e))
         iterator1()
 
@@ -370,7 +369,7 @@ class self_elt(data_elt):
       def loop2(iterator2, ca):
 
         def fail2(e):
-          rpki.log.error(traceback.format_exc())
+          rpki.log.traceback()
           rpki.log.warn("Couldn't regenerate CRLs and manifests for CA %r, skipping: %s" % (ca, e))
           iterator2()
 
@@ -411,7 +410,7 @@ class self_elt(data_elt):
       def roa_requests_loop(iterator, roa_request):
 
         def lose(e):
-          rpki.log.error(traceback.format_exc())
+          rpki.log.traceback()
           rpki.log.warn("Could not update ROA %r, skipping: %s" % (roa, e))
           iterator()
 
@@ -463,7 +462,7 @@ class self_elt(data_elt):
         def roa_withdraw_loop(iterator, roa):
 
           def lose(e):
-            rpki.log.error(traceback.format_exc())
+            rpki.log.traceback()
             rpki.log.warn("Could not withdraw ROA %r: %s" % (roa, e))
             iterator()
 
@@ -474,7 +473,7 @@ class self_elt(data_elt):
       rpki.async.iterator(roa_requests, roa_requests_loop, roa_requests_done)
 
     def roa_requests_failed(e):
-      rpki.log.error(traceback.format_exc())
+      rpki.log.traceback()
       rpki.log.warn("Could not fetch ROA requests for %s, skipping: %s" % (self.self_handle, e))
       cb()
 
@@ -557,8 +556,7 @@ class repository_elt(data_elt):
     """
     rpki.log.trace()
     bsc = self.bsc()
-    q_msg = rpki.publication.msg(pdus)
-    q_msg.type = "query"
+    q_msg = rpki.publication.msg.query(pdus)
     q_cms = rpki.publication.cms_msg.wrap(q_msg, bsc.private_key_id, bsc.signing_cert, bsc.signing_cert_crl)
     bpki_ta_path = (self.gctx.bpki_ta, self.self().bpki_cert, self.self().bpki_glue, self.bpki_https_cert, self.bpki_https_glue)
 
@@ -795,7 +793,7 @@ class child_elt(data_elt):
     except rpki.exceptions.NoActiveCA, data:
       done(q_msg.serve_error(data))
     except Exception, data:
-      rpki.log.error(traceback.format_exc())
+      rpki.log.traceback()
       done(q_msg.serve_error(data))
 
 class list_resources_elt(rpki.xml_utils.base_elt, left_right_namespace):
@@ -862,12 +860,13 @@ class report_error_elt(rpki.xml_utils.base_elt, left_right_namespace):
   attributes = ("tag", "self_handle", "error_code")
 
   @classmethod
-  def from_exception(cls, e, self_handle = None):
+  def from_exception(cls, e, self_handle = None, tag = None):
     """
     Generate a <report_error/> element from an exception.
     """
     self = cls()
     self.self_handle = self_handle
+    self.tag = tag
     self.error_code = e.__class__.__name__
     self.text = str(e)
     return self
@@ -892,14 +891,14 @@ class msg(rpki.xml_utils.msg, left_right_namespace):
     """
     Serve one msg PDU.
     """
-    r_msg = self.__class__()
-    r_msg.type = "reply"
+
+    r_msg = self.__class__.reply()
 
     def loop(iterator, q_pdu):
 
       def fail(e):
-        rpki.log.error(traceback.format_exc())
-        r_msg.append(report_error_elt.from_exception(e, self_handle = q_pdu.self_handle))
+        rpki.log.traceback()
+        r_msg.append(report_error_elt.from_exception(e, self_handle = q_pdu.self_handle, tag = q_pdu.tag))
         cb(r_msg)
 
       try:
diff --git a/rpkid/rpki/log.py b/rpkid/rpki/log.py
index 77a5c67c..f7163733 100644
--- a/rpkid/rpki/log.py
+++ b/rpkid/rpki/log.py
@@ -32,7 +32,8 @@ OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 PERFORMANCE OF THIS SOFTWARE.
 """
 
-import syslog, traceback, sys, os, time
+import syslog, sys, os, time
+import traceback as tb
 
 ## @var enable_trace
 # Whether call tracing is enabled.
@@ -93,5 +94,14 @@ def trace():
   """
 
   if enable_trace:
-    bt = traceback.extract_stack(limit = 3)
+    bt = tb.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]))
+
+def traceback():
+  """
+  Consolidated backtrace facility with a bit of extra info.
+  """
+
+  bt = tb.extract_stack(limit = 3)
+  error("Exception caught in %s() at %s:%d called from %s:%d" % (bt[1][2], bt[1][0], bt[1][1], bt[0][0], bt[0][1]))
+  error(tb.format_exc())
diff --git a/rpkid/rpki/publication.py b/rpkid/rpki/publication.py
index 8130f78c..dc033d31 100644
--- a/rpkid/rpki/publication.py
+++ b/rpkid/rpki/publication.py
@@ -32,7 +32,7 @@ OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 PERFORMANCE OF THIS SOFTWARE.
 """
 
-import base64, os, traceback
+import base64, os
 import rpki.resource_set, rpki.x509, rpki.sql, rpki.exceptions, rpki.xml_utils
 import rpki.https, rpki.up_down, rpki.relaxng, rpki.sundial, rpki.log, rpki.roa
 
@@ -288,11 +288,12 @@ class report_error_elt(rpki.xml_utils.base_elt, publication_namespace):
   attributes = ("tag", "error_code")
 
   @classmethod
-  def from_exception(cls, exc):
+  def from_exception(cls, exc, tag = None):
     """
     Generate a <report_error/> element from an exception.
     """
     self = cls()
+    self.tag = tag
     self.error_code = exc.__class__.__name__
     return self
 
@@ -322,8 +323,8 @@ class msg(rpki.xml_utils.msg, publication_namespace):
     def loop(iterator, q_pdu):
 
       def fail(e):
-        rpki.log.error(traceback.format_exc())
-        r_msg.append(report_error_elt.from_exception(e))
+        rpki.log.traceback()
+        r_msg.append(report_error_elt.from_exception(e, q_pdu.tag))
         cb(r_msg)
 
       try:
diff --git a/rpkid/rpki/rpki_engine.py b/rpkid/rpki/rpki_engine.py
index 07f18584..08f090f3 100644
--- a/rpkid/rpki/rpki_engine.py
+++ b/rpkid/rpki/rpki_engine.py
@@ -32,7 +32,7 @@ OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 PERFORMANCE OF THIS SOFTWARE.
 """
 
-import traceback, lxml.etree, re
+import lxml.etree, re
 import rpki.resource_set, rpki.up_down, rpki.left_right, rpki.x509, rpki.sql
 import rpki.https, rpki.config, rpki.exceptions, rpki.relaxng, rpki.log, rpki.async
 
@@ -65,8 +65,7 @@ class rpkid_context(object):
 
     rpki.log.trace()
 
-    q_msg = rpki.left_right.msg()
-    q_msg.type = "query"
+    q_msg = rpki.left_right.msg.query()
     q_msg.append(q_pdu)
     q_cms = rpki.left_right.cms_msg.wrap(q_msg, self.rpkid_key, self.rpkid_cert)
 
@@ -144,7 +143,7 @@ class rpkid_context(object):
     except (rpki.async.ExitNow, SystemExit):
       raise
     except Exception, data:
-      rpki.log.error(traceback.format_exc())
+      rpki.log.traceback()
       cb(500, "Unhandled exception %s" % data)
 
   up_down_url_regexp = re.compile("/up-down/([-A-Z0-9_]+)/([-A-Z0-9_]+)$", re.I)
@@ -174,7 +173,7 @@ class rpkid_context(object):
     except (rpki.async.ExitNow, SystemExit):
       raise
     except Exception, data:
-      rpki.log.error(traceback.format_exc())
+      rpki.log.traceback()
       cb(400, "Could not process PDU: %s" % data)
 
   def cronjob_handler(self, query, path, cb):
@@ -396,7 +395,7 @@ class ca_obj(rpki.sql.sql_persistent):
     """
 
     def fail(e):
-      rpki.log.error(traceback.format_exc())
+      rpki.log.traceback()
       rpki.log.warn("Could not delete CA %r, skipping: %s" % (self, e))
       callback()
 
@@ -1119,7 +1118,7 @@ class roa_obj(rpki.sql.sql_persistent):
     """
 
     def lose(e):
-      rpki.log.error(traceback.format_exc())
+      rpki.log.traceback()
       rpki.log.warn("Could not update ROA %r, skipping: %s" % (self, e))
       callback()
       return
diff --git a/rpkid/rpki/up_down.py b/rpkid/rpki/up_down.py
index a7e14a43..6aa7e294 100644
--- a/rpkid/rpki/up_down.py
+++ b/rpkid/rpki/up_down.py
@@ -32,8 +32,8 @@ OR OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
 PERFORMANCE OF THIS SOFTWARE.
 """
 
-import base64, lxml.etree, traceback
-import rpki.resource_set, rpki.x509, rpki.exceptions
+import base64, lxml.etree
+import rpki.resource_set, rpki.x509, rpki.exceptions, rpki.log
 import rpki.xml_utils, rpki.relaxng
 
 xmlns = "http://www.apnic.net/specs/rescerts/up-down/"
@@ -620,7 +620,7 @@ class message_pdu(base_elt):
       callback(r_msg)
 
     def lose(e):
-      rpki.log.error(traceback.format_exc())
+      rpki.log.traceback()
       callback(self.serve_error(e))
 
     try:
diff --git a/rpkid/rpki/xml_utils.py b/rpkid/rpki/xml_utils.py
index be2b9510..9e4aa265 100644
--- a/rpkid/rpki/xml_utils.py
+++ b/rpkid/rpki/xml_utils.py
@@ -415,3 +415,17 @@ class msg(list):
     elt = lxml.etree.Element("{%s}msg" % (self.xmlns), nsmap = self.nsmap, version = str(self.version), type = self.type)
     elt.extend([i.toXML() for i in self])
     return elt
+
+  @classmethod
+  def query(cls, *args):
+    """Create a query PDU."""
+    self = cls(*args)
+    self.type = "query"
+    return self
+
+  @classmethod
+  def reply(cls, *args):
+    """Create a reply PDU."""
+    self = cls(*args)
+    self.type = "reply"
+    return self
diff --git a/rpkid/testbed.py b/rpkid/testbed.py
index c2be102c..698f986e 100644
--- a/rpkid/testbed.py
+++ b/rpkid/testbed.py
@@ -758,8 +758,7 @@ class allocation(object):
     assert isinstance(pdus, (list, tuple))
     assert self.rpki_port is not None
 
-    msg = rpki.left_right.msg(pdus)
-    msg.type = "query"
+    msg = rpki.left_right.msg.query(pdus)
     cms, xml = rpki.left_right.cms_msg.wrap(msg, self.irbe_key, self.irbe_cert,
                                             pretty_print = True)
     rpki.log.debug(xml)
@@ -1146,8 +1145,7 @@ def call_pubd(pdus, cb):
   response.
   """
   rpki.log.info("Calling pubd")
-  msg = rpki.publication.msg(pdus)
-  msg.type = "query"
+  msg = rpki.publication.msg.query(pdus)
   cms, xml = rpki.publication.cms_msg.wrap(msg, pubd_irbe_key, pubd_irbe_cert,
                                            pretty_print = True)
   rpki.log.debug(xml)