Use a lock to serialize rpkid tasks. Add temporary trace call

sequence trace code to rpki.rpkidb.models to assist in simplifying
some of the gratuitously complicated method call chains.  Various
trivial PyLint cleanups.

svn path=/branches/tk705/; revision=6161

17 files changed, 282 insertions, 139 deletions

diff --git a/rpki/POW/__init__.py b/rpki/POW/__init__.py
index 7830a477..7fb445e0 100644
--- a/rpki/POW/__init__.py
+++ b/rpki/POW/__init__.py
@@ -31,9 +31,9 @@ del sundial_datetime
 # Construct friendlier representation for validation status codes.
 
 from rpki.POW._POW import _validation_status_codes
-class validation_status:
+class validation_status(object):
     "RPKI validation status codes."
 for code in _validation_status_codes:
     setattr(validation_status, code.name, code)
-del code
+del code                                # pylint: disable=W0631
 del _validation_status_codes
diff --git a/rpki/cli.py b/rpki/cli.py
index 51ac0367..9440ecb2 100644
--- a/rpki/cli.py
+++ b/rpki/cli.py
@@ -82,12 +82,12 @@ class Cmd(cmd.Cmd):
         self.last_command_failed = True
         return False
 
-    def do_EOF(self, arg):
+    def do_EOF(self, arg):              # pylint: disable=W0613
         if self.EOF_exits_command_loop and self.prompt:
             print
         return self.EOF_exits_command_loop
 
-    def do_exit(self, arg):
+    def do_exit(self, arg):             # pylint: disable=W0613,R0201
         """
         Exit program.
         """
@@ -106,7 +106,7 @@ class Cmd(cmd.Cmd):
         if self.emptyline_repeats_last_command:
             cmd.Cmd.emptyline(self)
 
-    def filename_complete(self, text, line, begidx, endidx):
+    def filename_complete(self, text, line, begidx, endidx):              # pylint: disable=W0613,R0201
         """
         Filename completion handler, with hack to restore what I consider
         the normal (bash-like) behavior when one hits the completion key
@@ -199,9 +199,9 @@ def yes_or_no(prompt, default = None, require_full_word = False):
         print 'Please answer "yes" or "no"'
 
 _yes_or_no_prompts = {
-  True  : ' ("yes" or "no" ["yes"]) ',
-  False : ' ("yes" or "no" ["no"]) ',
-  None  : ' ("yes" or "no") ' }
+    True  : ' ("yes" or "no" ["yes"]) ',
+    False : ' ("yes" or "no" ["no"]) ',
+    None  : ' ("yes" or "no") ' }
 
 
 class NonExitingArgumentParser(argparse.ArgumentParser):
diff --git a/rpki/config.py b/rpki/config.py
index 5dd03a6d..a9bd3219 100644
--- a/rpki/config.py
+++ b/rpki/config.py
@@ -170,6 +170,7 @@ class parser(object):
         Get a boolean option, perhaps with a default value.
         """
 
+        # pylint: disable=W0212
         v = self.get(option, default, section)
         if isinstance(v, str):
             v = v.lower()
@@ -264,7 +265,7 @@ class parser(object):
             rpki.x509.generate_insecure_debug_only_rsa_key = rpki.x509.insecure_debug_only_rsa_key_generator(*self.get("insecure-debug-only-rsa-key-db").split())
         except ConfigParser.NoOptionError:
             pass
-        except:                             # pylint: disable=W0702
+        except:
             logger.warning("insecure-debug-only-rsa-key-db configured but initialization failed, check for corrupted database file")
 
         try:
diff --git a/rpki/daemonize.py b/rpki/daemonize.py
index bd59fca0..472d4b33 100644
--- a/rpki/daemonize.py
+++ b/rpki/daemonize.py
@@ -100,7 +100,7 @@ def daemon(nochdir = False, noclose = False, pidfile = None):
         sys.exit("fork() failed: %d (%s)" % (e.errno, e.strerror))
     else:
         if pid > 0:
-            os._exit(0)
+            os._exit(0)                 # pylint: disable=W0212
 
     if not nochdir:
         os.chdir("/")
diff --git a/rpki/fields.py b/rpki/fields.py
index 1390d4ac..f8ee8789 100644
--- a/rpki/fields.py
+++ b/rpki/fields.py
@@ -130,6 +130,8 @@ class DERField(models.BinaryField):
     classes are derived from it.
     """
 
+    rpki_type = rpki.x509.DER_object
+
     def __init__(self, *args, **kwargs):
         kwargs["blank"] = True
         kwargs["default"] = None
@@ -141,7 +143,7 @@ class DERField(models.BinaryField):
         del kwargs["default"]
         return name, path, args, kwargs
 
-    def from_db_value(self, value, expression, connection, context):
+    def from_db_value(self, value, expression, connection, context): # pylint: disable=W0613
         if value is not None:
             value = self.rpki_type(DER = str(value))
         return value
diff --git a/rpki/http_simple.py b/rpki/http_simple.py
index 6f73def5..86b2eb5a 100644
--- a/rpki/http_simple.py
+++ b/rpki/http_simple.py
@@ -35,6 +35,8 @@ class HTTPRequestHandler(BaseHTTPServer.BaseHTTPRequestHandler):
     HTTP request handler simple RPKI servers.
     """
 
+    rpki_handlers = ()
+
     def do_POST(self):
         try:
             content_type   = self.headers.get("Content-Type")
@@ -97,7 +99,7 @@ class BadContentType(Exception):
 
 
 def client(proto_cms_msg, client_key, client_cert, server_ta, server_cert, url, q_msg,
-           debug = False, replay_track = None, client_crl = None, content_type = default_content_type):
+           debug = None, replay_track = None, client_crl = None, content_type = default_content_type):
     """
     Issue single a query and return the response, handling all the CMS and XML goo.
     """
@@ -110,7 +112,7 @@ def client(proto_cms_msg, client_key, client_cert, server_ta, server_cert, url,
     q_cms = proto_cms_msg()
     q_der = q_cms.wrap(q_msg, client_key, client_cert, client_crl)
 
-    if debug:
+    if debug is not None:
         debug.write("<!-- Query -->\n" + q_cms.pretty_print_content() + "\n")
 
     http = httplib.HTTPConnection(u.hostname, u.port or httplib.HTTP_PORT)
@@ -130,7 +132,7 @@ def client(proto_cms_msg, client_key, client_cert, server_ta, server_cert, url,
     if replay_track is not None:
         replay_track.cms_timestamp = r_cms.check_replay(replay_track.cms_timestamp, url)
 
-    if debug:
+    if debug is not None:
         debug.write("<!-- Reply -->\n" + r_cms.pretty_print_content() + "\n")
 
     return r_msg
diff --git a/rpki/irdb/zookeeper.py b/rpki/irdb/zookeeper.py
index a65f1f5f..514ff683 100644
--- a/rpki/irdb/zookeeper.py
+++ b/rpki/irdb/zookeeper.py
@@ -599,10 +599,10 @@ class Zookeeper(object):
         self.log("Child calls itself %r, we call it %r" % (x.get("child_handle"), child_handle))
 
         child, created = rpki.irdb.models.Child.objects.get_or_certify(
-            issuer    = self.resource_ca,
-            handle    = child_handle,
-            ta        = rpki.x509.X509(Base64 = x.findtext(tag_oob_child_bpki_ta)),
-          valid_until = valid_until)
+            issuer      = self.resource_ca,
+            handle      = child_handle,
+            ta          = rpki.x509.X509(Base64 = x.findtext(tag_oob_child_bpki_ta)),
+            valid_until = valid_until)
 
         return self.generate_parental_response(child), child_handle
 
@@ -1210,7 +1210,7 @@ class Zookeeper(object):
             q_msg = self._compose_publication_control_query()
             for client in self.server_ca.clients.all():
                 SubElement(q_msg, rpki.publication_control.tag_client, action = "set",
-                           client_handle = client.handle, clear_reply_protection = "yes")
+                           client_handle = client.handle, clear_replay_protection = "yes")
             self.call_pubd(q_msg)
 
 
