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

8 files changed, 65 insertions, 42 deletions

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