@@ -1654,10 +1654,10 @@ class Zookeeper(object):
 
         q_msg = self._compose_left_right_query()
         SubElement(q_msg, rpki.left_right.tag_tenant, action = "list")
-        self.call_rpkid(q_msg)
+        r_msg = self.call_rpkid(q_msg)
 
-        tenant_handles = set(s.get("tenant_handle") for s in q_msg)
-        ca_handles   = set(ca.handle for ca in rpki.irdb.models.ResourceHolderCA.objects.all())
+        tenant_handles = set(s.get("tenant_handle") for s in r_msg)
+        ca_handles = set(ca.handle for ca in rpki.irdb.models.ResourceHolderCA.objects.all())
         assert ca_handles <= tenant_handles
 
         q_msg = self._compose_left_right_query()
diff --git a/rpki/old_irdbd.py b/rpki/old_irdbd.py
index fca1f1d9..4ebb33b0 100644
--- a/rpki/old_irdbd.py
+++ b/rpki/old_irdbd.py
@@ -221,10 +221,10 @@ class main(object):
 
 
     handle_dispatch = {
-      rpki.left_right.list_resources_elt               : handle_list_resources,
-      rpki.left_right.list_roa_requests_elt            : handle_list_roa_requests,
-      rpki.left_right.list_ghostbuster_requests_elt    : handle_list_ghostbuster_requests,
-      rpki.left_right.list_ee_certificate_requests_elt : handle_list_ee_certificate_requests }
+        rpki.left_right.list_resources_elt               : handle_list_resources,
+        rpki.left_right.list_roa_requests_elt            : handle_list_roa_requests,
+        rpki.left_right.list_ghostbuster_requests_elt    : handle_list_ghostbuster_requests,
+        rpki.left_right.list_ee_certificate_requests_elt : handle_list_ee_certificate_requests }
 
     def handler(self, request, q_der):
         try:
diff --git a/rpki/rcynic.py b/rpki/rcynic.py
index 3307e926..76d5d183 100644
--- a/rpki/rcynic.py
+++ b/rpki/rcynic.py
@@ -112,10 +112,10 @@ class rcynic_roa(rcynic_object):
         v4, v6 = self.obj.get_POW().getPrefixes()
         if v4:
             self.prefix_sets.append(rpki.resource_set.roa_prefix_set_ipv4([
-              rpki.resource_set.roa_prefix_ipv4(p[0], p[1], p[2]) for p in v4]))
+                rpki.resource_set.roa_prefix_ipv4(p[0], p[1], p[2]) for p in v4]))
         if v6:
             self.prefix_sets.append(rpki.resource_set.roa_prefix_set_ipv6([
-              rpki.resource_set.roa_prefix_ipv6(p[0], p[1], p[2]) for p in v6]))
+                rpki.resource_set.roa_prefix_ipv6(p[0], p[1], p[2]) for p in v6]))
         self.ee = rpki.x509.X509(POW = self.obj.get_POW().certs()[0])
         self.notBefore = self.ee.getNotBefore()
         self.notAfter = self.ee.getNotAfter()
@@ -163,9 +163,9 @@ class rcynic_ghostbuster(rcynic_object):
         self.show_attrs("notBefore", "notAfter", "vcard")
 
 file_name_classes = {
-  ".cer" : rcynic_certificate,
-  ".gbr" : rcynic_ghostbuster,
-  ".roa" : rcynic_roa }
+    ".cer" : rcynic_certificate,
+    ".gbr" : rcynic_ghostbuster,
+    ".roa" : rcynic_roa }
 
 class rcynic_file_iterator(object):
     """
diff --git a/rpki/resource_set.py b/rpki/resource_set.py
index 43dfa9ef..b8d1f658 100644
--- a/rpki/resource_set.py
+++ b/rpki/resource_set.py
@@ -606,8 +606,8 @@ class resource_set_ip(resource_set):
         for r in self:
             r.chop_into_prefixes(prefix_ranges)
         return self.roa_prefix_set_type([
-          self.roa_prefix_set_type.prefix_type(r.min, r.prefixlen())
-          for r in prefix_ranges])
+            self.roa_prefix_set_type.prefix_type(r.min, r.prefixlen())
+            for r in prefix_ranges])
 
 class resource_set_ipv4(resource_set_ip):
     """
diff --git a/rpki/rpkid.py b/rpki/rpkid.py
index c0ddbd58..001c36e2 100644
--- a/rpki/rpkid.py
+++ b/rpki/rpkid.py
@@ -455,11 +455,11 @@ class main(object):
         except AttributeError:
             import rpki.rpkidb.models         # pylint: disable=W0621
             self._left_right_models = {
-              rpki.left_right.tag_tenant      : rpki.rpkidb.models.Tenant,
-              rpki.left_right.tag_bsc         : rpki.rpkidb.models.BSC,
-              rpki.left_right.tag_parent      : rpki.rpkidb.models.Parent,
-              rpki.left_right.tag_child       : rpki.rpkidb.models.Child,
-              rpki.left_right.tag_repository  : rpki.rpkidb.models.Repository }
+                rpki.left_right.tag_tenant      : rpki.rpkidb.models.Tenant,
+                rpki.left_right.tag_bsc         : rpki.rpkidb.models.BSC,
+                rpki.left_right.tag_parent      : rpki.rpkidb.models.Parent,
+                rpki.left_right.tag_child       : rpki.rpkidb.models.Child,
+                rpki.left_right.tag_repository  : rpki.rpkidb.models.Repository }
             return self._left_right_models
 
     @property
@@ -472,8 +472,8 @@ class main(object):
             return self._left_right_trivial_handlers
         except AttributeError:
             self._left_right_trivial_handlers = {
-              rpki.left_right.tag_list_published_objects      : self.handle_list_published_objects,
-              rpki.left_right.tag_list_received_resources     : self.handle_list_received_resources }
+                rpki.left_right.tag_list_published_objects  : self.handle_list_published_objects,
+                rpki.left_right.tag_list_received_resources : self.handle_list_received_resources }
             return self._left_right_trivial_handlers
 
     def handle_list_published_objects(self, q_pdu, r_msg):
@@ -538,8 +538,6 @@ class main(object):
         Process one left-right message.
         """
 
-        logger.debug("Entering left_right_handler()")
-
         content_type = handler.request.headers["Content-Type"]
         if content_type not in rpki.left_right.allowed_content_types:
             handler.set_status(415, "No handler for Content-Type %s" % content_type)
@@ -609,7 +607,6 @@ class main(object):
 
             handler.set_status(200)
             handler.finish(rpki.left_right.cms_msg().wrap(r_msg, self.rpkid_key, self.rpkid_cert))
-            logger.debug("Normal exit from left_right_handler()")
 
         except Exception, e:
             logger.exception("Unhandled exception serving left-right request")
@@ -622,8 +619,6 @@ class main(object):
         Process one up-down PDU.
         """
 
-        logger.debug("Entering up_down_handler()")
-
         content_type = handler.request.headers["Content-Type"]
         if content_type not in rpki.up_down.allowed_content_types:
             handler.set_status(415, "No handler for Content-Type %s" % content_type)
@@ -684,27 +679,30 @@ class publication_queue(object):
         logger.debug("Queuing publication action: uri %s, old %r, new %r, hash %s",
                      uri, old_obj, new_obj, old_hash)
 
-        # id(repository) may need to change to repository.peer_contact_uri
-        # once we convert from our custom SQL cache to Django ORM.
-
-        rid = id(repository)
+        rid = repository.peer_contact_uri
         if rid not in self.repositories:
             self.repositories[rid] = repository
             self.msgs[rid] = Element(rpki.publication.tag_msg, nsmap = rpki.publication.nsmap,
                                      type = "query", version = rpki.publication.version)
 
         if self.replace and uri in self.uris:
-            logger.debug("Removing publication duplicate %r", self.uris[uri])
+            logger.debug("Removing publication duplicate %r hash %s", self.uris[uri], self.uris[uri].get("hash"))
             old_pdu = self.uris.pop(uri)
             self.msgs[rid].remove(old_pdu)
             pdu_hash = old_pdu.get("hash")
         elif old_hash is not None:
+            logger.debug("Old hash supplied")                   # XXX
             pdu_hash = old_hash
         elif old_obj is None:
+            logger.debug("No old object present")               # XXX
             pdu_hash = None
         else:
+            logger.debug("Calculating hash of old object")      # XXX
             pdu_hash = rpki.x509.sha256(old_obj.get_DER()).encode("hex")
 
+        logger.debug("uri %s old hash %s new hash %s", uri, pdu_hash, # XXX
+                     None if new_obj is None else rpki.x509.sha256(new_obj.get_DER()).encode("hex"))
+
         if new_obj is None:
             pdu = SubElement(self.msgs[rid], rpki.publication.tag_withdraw, uri = uri, hash = pdu_hash)
         else:
diff --git a/rpki/rpkid_tasks.py b/rpki/rpkid_tasks.py
index 5c28afc3..989042b9 100644
--- a/rpki/rpkid_tasks.py
+++ b/rpki/rpkid_tasks.py
@@ -47,7 +47,7 @@ def queue_task(cls):
     Class decorator to add a new task class to task_classes.
     """
 
-    global task_classes
+    global task_classes                 # pylint: disable=W0603
     task_classes += (cls,)
     return cls
 
@@ -63,6 +63,11 @@ class AbstractTask(object):
 
     timeslice = rpki.sundial.timedelta(seconds = 15)
 
+    ## @var serialize
+    # Lock to force prevent more than one task from running at a time.
+
+    serialize = tornado.locks.Lock()
+
     def __init__(self, rpkid, tenant, description = None):
         self.rpkid       = rpkid
         self.tenant      = tenant
@@ -84,6 +89,7 @@ class AbstractTask(object):
     @tornado.gen.coroutine
     def start(self):
         try:
+            yield self.serialize.acquire()
             logger.debug("%r: Starting", self)
             self.due_date = rpki.sundial.now() + self.timeslice
             self.clear()
@@ -101,6 +107,7 @@ class AbstractTask(object):
                 self.done_this.notify_all()
             self.done_this = self.done_next
             self.done_next = None
+            self.serialize.release()
 
     def wait(self):
         done = "done_next" if self.started else "done_this"
@@ -119,7 +126,11 @@ class AbstractTask(object):
         logger.debug("%r: Postponing", self)
         self.due_date = None
         self.runnable.clear()
-        yield self.runnable.wait()
+        try:
+            self.serialize.release()
+            yield self.runnable.wait()
+        finally:
+            yield self.serialize.acquire()
         logger.debug("%r: Resuming", self)
         self.due_date = rpki.sundial.now() + self.timeslice
 
@@ -217,7 +228,7 @@ class UpdateChildrenTask(AbstractTask):
                             ca_detail.generate_crl(publisher = publisher)
                             ca_detail.generate_manifest(publisher = publisher)
 
-                        elif (old_resources != new_resources or old_aia != new_aia or (old_resources.valid_until < rsn and irdb_resources.valid_until > now and old_resources.valid_until != irdb_resources.valid_until)):
+                        elif old_resources != new_resources or old_aia != new_aia or (old_resources.valid_until < rsn and irdb_resources.valid_until > now and old_resources.valid_until != irdb_resources.valid_until):
                             logger.debug("Need to reissue child %s certificate g(SKI) %s", child.child_handle, child_cert.gski)
                             if old_resources != new_resources:
                                 logger.debug("Child %s g(SKI) %s resources changed: old %s new %s", child.child_handle, child_cert.gski, old_resources, new_resources)
@@ -275,7 +286,7 @@ class UpdateROAsTask(AbstractTask):
             k = (roa.asn, str(roa.ipv4), str(roa.ipv6))
             if k not in roas:
                 roas[k] = roa
-            elif (roa.roa is not None and roa.cert is not None and roa.ca_detail is not None and roa.ca_detail.state == "active" and (roas[k].roa is None or roas[k].cert is None or roas[k].ca_detail is None or roas[k].ca_detail.state != "active")):
+            elif roa.roa is not None and roa.cert is not None and roa.ca_detail is not None and roa.ca_detail.state == "active" and (roas[k].roa is None or roas[k].cert is None or roas[k].ca_detail is None or roas[k].ca_detail.state != "active"):
                 orphans.append(roas[k])
                 roas[k] = roa
             else:
@@ -418,6 +429,8 @@ class UpdateEECertificatesTask(AbstractTask):
 
             publisher = rpki.rpkid.publication_queue(self.rpkid)
 
+            logger.debug("%r: Examining EE certificate requests", self)
+
             existing = dict()
             for ee in self.tenant.ee_certificates.all():
                 gski = ee.gski
@@ -441,25 +454,25 @@ class UpdateEECertificatesTask(AbstractTask):
 
                 for ee in ees:
                     if ee.ca_detail in covering:
-                        logger.debug("Updating existing EE certificate for %s %s", gski, resources)
+                        logger.debug("%r: Updating existing EE certificate for %s %s", self, gski, resources)
                         ee.reissue(resources = resources, publisher = publisher)
                         covering.remove(ee.ca_detail)
                     else:
-                        logger.debug("Existing EE certificate for %s %s is no longer covered", gski, resources)
+                        logger.debug("%r: Existing EE certificate for %s %s is no longer covered", self, gski, resources)
                         ee.revoke(publisher = publisher)
 
                 subject_name = rpki.x509.X501DN.from_cn(r_pdu.get("cn"), r_pdu.get("sn"))
                 subject_key  = rpki.x509.PKCS10(Base64 = r_pdu[0].text).getPublicKey()
 
                 for ca_detail in covering:
-                    logger.debug("No existing EE certificate for %s %s", gski, resources)
+                    logger.debug("%r: No existing EE certificate for %s %s", self, gski, resources)
                     rpki.rpkidb.models.EECertificate.create(      # sic: class method, not Django manager method (for now, anyway)
-                      ca_detail    = ca_detail,
-                      subject_name = subject_name,
-                      subject_key  = subject_key,
-                      resources    = resources,
-                      publisher    = publisher,
-                      eku          = r_pdu.get("eku", "").split(",") or None)
+                        ca_detail    = ca_detail,
+                        subject_name = subject_name,
+                        subject_key  = subject_key,
+                        resources    = resources,
+                        publisher    = publisher,
+                        eku          = r_pdu.get("eku", "").split(",") or None)
 
             # Anything left is an orphan
             for ees in existing.values():
@@ -474,7 +487,7 @@ class UpdateEECertificatesTask(AbstractTask):
             yield publisher.call_pubd()
 
         except:
-            logger.exception("Could not update EE certificates for %s, skipping", self.tenant.tenant_handle)
+            logger.exception("%r: Could not update EE certificates, skipping", self)
 
 
 @queue_task
diff --git a/rpki/rpkidb/models.py b/rpki/rpkidb/models.py
index ab16a176..ab89ba7b 100644
--- a/rpki/rpkidb/models.py
+++ b/rpki/rpkidb/models.py
@@ -26,6 +26,20 @@ from lxml.etree import Element, SubElement, tostring as ElementToString
 
 logger = logging.getLogger(__name__)
 
+# XXX Temporary hack to help trace call chains so we can clear some of
+# the historical clutter out of this module.
+
+def trace_call_chain():
+    if True:
+        from traceback import extract_stack
+        caller, callee = extract_stack(None, 3)[:2]
+        caller_file, caller_line, caller_name = caller[:3]
+        callee_file, callee_line, callee_name = callee[:3]
+        logger.debug("<Call trace> %s() at %s:%s called by %s() at %s:%s",
+                     callee_name, callee_file, callee_line,
+                     caller_name, caller_file, caller_line)
+
+
 # The objects available via the left-right protocol allow NULL values
 # in places we wouldn't otherwise (eg, bpki_cert fields), to support
 # existing protocol which allows back-end to build up objects
@@ -38,6 +52,10 @@ class XMLTemplate(object):
     Encapsulate all the voodoo for transcoding between lxml and ORM.
     """
 
+    # Whether to drop XMl into the log
+
+    debug = False
+
     # Type map to simplify declaration of Base64 sub-elements.
 
     element_type = dict(bpki_cert        = rpki.x509.X509,
@@ -83,7 +101,8 @@ class XMLTemplate(object):
             v = getattr(obj, k)
             if v is not None and not v.empty():
                 SubElement(r_pdu, rpki.left_right.xmlns + k).text = v.get_Base64()
-        logger.debug("XMLTemplate.encode(): %s", ElementToString(r_pdu))
+        if self.debug:
+            logger.debug("XMLTemplate.encode(): %s", ElementToString(r_pdu))
 
 
     def acknowledge(self, obj, q_pdu, r_msg):
@@ -108,7 +127,8 @@ class XMLTemplate(object):
         if self.name == "bsc" and action != "destroy" and obj.pkcs10_request is not None:
             assert not obj.pkcs10_request.empty()
             SubElement(r_pdu, rpki.left_right.xmlns + "pkcs10_request").text = obj.pkcs10_request.get_Base64()
-        logger.debug("XMLTemplate.acknowledge(): %s", ElementToString(r_pdu))
+        if self.debug:
+            logger.debug("XMLTemplate.acknowledge(): %s", ElementToString(r_pdu))
 
 
     def decode(self, obj, q_pdu):
@@ -116,7 +136,8 @@ class XMLTemplate(object):
         Decode XML into an ORM object.
         """
 
-        logger.debug("XMLTemplate.decode(): %r %s", obj, ElementToString(q_pdu))
+        if self.debug:
+            logger.debug("XMLTemplate.decode(): %r %s", obj, ElementToString(q_pdu))
         assert q_pdu.tag == rpki.left_right.xmlns + self.name
         for h in self.handles:
             k = h.xml_template.name
@@ -149,6 +170,10 @@ class XMLManager(models.Manager):       # pylint: disable=W0232
     class attribute holding an XMLTemplate object (above).
     """
 
+    # Whether to blather about what we're doing
+
+    debug = False
+
     def xml_get_or_create(self, xml):
         name   = self.model.xml_template.name
         action = xml.get("action")
@@ -156,11 +181,13 @@ class XMLManager(models.Manager):       # pylint: disable=W0232
         d = { name + "_handle" : xml.get(name + "_handle") }
         if name != "tenant" and action != "create":
             d["tenant__tenant_handle"] = xml.get("tenant_handle")
-        logger.debug("XMLManager.xml_get_or_create(): name %s action %s filter %r", name, action, d)
+        if self.debug:
+            logger.debug("XMLManager.xml_get_or_create(): name %s action %s filter %r", name, action, d)
         result = self.model(**d) if action == "create" else self.get(**d)
         if name != "tenant" and action == "create":
             result.tenant = Tenant.objects.get(tenant_handle = xml.get("tenant_handle"))
-        logger.debug("XMLManager.xml_get_or_create(): name %s action %s filter %r result %r", name, action, d, result)
+        if self.debug:
+            logger.debug("XMLManager.xml_get_or_create(): name %s action %s filter %r result %r", name, action, d, result)
         return result
 
     def xml_list(self, xml):
@@ -172,9 +199,11 @@ class XMLManager(models.Manager):       # pylint: disable=W0232
             d[name + "_handle"] = xml.get(name + "_handle")
         if name != "tenant":
             d["tenant__tenant_handle"] = xml.get("tenant_handle")
-        logger.debug("XMLManager.xml_list(): name %s action %s filter %r", name, action, d)
+        if self.debug:
+            logger.debug("XMLManager.xml_list(): name %s action %s filter %r", name, action, d)
         result = self.filter(**d) if d else self.all()
-        logger.debug("XMLManager.xml_list(): name %s action %s filter %r result %r", name, action, d, result)
+        if self.debug:
+            logger.debug("XMLManager.xml_list(): name %s action %s filter %r result %r", name, action, d, result)
         return result
 
     def xml_get_for_delete(self, xml):
@@ -184,9 +213,11 @@ class XMLManager(models.Manager):       # pylint: disable=W0232
         d = { name + "_handle" : xml.get(name + "_handle") }
         if name != "tenant":
             d["tenant__tenant_handle"] = xml.get("tenant_handle")
-        logger.debug("XMLManager.xml_get_for_delete(): name %s action %s filter %r", name, action, d)
+        if self.debug:
+            logger.debug("XMLManager.xml_get_for_delete(): name %s action %s filter %r", name, action, d)
         result = self.get(**d)
-        logger.debug("XMLManager.xml_get_for_delete(): name %s action %s filter %r result %r", name, action, d, result)
+        if self.debug:
+            logger.debug("XMLManager.xml_get_for_delete(): name %s action %s filter %r result %r", name, action, d, result)
         return result
 
 
@@ -200,15 +231,18 @@ def xml_hooks(cls):
     # for the XMLTemplate setup.  Whatever.  Gussie up later.
 
     def default_xml_pre_save_hook(self, q_pdu):
-        logger.debug("default_xml_pre_save_hook()")
+        #logger.debug("default_xml_pre_save_hook()")
+        pass
 
     @tornado.gen.coroutine
     def default_xml_post_save_hook(self, rpkid, q_pdu):
-        logger.debug("default_xml_post_save_hook()")
+        #logger.debug("default_xml_post_save_hook()")
+        pass
 
     @tornado.gen.coroutine
     def default_xml_pre_delete_hook(self, rpkid):
-        logger.debug("default_xml_pre_delete_hook()")
+        #logger.debug("default_xml_pre_delete_hook()")
+        pass
 
     for name, method in (("xml_pre_save_hook",   default_xml_pre_save_hook),
                          ("xml_post_save_hook",  default_xml_post_save_hook),
@@ -242,10 +276,13 @@ class Tenant(models.Model):
 
     @tornado.gen.coroutine
     def xml_pre_delete_hook(self, rpkid):
+        trace_call_chain()
         yield [parent.destroy() for parent in self.parents.all()]
 
     @tornado.gen.coroutine
     def xml_post_save_hook(self, rpkid, q_pdu):
+        trace_call_chain()
+
         rekey             = q_pdu.get("rekey")
         revoke            = q_pdu.get("revoke")
         reissue           = q_pdu.get("reissue")
@@ -264,25 +301,27 @@ class Tenant(models.Model):
         if rekey or revoke or reissue or revoke_forgotten:
             for parent in self.parents.all():
                 if rekey:
-                    futures.append(parent.serve_rekey(rpkid))
+                    futures.append(parent.serve_rekey(rpkid = rpkid))
                 if revoke:
-                    futures.append(parent.serve_revoke(rpkid))
+                    futures.append(parent.serve_revoke(rpkid = rpkid))
                 if reissue:
-                    futures.append(parent.serve_reissue(rpkid))
+                    futures.append(parent.serve_reissue(rpkid = rpkid))
                 if revoke_forgotten:
-                    futures.append(parent.serve_revoke_forgotten(rpkid))
+                    futures.append(parent.serve_revoke_forgotten(rpkid = rpkid))
 
         if q_pdu.get("publish_world_now"):
-            futures.append(self.serve_publish_world_now(rpkid))
+            futures.append(self.serve_publish_world_now(rpkid = rpkid))
         if q_pdu.get("run_now"):
-            futures.append(self.serve_run_now(rpkid))
+            futures.append(self.serve_run_now(rpkid = rpkid))
 
         yield futures
 
 
     @tornado.gen.coroutine
     def serve_publish_world_now(self, rpkid):
-        publisher = rpki.rpkid.publication_queue(rpkid)
+        trace_call_chain()
+
+        publisher = rpki.rpkid.publication_queue(rpkid = rpkid)
         repositories = set()
         objects = dict()
 
@@ -332,8 +371,9 @@ class Tenant(models.Model):
 
     @tornado.gen.coroutine
     def serve_run_now(self, rpkid):
+        trace_call_chain()
         logger.debug("Forced immediate run of periodic actions for tenant %s[%r]", self.tenant_handle, self)
-        tasks = self.cron_tasks(rpkid)
+        tasks = self.cron_tasks(rpkid = rpkid)
         rpkid.task_add(tasks)
         futures = [task.wait() for task in tasks]
         rpkid.task_run()
@@ -341,6 +381,7 @@ class Tenant(models.Model):
 
 
     def cron_tasks(self, rpkid):
+        trace_call_chain()
         try:
             return self._cron_tasks
         except AttributeError:
@@ -360,6 +401,7 @@ class Tenant(models.Model):
         any case, this is an optimization we can leave for later.
         """
 
+        trace_call_chain()
         return set(ca_detail
                    for ca_detail in CADetail.objects.filter(ca__parent__tenant = self, state = "active")
                    if ca_detail.covers(resources))
@@ -417,11 +459,13 @@ class Repository(models.Model):
 
     @tornado.gen.coroutine
     def xml_post_save_hook(self, rpkid, q_pdu):
+        trace_call_chain()
         if q_pdu.get("clear_replay_protection"):
             self.clear_replay_protection()
 
 
     def clear_replay_protection(self):
+        trace_call_chain()
         self.last_cms_timestamp = None
         self.save()
 
@@ -441,6 +485,8 @@ class Repository(models.Model):
         handler value of False suppresses calling of the default handler.
         """
 
+        trace_call_chain()
+
         if len(q_msg) == 0:
             return
 
@@ -508,36 +554,42 @@ class Parent(models.Model):
 
     @tornado.gen.coroutine
     def xml_pre_delete_hook(self, rpkid):
+        trace_call_chain()
         yield self.destroy(rpkid, delete_parent = False)
 
     @tornado.gen.coroutine
     def xml_post_save_hook(self, rpkid, q_pdu):
+        trace_call_chain()
         if q_pdu.get("clear_replay_protection"):
             self.clear_replay_protection()
         futures = []
         if q_pdu.get("rekey"):
-            futures.append(self.serve_rekey(rpkid))
+            futures.append(self.serve_rekey(rpkid = rpkid))
         if q_pdu.get("revoke"):
-            futures.append(self.serve_revoke(rpkid))
+            futures.append(self.serve_revoke(rpkid = rpkid))
         if q_pdu.get("reissue"):
-            futures.append(self.serve_reissue(rpkid))
+            futures.append(self.serve_reissue(rpkid = rpkid))
         if q_pdu.get("revoke_forgotten"):
-            futures.append(self.serve_revoke_forgotten(rpkid))
+            futures.append(self.serve_revoke_forgotten(rpkid = rpkid))
         yield futures
 
     @tornado.gen.coroutine
     def serve_rekey(self, rpkid):
-        yield [ca.rekey() for ca in self.cas.all()]
+        trace_call_chain()
+        yield [ca.rekey(rpkid = rpkid) for ca in self.cas.all()]
 
     @tornado.gen.coroutine
     def serve_revoke(self, rpkid):
-        yield [ca.revoke() for ca in self.cas.all()]
+        trace_call_chain()
+        yield [ca.revoke(rpkid = rpkid) for ca in self.cas.all()]
 
     @tornado.gen.coroutine
     def serve_reissue(self, rpkid):
-        yield [ca.reissue() for ca in self.cas.all()]
+        trace_call_chain()
+        yield [ca.reissue(rpkid = rpkid) for ca in self.cas.all()]
 
     def clear_replay_protection(self):
+        trace_call_chain()
         self.last_cms_timestamp = None
         self.save()
 
@@ -557,6 +609,8 @@ class Parent(models.Model):
         not raw SKI values.  Sorry.
         """
 
+        trace_call_chain()
+
         r_msg = yield self.up_down_list_query(rpkid = rpkid)
 
         ski_map = {}
@@ -576,6 +630,8 @@ class Parent(models.Model):
         Revoke a set of SKIs within a particular resource class.
         """
 
+        trace_call_chain()
+
         for ski in skis_to_revoke:
             logger.debug("Asking parent %r to revoke class %r, g(SKI) %s", self, rc_name, ski)
             yield self.up_down_revoke_query(rpkid = rpkid, class_name = rc_name, ski = ski)
@@ -596,7 +652,8 @@ class Parent(models.Model):
         require an explicit trigger.
         """
 
-        skis_from_parent = yield self.get_skis(rpkid)
+        trace_call_chain()
+        skis_from_parent = yield self.get_skis(rpkid = rpkid)
         for rc_name, skis_to_revoke in skis_from_parent.iteritems():
             for ca_detail in CADetail.objects.filter(ca__parent = self).exclude(state = "revoked"):
                 skis_to_revoke.discard(ca_detail.latest_ca_cert.gSKI())
@@ -610,8 +667,9 @@ class Parent(models.Model):
         itself.
         """
 
+        trace_call_chain()
         yield [ca.destroy(self) for ca in self.cas()]
-        yield self.serve_revoke_forgotten(rpkid)
+        yield self.serve_revoke_forgotten(rpkid = rpkid)
         if delete_parent:
             self.delete()
 
@@ -623,6 +681,7 @@ class Parent(models.Model):
 
     @tornado.gen.coroutine
     def up_down_list_query(self, rpkid):
+        trace_call_chain()
         q_msg = self._compose_up_down_query("list")
         r_msg = yield self.query_up_down(rpkid, q_msg)
         raise tornado.gen.Return(r_msg)
@@ -630,6 +689,7 @@ class Parent(models.Model):
 
     @tornado.gen.coroutine
     def up_down_issue_query(self, rpkid, ca, ca_detail):
+        trace_call_chain()
         logger.debug("Parent.up_down_issue_query(): caRepository %r rpkiManifest %r rpkiNotify %r",
                      ca.sia_uri, ca_detail.manifest_uri, ca.parent.repository.rrdp_notification_uri)
         pkcs10 = rpki.x509.PKCS10.create(
@@ -646,6 +706,7 @@ class Parent(models.Model):
 
     @tornado.gen.coroutine
     def up_down_revoke_query(self, rpkid, class_name, ski):
+        trace_call_chain()
         q_msg = self._compose_up_down_query("revoke")
         SubElement(q_msg, rpki.up_down.tag_key, class_name = class_name, ski = ski)
         r_msg = yield self.query_up_down(rpkid, q_msg)
@@ -654,6 +715,7 @@ class Parent(models.Model):
 
     @tornado.gen.coroutine
     def query_up_down(self, rpkid, q_msg):
+        trace_call_chain()
 
         if self.bsc is None:
             raise rpki.exceptions.BSCNotFound("Could not find BSC")
@@ -694,6 +756,7 @@ class Parent(models.Model):
         list_response PDU.
         """
 
+        trace_call_chain()
         sia_uri = rc.get("suggested_sia_head", "")
         if not sia_uri.startswith("rsync://") or not sia_uri.startswith(self.sia_base):
             sia_uri = self.sia_base
@@ -743,6 +806,7 @@ class CA(models.Model):
         with the same key, etc.
         """
 
+        trace_call_chain()
         logger.debug("check_for_updates()")
         sia_uri = parent.construct_sia_uri(rc)
         sia_uri_changed = self.sia_uri != sia_uri
@@ -771,7 +835,7 @@ class CA(models.Model):
         if not ca_details:
             logger.warning("Existing resource class %s to %s from %s with no certificates, rekeying",
                            class_name, parent.tenant.tenant_handle, parent.parent_handle)
-            yield self.rekey(rpkid)
+            yield self.rekey(rpkid = rpkid)
             return
 
         for ca_detail in ca_details:
@@ -782,7 +846,7 @@ class CA(models.Model):
                 logger.warning("g(SKI) %s in resource class %s is in database but missing from list_response to %s from %s, "
                                "maybe parent certificate went away?",
                                ca_detail.public_key.gSKI(), class_name, parent.tenant.tenant_handle, parent.parent_handle)
-                publisher = rpki.rpkid.publication_queue(rpkid)
+                publisher = rpki.rpkid.publication_queue(rpkid = rpkid)
                 ca_detail.destroy(ca = ca_detail.ca, publisher = publisher)
                 yield publisher.call_pubd()
                 continue
@@ -831,6 +895,8 @@ class CA(models.Model):
         to create and set up a corresponding CA object.
         """
 
+        trace_call_chain()
+
         self = cls.objects.create(parent = parent,
                                   parent_resource_class = rc.get("class_name"),
                                   sia_uri = parent.construct_sia_uri(rc))
@@ -865,7 +931,9 @@ class CA(models.Model):
         CA, then finally delete this CA itself.
         """
 
-        publisher = rpki.rpkid.publication_queue(rpkid)
+        trace_call_chain()
+
+        publisher = rpki.rpkid.publication_queue(rpkid = rpkid)
 
         for ca_detail in self.ca_details.all():
             ca_detail.destroy(ca = self, publisher = publisher, allow_failure = True)
@@ -886,6 +954,7 @@ class CA(models.Model):
         Allocate a certificate serial number.
         """
 
+        trace_call_chain()
         self.last_issued_sn += 1
         self.save()
         return self.last_issued_sn
@@ -896,6 +965,7 @@ class CA(models.Model):
         Allocate a manifest serial number.
         """
 
+        trace_call_chain()
         self.last_manifest_sn += 1
         self.save()
         return self.last_manifest_sn
@@ -906,6 +976,7 @@ class CA(models.Model):
         Allocate a CRL serial number.
         """
 
+        trace_call_chain()
         self.last_crl_sn += 1
         self.save()
         return self.last_crl_sn
@@ -920,6 +991,7 @@ class CA(models.Model):
         the new ca_detail.
         """
 
+        trace_call_chain()
         try:
             old_detail = self.ca_details.get(state = "active")
         except CADetail.DoesNotExist:
@@ -944,29 +1016,31 @@ class CA(models.Model):
 
 
     @tornado.gen.coroutine
-    def revoke(self, revoke_all = False):
+    def revoke(self, rpkid, revoke_all = False):
         """
         Revoke deprecated ca_detail objects associated with this CA, or
         all ca_details associated with this CA if revoke_all is set.
         """
 
+        trace_call_chain()
         if revoke_all:
             ca_details = self.ca_details.all()
         else:
             ca_details = self.ca_details.filter(state = "deprecated")
 
-        yield [ca_detail.revoke() for ca_detail in ca_details]
+        yield [ca_detail.revoke(rpkid = rpkid) for ca_detail in ca_details]
 
 
     @tornado.gen.coroutine
-    def reissue(self):
+    def reissue(self, rpkid):
         """
         Reissue all current certificates issued by this CA.
         """
 
+        trace_call_chain()
         ca_detail = self.ca_details.get(state = "active")
         if ca_detail:
-            yield ca_detail.reissue()
+            yield ca_detail.reissue(rpkid = rpkid)
 
 
 class CADetail(models.Model):
@@ -1041,7 +1115,8 @@ class CADetail(models.Model):
         Activate this ca_detail.
         """
 
-        publisher = rpki.rpkid.publication_queue(rpkid)
+        trace_call_chain()
+        publisher = rpki.rpkid.publication_queue(rpkid = rpkid)
         self.latest_ca_cert = cert
         self.ca_cert_uri = uri
         self.generate_manifest_cert()
@@ -1073,6 +1148,7 @@ class CADetail(models.Model):
         raise an exception.
         """
 
+        trace_call_chain()
         repository = ca.parent.repository
         handler = False if allow_failure else None
         for child_cert in self.child_certs.all():
@@ -1117,6 +1193,8 @@ class CADetail(models.Model):
           time has passed.
         """
 
+        trace_call_chain()
+
         gski = self.latest_ca_cert.gSKI()
 
         logger.debug("Asking parent to revoke CA certificate matching g(SKI) = %s", gski)
@@ -1142,7 +1220,7 @@ class CADetail(models.Model):
         if self.latest_crl is not None:
             nextUpdate = nextUpdate.later(self.latest_crl.getNextUpdate())
 
-        publisher = rpki.rpkid.publication_queue(rpkid)
+        publisher = rpki.rpkid.publication_queue(rpkid = rpkid)
 
         for child_cert in self.child_certs.all():
             nextUpdate = nextUpdate.later(child_cert.cert.getNotAfter())
@@ -1177,6 +1255,8 @@ class CADetail(models.Model):
         children of this ca_detail.
         """
 
+        trace_call_chain()
+
         logger.debug("Sending issue request to %r from %r", parent, self.update)
 
         r_msg = yield parent.up_down_issue_query(rpkid = rpkid, ca = ca, ca_detail = self)
@@ -1194,7 +1274,7 @@ class CADetail(models.Model):
 
         validity_changed = self.latest_ca_cert is None or self.latest_ca_cert.getNotAfter() != cert.getNotAfter()
 
-        publisher = rpki.rpkid.publication_queue(rpkid)
+        publisher = rpki.rpkid.publication_queue(rpkid = rpkid)
 
         if self.latest_ca_cert != cert:
             self.latest_ca_cert = cert
@@ -1228,6 +1308,7 @@ class CADetail(models.Model):
         Create a new ca_detail object for a specified CA.
         """
 
+        trace_call_chain()
         cer_keypair = rpki.x509.RSA.generate()
         mft_keypair = rpki.x509.RSA.generate()
         return cls.objects.create(
@@ -1245,6 +1326,7 @@ class CADetail(models.Model):
         Issue a new EE certificate.
         """
 
+        trace_call_chain()
         if notAfter is None:
             notAfter = self.latest_ca_cert.getNotAfter()
         return self.latest_ca_cert.issue(
@@ -1267,6 +1349,7 @@ class CADetail(models.Model):
         Generate a new manifest certificate for this ca_detail.
         """
 
+        trace_call_chain()
         resources = rpki.resource_set.resource_bag.from_inheritance()
         self.latest_manifest_cert = self.issue_ee(
             ca          = self.ca,
@@ -1283,6 +1366,7 @@ class CADetail(models.Model):
         containing the newly issued cert.
         """
 
+        trace_call_chain()
         self.check_failed_publication(publisher)
         cert = self.latest_ca_cert.issue(
             keypair     = self.private_key_id,
@@ -1322,6 +1406,7 @@ class CADetail(models.Model):
         new CRL is needed.
         """
 
+        trace_call_chain()
         self.check_failed_publication(publisher)
         crl_interval = rpki.sundial.timedelta(seconds = self.ca.parent.tenant.crl_interval)
         now = rpki.sundial.now()
@@ -1357,6 +1442,7 @@ class CADetail(models.Model):
         Check result of CRL publication.
         """
 
+        trace_call_chain()
         rpki.publication.raise_if_error(pdu)
         self.crl_published = None
         self.save()
@@ -1367,6 +1453,8 @@ class CADetail(models.Model):
         Generate a new manifest for this ca_detail.
         """
 
+        trace_call_chain()
+
         self.check_failed_publication(publisher)
 
         crl_interval = rpki.sundial.timedelta(seconds = self.ca.parent.tenant.crl_interval)
@@ -1412,6 +1500,7 @@ class CADetail(models.Model):
         Check result of manifest publication.
         """
 
+        trace_call_chain()
         rpki.publication.raise_if_error(pdu)
         self.manifest_published = None
         self.save()
@@ -1423,7 +1512,8 @@ class CADetail(models.Model):
         Reissue all current certificates issued by this ca_detail.
         """
 
-        publisher = rpki.rpkid.publication_queue(rpkid)
+        trace_call_chain()
+        publisher = rpki.rpkid.publication_queue(rpkid = rpkid)
         self.check_failed_publication(publisher)
         for roa in self.roas.all():
             roa.regenerate(publisher, fast = True)
@@ -1466,6 +1556,8 @@ class CADetail(models.Model):
         should become configurable.
         """
 
+        trace_call_chain()
+
         logger.debug("Checking for failed publication for %r", self)
 
         stale = rpki.sundial.now() - rpki.sundial.timedelta(seconds = 60)
@@ -1535,7 +1627,8 @@ class Child(models.Model):
 
     @tornado.gen.coroutine
     def xml_pre_delete_hook(self, rpkid):
-        publisher = rpki.rpkid.publication_queue(rpkid)
+        trace_call_chain()
+        publisher = rpki.rpkid.publication_queue(rpkid = rpkid)
         for child_cert in self.child_certs.all():
             child_cert.revoke(publisher = publisher, generate_crl_and_manifest = True)
         yield publisher.call_pubd()
@@ -1543,20 +1636,23 @@ class Child(models.Model):
 
     @tornado.gen.coroutine
     def xml_post_save_hook(self, rpkid, q_pdu):
+        trace_call_chain()
         if q_pdu.get("clear_replay_protection"):
             self.clear_replay_protection()
         if q_pdu.get("reissue"):
-            yield self.serve_reissue(rpkid)
+            yield self.serve_reissue(rpkid = rpkid)
 
 
     def serve_reissue(self, rpkid):
-        publisher = rpki.rpkid.publication_queue(rpkid)
+        trace_call_chain()
+        publisher = rpki.rpkid.publication_queue(rpkid = rpkid)
         for child_cert in self.child_certs.all():
             child_cert.reissue(child_cert.ca_detail, publisher, force = True)
         yield publisher.call_pubd()
 
 
     def clear_replay_protection(self):
+        trace_call_chain()
         self.last_cms_timestamp = None
         self.save()
 
@@ -1564,6 +1660,8 @@ class Child(models.Model):
     @tornado.gen.coroutine
     def up_down_handle_list(self, rpkid, q_msg, r_msg):
 
+        trace_call_chain()
+
         irdb_resources = yield rpkid.irdb_query_child_resources(self.tenant.tenant_handle, self.child_handle)
 
         if irdb_resources.valid_until < rpki.sundial.now():
@@ -1596,6 +1694,8 @@ class Child(models.Model):
     @tornado.gen.coroutine
     def up_down_handle_issue(self, rpkid, q_msg, r_msg):
 
+        trace_call_chain()
+
         req = q_msg[0]
         assert req.tag == rpki.up_down.tag_request
 
@@ -1623,7 +1723,7 @@ class Child(models.Model):
 
         # Generate new cert or regenerate old one if necessary
 
-        publisher = rpki.rpkid.publication_queue(rpkid)
+        publisher = rpki.rpkid.publication_queue(rpkid = rpkid)
 
         try:
             child_cert = self.child_certs.get(ca_detail = ca_detail, gski = req_key.gSKI())
@@ -1660,10 +1760,11 @@ class Child(models.Model):
 
     @tornado.gen.coroutine
     def up_down_handle_revoke(self, rpkid, q_msg, r_msg):
+        trace_call_chain()
         key = q_msg[0]
         assert key.tag == rpki.up_down.tag_key
         class_name = key.get("class_name")
-        publisher = rpki.rpkid.publication_queue(rpkid)
+        publisher = rpki.rpkid.publication_queue(rpkid = rpkid)
         for child_cert in ChildCert.objects.filter(ca_detail__ca__parent__tenant = self.tenant,
                                                    ca_detail__ca__parent_resource_class = class_name,
                                                    gski = key.get("ski")):
@@ -1678,6 +1779,8 @@ class Child(models.Model):
         Outer layer of server handling for one up-down PDU from this child.
         """
 
+        trace_call_chain()
+
         if self.bsc is None:
             raise rpki.exceptions.BSCNotFound("Could not find BSC")
 
@@ -1736,6 +1839,7 @@ class ChildCert(models.Model):
         Revoke a child cert.
         """
 
+        trace_call_chain()
         ca_detail = self.ca_detail
         logger.debug("Revoking %r %r", self, self.uri)
         RevokedCert.revoke(cert = self.cert, ca_detail = ca_detail)
@@ -1756,6 +1860,7 @@ class ChildCert(models.Model):
         updated child_cert_obj must use the return value from this method.
         """
 
+        trace_call_chain()
         ca = ca_detail.ca
         child = self.child
         old_resources = self.cert.get_3779resources()
@@ -1817,6 +1922,7 @@ class ChildCert(models.Model):
         Publication callback: check result and mark published.
         """
 
+        trace_call_chain()
         rpki.publication.raise_if_error(pdu)
         self.published = None
         self.save()
@@ -1855,6 +1961,8 @@ class EECertificate(models.Model):
         Generate a new EE certificate.
         """
 
+        trace_call_chain()
+
         # The low-level X.509 code really ought to supply the singleton
         # tuple wrapper when handed a string, but that yak will need to
         # wait until another day for its shave.
@@ -1889,6 +1997,7 @@ class EECertificate(models.Model):
         Revoke and withdraw an EE certificate.
         """
 
+        trace_call_chain()
         ca_detail = self.ca_detail
         logger.debug("Revoking %r %r", self, self.uri)
         RevokedCert.revoke(cert = self.cert, ca_detail = ca_detail)
@@ -1908,6 +2017,7 @@ class EECertificate(models.Model):
         changed.
         """
 
+        trace_call_chain()
         needed = False
         old_cert = self.cert
         old_ca_detail = self.ca_detail
@@ -1969,6 +2079,7 @@ class EECertificate(models.Model):
         Publication callback: check result and mark published.
         """
 
+        trace_call_chain()
         rpki.publication.raise_if_error(pdu)
         self.published = None
         self.save()
@@ -1989,6 +2100,8 @@ class Ghostbuster(models.Model):
         Bring this ghostbuster_obj up to date if necesssary.
         """
 
+        trace_call_chain()
+
         if self.ghostbuster is None:
             logger.debug("Ghostbuster record doesn't exist, generating")
             return self.generate(publisher = publisher, fast = fast)
@@ -2022,6 +2135,7 @@ class Ghostbuster(models.Model):
         caller to handle, presumably at the end of a bulk operation.
         """
 
+        trace_call_chain()
         resources = rpki.resource_set.resource_bag.from_inheritance()
         keypair = rpki.x509.RSA.generate()
         self.cert = self.ca_detail.issue_ee(
@@ -2047,6 +2161,7 @@ class Ghostbuster(models.Model):
         Check publication result.
         """
 
+        trace_call_chain()
         rpki.publication.raise_if_error(pdu)
         self.published = None
         self.save()
@@ -2068,6 +2183,7 @@ class Ghostbuster(models.Model):
         flushing the SQL cache.
         """
 
+        trace_call_chain()
         ca_detail = self.ca_detail
         logger.debug("%s %r, ca_detail %r state is %s",
                      "Regenerating" if regenerate else "Not regenerating",
@@ -2092,6 +2208,7 @@ class Ghostbuster(models.Model):
         Reissue Ghostbuster associated with this ghostbuster_obj.
         """
 
+        trace_call_chain()
         if self.ghostbuster is None:
             self.generate(publisher = publisher, fast = fast)
         else:
@@ -2103,6 +2220,7 @@ class Ghostbuster(models.Model):
         Return publication URI for a public key.
         """
 
+        trace_call_chain()
         return self.ca_detail.ca.sia_uri + key.gSKI() + ".gbr"
 
 
@@ -2137,6 +2255,7 @@ class RevokedCert(models.Model):
         Revoke a certificate.
         """
 
+        trace_call_chain()
         return cls.objects.create(
             serial    = cert.getSerial(),
             expires   = cert.getNotAfter(),
@@ -2160,6 +2279,8 @@ class ROA(models.Model):
         Bring ROA up to date if necesssary.
         """
 
+        trace_call_chain()
+
         if self.roa is None:
             logger.debug("%r doesn't exist, generating", self)
             return self.generate(publisher = publisher, fast = fast)
@@ -2222,6 +2343,8 @@ class ROA(models.Model):
         caller to handle, presumably at the end of a bulk operation.
         """
 
+        trace_call_chain()
+
         if self.ipv4 is None and self.ipv6 is None:
             raise rpki.exceptions.EmptyROAPrefixList
 
@@ -2277,6 +2400,7 @@ class ROA(models.Model):
         Check publication result.
         """
 
+        trace_call_chain()
         rpki.publication.raise_if_error(pdu)
         self.published = None
         self.save()
@@ -2298,6 +2422,7 @@ class ROA(models.Model):
         flushing the SQL cache.
         """
 
+        trace_call_chain()
         ca_detail = self.ca_detail
         logger.debug("%s %r, ca_detail %r state is %s",
                      "Regenerating" if regenerate else "Not regenerating",
@@ -2321,6 +2446,7 @@ class ROA(models.Model):
         Reissue ROA associated with this roa_obj.
         """
 
+        trace_call_chain()
         if self.ca_detail is None:
             self.generate(publisher = publisher, fast = fast)
         else:
@@ -2332,6 +2458,7 @@ class ROA(models.Model):
         Return publication URI for a public key.
         """
 
+        trace_call_chain()
         return self.ca_detail.ca.sia_uri + key.gSKI() + ".roa"
 
 
diff --git a/rpki/rtr/channels.py b/rpki/rtr/channels.py
index e2f443e8..df96fa58 100644
--- a/rpki/rtr/channels.py
+++ b/rpki/rtr/channels.py
@@ -125,7 +125,7 @@ class ReadBuffer(object):
         if self.version is None and version not in rpki.rtr.pdus.PDU.version_map:
             raise rpki.rtr.pdus.UnsupportedProtocolVersion(
                 "Received PDU version %s, known versions %s" % (
-                version, ", ".join(str(v) for v in rpki.rtr.pdus.PDU.version_map)))
+                    version, ", ".join(str(v) for v in rpki.rtr.pdus.PDU.version_map)))
         self.version = version
 
 
diff --git a/rpki/rtr/pdus.py b/rpki/rtr/pdus.py
index 94f579a1..d355026c 100644
--- a/rpki/rtr/pdus.py
+++ b/rpki/rtr/pdus.py
@@ -573,16 +573,16 @@ class ErrorReportPDU(PDU):
     string_struct = struct.Struct("!L")
 
     errors = {
-      2 : "No Data Available" }
+        2 : "No Data Available" }
 
     fatal = {
-      0 : "Corrupt Data",
-      1 : "Internal Error",
-      3 : "Invalid Request",
-      4 : "Unsupported Protocol Version",
-      5 : "Unsupported PDU Type",
-      6 : "Withdrawal of Unknown Record",
-      7 : "Duplicate Announcement Received" }
+        0 : "Corrupt Data",
+        1 : "Internal Error",
+        3 : "Invalid Request",
+        4 : "Unsupported Protocol Version",
+        5 : "Unsupported PDU Type",
+        6 : "Withdrawal of Unknown Record",
+        7 : "Duplicate Announcement Received" }
 
     assert set(errors) & set(fatal) == set()
 
diff --git a/rpki/up_down.py b/rpki/up_down.py
index cfe86714..e2292efb 100644
--- a/rpki/up_down.py
+++ b/rpki/up_down.py
@@ -55,6 +55,7 @@ tag_certificate = xmlns + "certificate"
 tag_class       = xmlns + "class"
 tag_description = xmlns + "description"
 tag_issuer      = xmlns + "issuer"
+tag_key         = xmlns + "key"
 tag_message     = xmlns + "message"
 tag_request     = xmlns + "request"
 tag_status      = xmlns + "status"
@@ -92,22 +93,22 @@ class multi_uri(list):
 
 
 error_response_codes = {
-  1101 : "Already processing request",
-  1102 : "Version number error",
-  1103 : "Unrecognised request type",
-  1201 : "Request - no such resource class",
-  1202 : "Request - no resources allocated in resource class",
-  1203 : "Request - badly formed certificate request",
-  1301 : "Revoke - no such resource class",
-  1302 : "Revoke - no such key",
-  2001 : "Internal Server Error - Request not performed" }
+    1101 : "Already processing request",
+    1102 : "Version number error",
+    1103 : "Unrecognised request type",
+    1201 : "Request - no such resource class",
+    1202 : "Request - no resources allocated in resource class",
+    1203 : "Request - badly formed certificate request",
+    1301 : "Revoke - no such resource class",
+    1302 : "Revoke - no such key",
+    2001 : "Internal Server Error - Request not performed" }
 
 
 exception_map = {
-  rpki.exceptions.NoActiveCA                    : 1202,
-  (rpki.exceptions.ClassNameUnknown, "revoke")  : 1301,
-  rpki.exceptions.ClassNameUnknown              : 1201,
-  (rpki.exceptions.NotInDatabase,    "revoke")  : 1302 }
+    rpki.exceptions.NoActiveCA                    : 1202,
+    (rpki.exceptions.ClassNameUnknown, "revoke")  : 1301,
+    rpki.exceptions.ClassNameUnknown              : 1201,
+    (rpki.exceptions.NotInDatabase,    "revoke")  : 1302 }
 
 
 def check_response(r_msg, q_type):
diff --git a/rpki/x509.py b/rpki/x509.py
index d904bb0f..32bedc6a 100644
--- a/rpki/x509.py
+++ b/rpki/x509.py
@@ -2007,7 +2007,7 @@ class XML_CMS_object(Wrapped_CMS_object):
                 context = " (" + " ".join(context) + ")"
             raise rpki.exceptions.CMSReplay(
                 "CMS replay: last message %s, this message %s%s" % (
-                timestamp, new_timestamp, context))
+                    timestamp, new_timestamp, context))
         return new_timestamp
 
     def check_replay_sql(self, obj, *context):
@@ -2148,13 +2148,12 @@ class CRL(DER_object):
 # Map of known URI filename extensions and corresponding classes.
 
 uri_dispatch_map = {
-  ".cer" : X509,
-  ".crl" : CRL,
-  ".gbr" : Ghostbuster,
-  ".mft" : SignedManifest,
-  ".mnf" : SignedManifest,
-  ".roa" : ROA,
-  }
+    ".cer" : X509,
+    ".crl" : CRL,
+    ".gbr" : Ghostbuster,
+    ".mft" : SignedManifest,
+    ".mnf" : SignedManifest,
+    ".roa" : ROA }
 
 def uri_dispatch(uri):
     """