diff options
| -rw-r--r-- | ca/tests/smoketest.py | 125 | ||||
| -rw-r--r-- | rpki/adns.py | 11 | ||||
| -rw-r--r-- | rpki/async.py | 53 | ||||
| -rw-r--r-- | rpki/config.py | 9 | ||||
| -rw-r--r-- | rpki/daemonize.py | 5 | ||||
| -rw-r--r-- | rpki/http.py | 8 | ||||
| -rw-r--r-- | rpki/irdbd.py | 7 | ||||
| -rw-r--r-- | rpki/left_right.py | 17 | ||||
| -rw-r--r-- | rpki/log.py | 27 | ||||
| -rw-r--r-- | rpki/old_irdbd.py | 5 | ||||
| -rw-r--r-- | rpki/pubd.py | 7 | ||||
| -rw-r--r-- | rpki/publication.py | 7 | ||||
| -rw-r--r-- | rpki/rootd.py | 41 | ||||
| -rw-r--r-- | rpki/rpkid.py | 181 | ||||
| -rw-r--r-- | rpki/rpkid_tasks.py | 109 | ||||
| -rw-r--r-- | rpki/sql.py | 23 | ||||
| -rw-r--r-- | rpki/up_down.py | 27 | ||||
| -rw-r--r-- | rpki/x509.py | 47 |
18 files changed, 380 insertions, 329 deletions
diff --git a/ca/tests/smoketest.py b/ca/tests/smoketest.py index 1ff47aef..42e259e6 100644 --- a/ca/tests/smoketest.py +++ b/ca/tests/smoketest.py @@ -37,6 +37,7 @@ import yaml import subprocess import signal import time +import logging import argparse import sys import errno @@ -52,6 +53,8 @@ import rpki.async from rpki.mysql_import import MySQLdb +logger = logging.getLogger(__name__) + os.environ["TZ"] = "UTC" time.tzset() @@ -157,7 +160,7 @@ def main(): """ rpki.log.init(smoketest_name) - rpki.log.info("Starting") + logger.info("Starting") pubd_process = None rootd_process = None @@ -167,7 +170,7 @@ def main(): irdb_sql = mangle_sql(irdb_sql_file) pubd_sql = mangle_sql(pub_sql_file) - rpki.log.info("Initializing test directory") + logger.info("Initializing test directory") # Connect to test directory, creating it if necessary try: @@ -198,16 +201,16 @@ def main(): else: raise - rpki.log.info("Reading master YAML configuration") + logger.info("Reading master YAML configuration") y = yaml_script.pop(0) - rpki.log.info("Constructing internal allocation database") + logger.info("Constructing internal allocation database") db = allocation_db(y) - rpki.log.info("Constructing BPKI keys and certs for rootd") + logger.info("Constructing BPKI keys and certs for rootd") setup_bpki_cert_chain(rootd_name, ee = ("RPKI",)) - rpki.log.info("Constructing BPKI keys and certs for pubd") + logger.info("Constructing BPKI keys and certs for pubd") setup_bpki_cert_chain(pubd_name, ee = ("PUBD", "IRBE")) @@ -226,14 +229,14 @@ def main(): try: - rpki.log.info("Starting rootd") + logger.info("Starting rootd") rootd_process = subprocess.Popen((prog_python, prog_rootd, "--foreground", "--log-stderr", "--config", rootd_name + ".conf")) - rpki.log.info("Starting pubd") + logger.info("Starting pubd") pubd_process = subprocess.Popen((prog_python, prog_pubd, "--foreground", "--log-stderr", "--config", pubd_name + ".conf") + (("-p", pubd_name + ".prof") if args.profile else ())) - rpki.log.info("Starting rsyncd") + logger.info("Starting rsyncd") rsyncd_process = subprocess.Popen((prog_rsyncd, "--daemon", "--no-detach", "--config", rsyncd_name + ".conf")) # Start rpkid and irdbd instances @@ -259,7 +262,7 @@ def main(): # This is probably where we should be updating expired BPKI # objects, particular CRLs - rpki.log.info("Running cron for all RPKI engines") + logger.info("Running cron for all RPKI engines") rpki.async.iterator(db.engines, run_cron, run_yaml) def run_cron(iterator, a): @@ -272,10 +275,10 @@ def main(): # Apply next delta if we have one; otherwise, we're done. if yaml_script: - rpki.log.info("Applying deltas") + logger.info("Applying deltas") db.apply_delta(yaml_script.pop(0), apply_delta_done) else: - rpki.log.info("No more deltas to apply, done") + logger.info("No more deltas to apply, done") rpki.async.exit_event_loop() def apply_delta_done(): @@ -287,22 +290,22 @@ def main(): # Loop until we run out of control YAML yaml_loop() - rpki.log.info("Sleeping %d seconds while daemons start up" % startup_delay) + logger.info("Sleeping %d seconds while daemons start up" % startup_delay) rpki.async.timer(start).set(rpki.sundial.timedelta(seconds = startup_delay)) rpki.async.event_loop() # At this point we have gone into event-driven code. - rpki.log.info("Event loop exited normally") + logger.info("Event loop exited normally") except Exception, e: - rpki.log.info("Event loop exited with an exception: %r" % e) + logger.info("Event loop exited with an exception: %r" % e) rpki.log.traceback() finally: - rpki.log.info("Cleaning up") + logger.info("Cleaning up") for a in db.engines: a.kill_daemons() for proc, name in ((rootd_process, "rootd"), @@ -310,20 +313,20 @@ def main(): (rsyncd_process, "rsyncd")): # pylint: disable=E1103 if proc is not None and proc.poll() is None: - rpki.log.info("Killing %s, pid %s" % (name, proc.pid)) + logger.info("Killing %s, pid %s" % (name, proc.pid)) try: proc.terminate() except OSError: pass if proc is not None: - rpki.log.info("Daemon %s, pid %s exited with code %s" % (name, proc.pid, proc.wait())) + logger.info("Daemon %s, pid %s exited with code %s" % (name, proc.pid, proc.wait())) def cmd_sleep(cb, interval): """ Set an alarm, then wait for it to go off. """ howlong = rpki.sundial.timedelta.parse(interval) - rpki.log.info("Sleeping %r" % howlong) + logger.info("Sleeping %r" % howlong) rpki.async.timer(cb).set(howlong) def cmd_shell(cb, *cmd): @@ -332,14 +335,14 @@ def cmd_shell(cb, *cmd): """ cmd = " ".join(cmd) status = subprocess.call(cmd, shell = True) - rpki.log.info("Shell command returned status %d" % status) + logger.info("Shell command returned status %d" % status) cb() def cmd_echo(cb, *words): """ Echo some text to the log. """ - rpki.log.info(" ".join(words)) + logger.info(" ".join(words)) cb() ## @var cmds @@ -546,7 +549,7 @@ class allocation(object): Apply deltas to this entity. """ - rpki.log.info("Applying delta: %s" % yaml) + logger.info("Applying delta: %s" % yaml) def loop(iterator, kv): if kv[0] == "name": @@ -633,11 +636,11 @@ class allocation(object): cb() if target is None: - rpki.log.info("Rekeying <self/> %s" % self.name) + logger.info("Rekeying <self/> %s" % self.name) self.call_rpkid([rpki.left_right.self_elt.make_pdu( action = "set", self_handle = self.name, rekey = "yes")], cb = done) else: - rpki.log.info("Rekeying <parent/> %s %s" % (self.name, target)) + logger.info("Rekeying <parent/> %s %s" % (self.name, target)) self.call_rpkid([rpki.left_right.parent_elt.make_pdu( action = "set", self_handle = self.name, parent_handle = target, rekey = "yes")], cb = done) @@ -650,11 +653,11 @@ class allocation(object): cb() if target is None: - rpki.log.info("Revoking <self/> %s" % self.name) + logger.info("Revoking <self/> %s" % self.name) self.call_rpkid([rpki.left_right.self_elt.make_pdu( action = "set", self_handle = self.name, revoke = "yes")], cb = done) else: - rpki.log.info("Revoking <parent/> %s %s" % (self.name, target)) + logger.info("Revoking <parent/> %s %s" % (self.name, target)) self.call_rpkid([rpki.left_right.parent_elt.make_pdu( action = "set", self_handle = self.name, parent_handle = target, revoke = "yes")], cb = done) @@ -709,7 +712,7 @@ class allocation(object): """ Create BPKI certificates for this entity. """ - rpki.log.info("Constructing BPKI keys and certs for %s" % self.name) + logger.info("Constructing BPKI keys and certs for %s" % self.name) setup_bpki_cert_chain(name = self.name, ee = ("RPKI", "IRDB", "IRBE"), ca = ("SELF",)) @@ -722,7 +725,7 @@ class allocation(object): """ Write config files for this entity. """ - rpki.log.info("Writing config files for %s" % self.name) + logger.info("Writing config files for %s" % self.name) assert self.rpki_port is not None d = { "my_name" : self.name, "irdb_db_name" : self.irdb_db_name, @@ -741,7 +744,7 @@ class allocation(object): """ Set up this entity's IRDB. """ - rpki.log.info("Setting up MySQL for %s" % self.name) + logger.info("Setting up MySQL for %s" % self.name) db = MySQLdb.connect(user = "rpki", db = self.rpki_db_name, passwd = rpki_db_pass, conv = sql_conversions) cur = db.cursor() @@ -775,7 +778,7 @@ class allocation(object): once during setup, then do it again every time we apply a delta to this entity. """ - rpki.log.info("Updating MySQL data for IRDB %s" % self.name) + logger.info("Updating MySQL data for IRDB %s" % self.name) db = MySQLdb.connect(user = "irdb", db = self.irdb_db_name, passwd = irdb_db_pass, conv = sql_conversions) cur = db.cursor() @@ -828,7 +831,7 @@ class allocation(object): """ Run daemons for this entity. """ - rpki.log.info("Running daemons for %s" % self.name) + logger.info("Running daemons for %s" % self.name) self.rpkid_process = subprocess.Popen((prog_python, prog_rpkid, "--foreground", "--log-stderr", "--config", self.name + ".conf") + (("--profile", self.name + ".prof") if args.profile else ())) self.irdbd_process = subprocess.Popen((prog_python, prog_irdbd, "--foreground", "--log-stderr", "--config", self.name + ".conf")) @@ -841,13 +844,13 @@ class allocation(object): for proc, name in ((self.rpkid_process, "rpkid"), (self.irdbd_process, "irdbd")): if proc is not None and proc.poll() is None: - rpki.log.info("Killing daemon %s pid %s for %s" % (name, proc.pid, self.name)) + logger.info("Killing daemon %s pid %s for %s" % (name, proc.pid, self.name)) try: proc.terminate() except OSError: pass if proc is not None: - rpki.log.info("Daemon %s pid %s for %s exited with code %s" % ( + logger.info("Daemon %s pid %s for %s exited with code %s" % ( name, proc.pid, self.name, proc.wait())) def call_rpkid(self, pdus, cb): @@ -859,10 +862,10 @@ class allocation(object): of this happens with the hosting RPKI daemon. """ - rpki.log.info("Calling rpkid for %s" % self.name) + logger.info("Calling rpkid for %s" % self.name) if self.is_hosted: - rpki.log.info("rpkid %s is hosted by rpkid %s, switching" % (self.name, self.hosted_by.name)) + logger.info("rpkid %s is hosted by rpkid %s, switching" % (self.name, self.hosted_by.name)) self = self.hosted_by assert not self.is_hosted @@ -874,14 +877,14 @@ class allocation(object): q_der = q_cms.wrap(q_msg, self.irbe_key, self.irbe_cert) q_url = "http://localhost:%d/left-right" % self.rpki_port - rpki.log.debug(q_cms.pretty_print_content()) + logger.debug(q_cms.pretty_print_content()) def done(r_der): - rpki.log.info("Callback from rpkid %s" % self.name) + logger.info("Callback from rpkid %s" % self.name) r_cms = rpki.left_right.cms_msg(DER = r_der) r_msg = r_cms.unwrap((self.rpkid_ta, self.rpkid_cert)) self.last_cms_time = r_cms.check_replay(self.last_cms_time, q_url) - rpki.log.debug(r_cms.pretty_print_content()) + logger.debug(r_cms.pretty_print_content()) assert r_msg.is_reply for r_pdu in r_msg: assert not isinstance(r_pdu, rpki.left_right.report_error_elt) @@ -908,7 +911,7 @@ class allocation(object): certifier = self.name + "-SELF" certfile = certifier + "-" + certificant + ".cer" - rpki.log.info("Cross certifying %s into %s's BPKI (%s)" % (certificant, certifier, certfile)) + logger.info("Cross certifying %s into %s's BPKI (%s)" % (certificant, certifier, certfile)) child = rpki.x509.X509(Auto_file = certificant + ".cer") parent = rpki.x509.X509(Auto_file = certifier + ".cer") @@ -941,9 +944,9 @@ class allocation(object): f.write(x.get_PEM()) f.close() - rpki.log.debug("Cross certified %s:" % certfile) - rpki.log.debug(" Issuer %s [%s]" % (x.getIssuer(), x.hAKI())) - rpki.log.debug(" Subject %s [%s]" % (x.getSubject(), x.hSKI())) + logger.debug("Cross certified %s:" % certfile) + logger.debug(" Issuer %s [%s]" % (x.getIssuer(), x.hAKI())) + logger.debug(" Subject %s [%s]" % (x.getSubject(), x.hSKI())) return x def create_rpki_objects(self, cb): @@ -964,7 +967,7 @@ class allocation(object): selves = [self] + self.hosts for i, s in enumerate(selves): - rpki.log.info("Creating RPKI objects for [%d] %s" % (i, s.name)) + logger.info("Creating RPKI objects for [%d] %s" % (i, s.name)) rpkid_pdus = [] pubd_pdus = [] @@ -1050,18 +1053,18 @@ class allocation(object): for s in selves: b = bsc_dict[s.name] - rpki.log.info("Issuing BSC EE cert for %s" % s.name) + logger.info("Issuing BSC EE cert for %s" % s.name) cmd = (prog_openssl, "x509", "-req", "-sha256", "-extfile", s.name + "-RPKI.conf", "-extensions", "req_x509_ext", "-days", "30", "-CA", s.name + "-SELF.cer", "-CAkey", s.name + "-SELF.key", "-CAcreateserial", "-text") signer = subprocess.Popen(cmd, stdin = subprocess.PIPE, stdout = subprocess.PIPE, stderr = subprocess.PIPE) signed = signer.communicate(input = b.pkcs10_request.get_PEM()) if not signed[0]: - rpki.log.warn(signed[1]) + logger.warning(signed[1]) raise CouldntIssueBSCEECertificate, "Couldn't issue BSC EE certificate" s.bsc_ee = rpki.x509.X509(PEM = signed[0]) s.bsc_crl = rpki.x509.CRL(PEM_file = s.name + "-SELF.crl") - rpki.log.info("BSC EE cert for %s SKI %s" % (s.name, s.bsc_ee.hSKI())) + logger.info("BSC EE cert for %s SKI %s" % (s.name, s.bsc_ee.hSKI())) bsc_pdus.append(rpki.left_right.bsc_elt.make_pdu( action = "set", @@ -1094,7 +1097,7 @@ class allocation(object): """ if not os.path.exists(self.name + ".key"): - rpki.log.info("Generating RPKI key for %s" % self.name) + logger.info("Generating RPKI key for %s" % self.name) subprocess.check_call((prog_openssl, "genrsa", "-out", self.name + ".key", "2048" ), stdout = subprocess.PIPE, stderr = subprocess.STDOUT) ski = rpki.x509.RSA(PEM_file = self.name + ".key").gSKI() @@ -1107,7 +1110,7 @@ class allocation(object): self.cross_certify(self.parent.name + "-SELF") self.cross_certify(parent_host + "-TA") - rpki.log.info("Writing leaf YAML for %s" % self.name) + logger.info("Writing leaf YAML for %s" % self.name) f = open(self.name + ".yaml", "w") f.write(yaml_fmt_1 % { "parent_name" : self.parent.name, @@ -1124,7 +1127,7 @@ class allocation(object): Trigger cron run for this engine. """ - rpki.log.info("Running cron for %s" % self.name) + logger.info("Running cron for %s" % self.name) assert self.rpki_port is not None @@ -1146,10 +1149,10 @@ class allocation(object): error, but only issue a warning when issue fails. """ - rpki.log.info("Running YAML for %s" % self.name) + logger.info("Running YAML for %s" % self.name) subprocess.check_call((prog_python, prog_poke, "-y", self.name + ".yaml", "-r", "list")) if subprocess.call((prog_python, prog_poke, "-y", self.name + ".yaml", "-r", "issue")) != 0: - rpki.log.warn("YAML issue command failed for %s, continuing" % self.name) + logger.warning("YAML issue command failed for %s, continuing" % self.name) def setup_bpki_cert_chain(name, ee = (), ca = ()): """ @@ -1183,7 +1186,7 @@ def setup_rootd(rpkid, rootd_yaml): Write the config files for rootd. """ rpkid.cross_certify(rootd_name + "-TA", reverse = True) - rpki.log.info("Writing config files for %s" % rootd_name) + logger.info("Writing config files for %s" % rootd_name) d = { "rootd_name" : rootd_name, "rootd_port" : rootd_port, "rpkid_name" : rpkid.name, @@ -1205,7 +1208,7 @@ def setup_rcynic(): """ Write the config file for rcynic. """ - rpki.log.info("Config file for rcynic") + logger.info("Config file for rcynic") d = { "rcynic_name" : rcynic_name, "rootd_name" : rootd_name, "rootd_sia" : rootd_sia } @@ -1217,7 +1220,7 @@ def setup_rsyncd(): """ Write the config file for rsyncd. """ - rpki.log.info("Config file for rsyncd") + logger.info("Config file for rsyncd") d = { "rsyncd_name" : rsyncd_name, "rsyncd_port" : rsyncd_port, "rsyncd_module" : rsyncd_module, @@ -1230,7 +1233,7 @@ def setup_publication(pubd_sql): """ Set up publication daemon. """ - rpki.log.info("Configure publication daemon") + logger.info("Configure publication daemon") publication_dir = os.getcwd() + "/publication" assert rootd_sia.startswith("rsync://") global rsyncd_dir @@ -1272,27 +1275,27 @@ def call_pubd(pdus, cb): Send a publication message to publication daemon and return the response. """ - rpki.log.info("Calling pubd") + logger.info("Calling pubd") q_msg = rpki.publication.msg.query(*pdus) q_cms = rpki.publication.cms_msg() q_der = q_cms.wrap(q_msg, pubd_irbe_key, pubd_irbe_cert) q_url = "http://localhost:%d/control" % pubd_port - rpki.log.debug(q_cms.pretty_print_content()) + logger.debug(q_cms.pretty_print_content()) def call_pubd_cb(r_der): global pubd_last_cms_time r_cms = rpki.publication.cms_msg(DER = r_der) r_msg = r_cms.unwrap((pubd_ta, pubd_pubd_cert)) pubd_last_cms_time = r_cms.check_replay(pubd_last_cms_time, q_url) - rpki.log.debug(r_cms.pretty_print_content()) + logger.debug(r_cms.pretty_print_content()) assert r_msg.is_reply for r_pdu in r_msg: assert not isinstance(r_pdu, rpki.publication.report_error_elt) cb(r_msg) def call_pubd_eb(e): - rpki.log.warn("Problem calling pubd: %s" % e) + logger.warning("Problem calling pubd: %s" % e) rpki.log.traceback() rpki.http.client( @@ -1307,7 +1310,7 @@ def set_pubd_crl(cb): publication daemon starts talking to its clients, and must be updated whenever we update the CRL. """ - rpki.log.info("Setting pubd's BPKI CRL") + logger.info("Setting pubd's BPKI CRL") crl = rpki.x509.CRL(Auto_file = pubd_name + "-TA.crl") call_pubd([rpki.publication.config_elt.make_pdu(action = "set", bpki_crl = crl)], cb = lambda ignored: cb()) @@ -1317,7 +1320,7 @@ def run_rcynic(): """ Run rcynic to see whether what was published makes sense. """ - rpki.log.info("Running rcynic") + logger.info("Running rcynic") env = os.environ.copy() env["TZ"] = "" global last_rcynic_run diff --git a/rpki/adns.py b/rpki/adns.py index 50841f7f..725463fe 100644 --- a/rpki/adns.py +++ b/rpki/adns.py @@ -22,10 +22,11 @@ Basic asynchronous DNS code, using asyncore and Bob Halley's excellent dnspython package. """ -import asyncore -import socket -import time import sys +import time +import socket +import logging +import asyncore import rpki.async import rpki.sundial import rpki.log @@ -40,6 +41,8 @@ except ImportError: else: raise +logger = logging.getLogger(__name__) + ## @var resolver # Resolver object, shared by everything using this module @@ -66,7 +69,7 @@ for ns in resolver.nameservers: continue except Exception: pass - rpki.log.error("Couldn't parse nameserver address %r" % ns) + logger.error("Couldn't parse nameserver address %r" % ns) class dispatcher(asyncore.dispatcher): """ diff --git a/rpki/async.py b/rpki/async.py index 49f98841..16f85087 100644 --- a/rpki/async.py +++ b/rpki/async.py @@ -18,14 +18,17 @@ Utilities for event-driven programming. """ -import asyncore -import signal -import traceback import gc import sys +import signal +import logging +import asyncore +import traceback import rpki.log import rpki.sundial +logger = logging.getLogger(__name__) + ExitNow = asyncore.ExitNow class iterator(object): @@ -66,7 +69,7 @@ class iterator(object): except (ExitNow, SystemExit): raise except Exception: - rpki.log.debug("Problem constructing iterator for %r" % (iterable,)) + logger.debug("Problem constructing iterator for %r" % (iterable,)) raise self.doit() @@ -130,7 +133,7 @@ class timer(object): """ if self.gc_debug: bt = traceback.extract_stack(limit = 3) - rpki.log.debug("%s from %s:%d" % (msg, bt[0][0], bt[0][1])) + logger.debug("%s from %s:%d" % (msg, bt[0][0], bt[0][1])) def set(self, when): """ @@ -153,7 +156,7 @@ class timer(object): if gc_debug: def __del__(self): - rpki.log.debug("Deleting %r" % self) + logger.debug("Deleting %r" % self) def cancel(self): """ @@ -203,19 +206,19 @@ class timer(object): while timer_queue and now >= timer_queue[0].when: t = timer_queue.pop(0) if cls.run_debug: - rpki.log.debug("Running %r" % t) + logger.debug("Running %r" % t) try: if t.handler is not None: t.handler() else: - rpki.log.warn("Timer %r expired with no handler set" % t) + logger.warning("Timer %r expired with no handler set" % t) except (ExitNow, SystemExit): raise except Exception, e: if t.errback is not None: t.errback(e) else: - rpki.log.error("Unhandled exception from timer %r: %s" % (t, e)) + logger.error("Unhandled exception from timer %r: %s" % (t, e)) rpki.log.traceback() def __repr__(self): @@ -291,14 +294,14 @@ def event_loop(catch_signals = (signal.SIGINT, signal.SIGTERM)): while asyncore.socket_map or timer_queue: t = timer.seconds_until_wakeup() if debug_event_timing: - rpki.log.debug("Dismissing to asyncore.poll(), t = %s, q = %r" % (t, timer_queue)) + logger.debug("Dismissing to asyncore.poll(), t = %s, q = %r" % (t, timer_queue)) asyncore.poll(t, asyncore.socket_map) timer.runq() if timer.gc_debug: gc.collect() if gc.garbage: for i in gc.garbage: - rpki.log.debug("GC-cycle %r" % i) + logger.debug("GC-cycle %r" % i) del gc.garbage[:] except ExitNow: break @@ -306,15 +309,15 @@ def event_loop(catch_signals = (signal.SIGINT, signal.SIGTERM)): raise except ValueError, e: if str(e) == "filedescriptor out of range in select()": - rpki.log.error("Something is badly wrong, select() thinks we gave it a bad file descriptor.") - rpki.log.error("Content of asyncore.socket_map:") + logger.error("Something is badly wrong, select() thinks we gave it a bad file descriptor.") + logger.error("Content of asyncore.socket_map:") for fd in sorted(asyncore.socket_map.iterkeys()): - rpki.log.error(" fd %s obj %r" % (fd, asyncore.socket_map[fd])) - rpki.log.error("Not safe to continue due to risk of spin loop on select(). Exiting.") + logger.error(" fd %s obj %r" % (fd, asyncore.socket_map[fd])) + logger.error("Not safe to continue due to risk of spin loop on select(). Exiting.") sys.exit(1) - rpki.log.error("event_loop() exited with exception %r, this is not supposed to happen, restarting" % e) + logger.error("event_loop() exited with exception %r, this is not supposed to happen, restarting" % e) except Exception, e: - rpki.log.error("event_loop() exited with exception %r, this is not supposed to happen, restarting" % e) + logger.error("event_loop() exited with exception %r, this is not supposed to happen, restarting" % e) else: break finally: @@ -392,9 +395,9 @@ class gc_summary(object): """ Collect and log GC state for this period, reset timer. """ - rpki.log.debug("gc_summary: Running gc.collect()") + logger.debug("gc_summary: Running gc.collect()") gc.collect() - rpki.log.debug("gc_summary: Summarizing (threshold %d)" % self.threshold) + logger.debug("gc_summary: Summarizing (threshold %d)" % self.threshold) total = {} tuples = {} for g in gc.get_objects(): @@ -403,18 +406,18 @@ class gc_summary(object): if isinstance(g, tuple): k = ", ".join(type(x).__name__ for x in g) tuples[k] = tuples.get(k, 0) + 1 - rpki.log.debug("gc_summary: Sorting result") + logger.debug("gc_summary: Sorting result") total = total.items() total.sort(reverse = True, key = lambda x: x[1]) tuples = tuples.items() tuples.sort(reverse = True, key = lambda x: x[1]) - rpki.log.debug("gc_summary: Object type counts in descending order") + logger.debug("gc_summary: Object type counts in descending order") for name, count in total: if count > self.threshold: - rpki.log.debug("gc_summary: %8d %s" % (count, name)) - rpki.log.debug("gc_summary: Tuple content type signature counts in descending order") + logger.debug("gc_summary: %8d %s" % (count, name)) + logger.debug("gc_summary: Tuple content type signature counts in descending order") for types, count in tuples: if count > self.threshold: - rpki.log.debug("gc_summary: %8d (%s)" % (count, types)) - rpki.log.debug("gc_summary: Scheduling next cycle") + logger.debug("gc_summary: %8d (%s)" % (count, types)) + logger.debug("gc_summary: Scheduling next cycle") self.timer.set(self.interval) diff --git a/rpki/config.py b/rpki/config.py index 9f26664e..1b2c3c34 100644 --- a/rpki/config.py +++ b/rpki/config.py @@ -23,9 +23,12 @@ ConfigParser module. """ import ConfigParser +import logging import os import re +logger = logging.getLogger(__name__) + ## @var default_filename # Default name of config file if caller doesn't specify one explictly. @@ -252,14 +255,14 @@ class parser(object): try: rpki.x509.XML_CMS_object.dump_outbound_cms = rpki.x509.DeadDrop(self.get("dump_outbound_cms")) except OSError, e: - rpki.log.warn("Couldn't initialize mailbox %s: %s" % (self.get("dump_outbound_cms"), e)) + logger.warning("Couldn't initialize mailbox %s: %s" % (self.get("dump_outbound_cms"), e)) except ConfigParser.NoOptionError: pass try: rpki.x509.XML_CMS_object.dump_inbound_cms = rpki.x509.DeadDrop(self.get("dump_inbound_cms")) except OSError, e: - rpki.log.warn("Couldn't initialize mailbox %s: %s" % (self.get("dump_inbound_cms"), e)) + logger.warning("Couldn't initialize mailbox %s: %s" % (self.get("dump_inbound_cms"), e)) except ConfigParser.NoOptionError: pass @@ -298,4 +301,4 @@ class parser(object): except ConfigParser.NoOptionError: pass except: - rpki.log.warn("insecure-debug-only-rsa-key-db configured but initialization failed, check for corrupted database file") + logger.warning("insecure-debug-only-rsa-key-db configured but initialization failed, check for corrupted database file") diff --git a/rpki/daemonize.py b/rpki/daemonize.py index 62b4ee4e..6e6f1a42 100644 --- a/rpki/daemonize.py +++ b/rpki/daemonize.py @@ -62,8 +62,11 @@ import sys import os import atexit import signal +import logging import rpki.log +logger = logging.getLogger(__name__) + # Does default_pid_directory need to be autoconf-configurable? ## @var default_pid_directory @@ -130,4 +133,4 @@ def daemon(nochdir = False, noclose = False, pidfile = None): f.write("%d\n" % os.getpid()) f.close() except IOError, e: - rpki.log.warn("Couldn't write PID file %s: %s" % (pidfile, e.strerror)) + logger.warning("Couldn't write PID file %s: %s" % (pidfile, e.strerror)) diff --git a/rpki/http.py b/rpki/http.py index 4436a993..812f45b2 100644 --- a/rpki/http.py +++ b/rpki/http.py @@ -36,6 +36,8 @@ import rpki.exceptions import rpki.log import rpki.POW +logger = logging.getLogger(__name__) + ## @var rpki_content_type # HTTP content type used for all RPKI messages. rpki_content_type = "application/x-rpki" @@ -978,7 +980,7 @@ def client(msg, url, callback, errback): raise rpki.exceptions.BadClientURL, "Unusable URL %s" % url if debug_http: - rpki.log.debug("Contacting %s" % url) + logger.debug("Contacting %s" % url) request = http_request( cmd = "POST", @@ -992,7 +994,7 @@ def client(msg, url, callback, errback): hostport = (u.hostname or "localhost", u.port or default_tcp_port) if debug_http: - rpki.log.debug("Created request %r for %s" % (request, addr_to_string(hostport))) + logger.debug("Created request %r for %s" % (request, addr_to_string(hostport))) if hostport not in client_queues: client_queues[hostport] = http_queue(hostport) client_queues[hostport].request(request) @@ -1001,7 +1003,7 @@ def client(msg, url, callback, errback): # pending I/O events, in case connections have closed. if debug_http: - rpki.log.debug("Scheduling connection startup for %r" % request) + logger.debug("Scheduling connection startup for %r" % request) rpki.async.event_defer(client_queues[hostport].restart) def server(handlers, port, host = ""): diff --git a/rpki/irdbd.py b/rpki/irdbd.py index 850f8ac8..591e345a 100644 --- a/rpki/irdbd.py +++ b/rpki/irdbd.py @@ -24,6 +24,7 @@ IR database daemon. import sys import os import time +import logging import argparse import urlparse import rpki.http @@ -36,6 +37,8 @@ import rpki.log import rpki.x509 import rpki.daemonize +logger = logging.getLogger(__name__) + class main(object): def handle_list_resources(self, q_pdu, r_msg): @@ -177,7 +180,7 @@ class main(object): prof.runcall(self.main) finally: prof.dump_stats(args.profile) - rpki.log.info("Dumped profile data to %s" % args.profile) + logger.info("Dumped profile data to %s" % args.profile) else: self.main() @@ -188,7 +191,7 @@ class main(object): startup_msg = self.cfg.get("startup-message", "") if startup_msg: - rpki.log.info(startup_msg) + logger.info(startup_msg) # Do -not- turn on DEBUG here except for short-lived tests, # otherwise irdbd will eventually run out of memory and crash. diff --git a/rpki/left_right.py b/rpki/left_right.py index 5c1ae106..74ae97d4 100644 --- a/rpki/left_right.py +++ b/rpki/left_right.py @@ -21,6 +21,7 @@ RPKI "left-right" protocol. """ +import logging import rpki.resource_set import rpki.x509 import rpki.sql @@ -35,6 +36,8 @@ import rpki.publication import rpki.async import rpki.rpkid_tasks +logger = logging.getLogger(__name__) + ## @var enforce_strict_up_down_xml_sender # Enforce strict checking of XML "sender" field in up-down protocol @@ -334,7 +337,7 @@ class self_elt(data_elt): """ Handle a left-right run_now action for this self. """ - rpki.log.debug("Forced immediate run of periodic actions for self %s[%d]" % ( + logger.debug("Forced immediate run of periodic actions for self %s[%d]" % ( self.self_handle, self.self_id)) completion = rpki.rpkid_tasks.CompletionHandler(cb) self.schedule_cron_tasks(completion) @@ -550,7 +553,7 @@ class repository_elt(data_elt): handlers = {} for q_pdu in q_msg: - rpki.log.info("Sending %s %s to pubd" % (q_pdu.action, q_pdu.uri)) + logger.info("Sending %s %s to pubd" % (q_pdu.action, q_pdu.uri)) bsc = self.bsc q_der = rpki.publication.cms_msg().wrap(q_msg, bsc.private_key_id, bsc.signing_cert, bsc.signing_cert_crl) @@ -558,14 +561,14 @@ class repository_elt(data_elt): def done(r_der): try: - rpki.log.debug("Received response from pubd") + logger.debug("Received response from pubd") r_cms = rpki.publication.cms_msg(DER = r_der) r_msg = r_cms.unwrap(bpki_ta_path) r_cms.check_replay_sql(self, self.peer_contact_uri) for r_pdu in r_msg: handler = handlers.get(r_pdu.tag, self.default_pubd_handler) if handler: - rpki.log.debug("Calling pubd handler %r" % handler) + logger.debug("Calling pubd handler %r" % handler) handler(r_pdu) if len(q_msg) != len(r_msg): raise rpki.exceptions.BadPublicationReply, "Wrong number of response PDUs from pubd: sent %r, got %r" % (q_msg, r_msg) @@ -575,7 +578,7 @@ class repository_elt(data_elt): except Exception, e: errback(e) - rpki.log.debug("Sending request to pubd") + logger.debug("Sending request to pubd") rpki.http.client( url = self.peer_contact_uri, msg = q_der, @@ -714,7 +717,7 @@ class parent_elt(data_elt): """ def loop(iterator, ski): - rpki.log.debug("Asking parent %r to revoke class %r, SKI %s" % (self, rc_name, ski)) + logger.debug("Asking parent %r to revoke class %r, SKI %s" % (self, rc_name, ski)) q_pdu = rpki.up_down.revoke_pdu() q_pdu.class_name = rc_name q_pdu.ski = ski @@ -767,7 +770,7 @@ class parent_elt(data_elt): self.serve_revoke_forgotten(done, fail) def fail(e): - rpki.log.warn("Trouble getting parent to revoke certificates, blundering onwards: %s" % e) + logger.warning("Trouble getting parent to revoke certificates, blundering onwards: %s" % e) done() def done(): diff --git a/rpki/log.py b/rpki/log.py index 4c4a444c..728cb321 100644 --- a/rpki/log.py +++ b/rpki/log.py @@ -37,6 +37,8 @@ try: except ImportError: pass +logger = logging.getLogger(__name__) + ## @var enable_trace # Whether call tracing is enabled. @@ -171,15 +173,6 @@ def init(ident = "rpki", args = argparse.Namespace(log_level = logging.DEBUG, lo setproctitle.setproctitle(ident) -# Temporary hack during transition. In the long run, other modules -# should call the logging system directly. I think. - -error = logging.error -warn = logging.warning -info = logging.info -debug = logging.debug - - def set_trace(enable): """ Enable or disable call tracing. @@ -191,11 +184,14 @@ def set_trace(enable): def trace(): """ Execution trace -- where are we now, and whence came we here? + + At this point we might be better off using logging's built in + support (pathname, lineno, etc) rather than this ancient hack. """ if enable_trace: 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])) + return logger.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(do_it = None): """ @@ -209,6 +205,11 @@ def traceback(do_it = None): theory that (a) assertion failures are programming errors by definition, and (b) it's often hard to figure out what's triggering a particular assertion failure without the backtrace. + + The logger calls here are arguably wrong, as they use the rpki.log + module's logger object rather than the calling module's logger. + Might need to fix this some day, need to think about what the API + for this should be (just take the logger to use as an argument?). """ if do_it is None: @@ -219,11 +220,11 @@ def traceback(do_it = None): if do_it or isinstance(e, AssertionError): 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])) + logger.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])) bt = tb.format_exc() assert bt is not None, "Apparently I'm still not using the right test for null backtrace" for line in bt.splitlines(): - warn(line) + logger.warning(line) def log_repr(obj, *tokens): """ @@ -245,7 +246,7 @@ def log_repr(obj, *tokens): s = str(token) except: s = "???" - debug("Failed to generate repr() string for object of type %r" % type(token)) + logger.debug("Failed to generate repr() string for object of type %r" % type(token)) traceback() if s: words.append(s) diff --git a/rpki/old_irdbd.py b/rpki/old_irdbd.py index eb901f5d..109fdcfd 100644 --- a/rpki/old_irdbd.py +++ b/rpki/old_irdbd.py @@ -28,6 +28,7 @@ the GUI, rpkic, or any of the other more recent tools. import sys import os import time +import logging import argparse import urlparse import rpki.http @@ -41,6 +42,8 @@ import rpki.x509 from rpki.mysql_import import MySQLdb +logger = logging.getLogger(__name__) + class main(object): @@ -296,7 +299,7 @@ class main(object): startup_msg = self.cfg.get("startup-message", "") if startup_msg: - rpki.log.info(startup_msg) + logger.info(startup_msg) self.cfg.set_global_flags() diff --git a/rpki/pubd.py b/rpki/pubd.py index ec7be81e..0cb4c6fd 100644 --- a/rpki/pubd.py +++ b/rpki/pubd.py @@ -23,6 +23,7 @@ RPKI publication engine. import os import time +import logging import argparse import sys import re @@ -38,6 +39,8 @@ import rpki.log import rpki.publication import rpki.daemonize +logger = logging.getLogger(__name__) + class main(object): """ Main program for pubd. @@ -79,14 +82,14 @@ class main(object): prof.runcall(self.main) finally: prof.dump_stats(self.profile) - rpki.log.info("Dumped profile data to %s" % self.profile) + logger.info("Dumped profile data to %s" % self.profile) else: self.main() def main(self): if self.profile: - rpki.log.info("Running in profile mode with output to %s" % self.profile) + logger.info("Running in profile mode with output to %s" % self.profile) self.sql = rpki.sql.session(self.cfg) diff --git a/rpki/publication.py b/rpki/publication.py index 0c3c5a10..c4ef8b44 100644 --- a/rpki/publication.py +++ b/rpki/publication.py @@ -34,6 +34,7 @@ RPKI "publication" protocol. import os import errno +import logging import rpki.resource_set import rpki.x509 import rpki.sql @@ -45,6 +46,8 @@ import rpki.relaxng import rpki.sundial import rpki.log +logger = logging.getLogger(__name__) + class publication_namespace(object): """ XML namespace parameters for publication protocol. @@ -247,7 +250,7 @@ class publication_object_elt(rpki.xml_utils.base_elt, publication_namespace): """ Publish an object. """ - rpki.log.info("Publishing %s" % self.payload.tracking_data(self.uri)) + logger.info("Publishing %s" % self.payload.tracking_data(self.uri)) filename = self.uri_to_filename() filename_tmp = filename + ".tmp" dirname = os.path.dirname(filename) @@ -262,7 +265,7 @@ class publication_object_elt(rpki.xml_utils.base_elt, publication_namespace): """ Withdraw an object, then recursively delete empty directories. """ - rpki.log.info("Withdrawing %s" % self.uri) + logger.info("Withdrawing %s" % self.uri) filename = self.uri_to_filename() try: os.remove(filename) diff --git a/rpki/rootd.py b/rpki/rootd.py index 1b6beb55..f8dc4eb3 100644 --- a/rpki/rootd.py +++ b/rpki/rootd.py @@ -25,6 +25,7 @@ rpki.* classes in order to reuse as much code as possible. import os import time +import logging import argparse import sys import rpki.resource_set @@ -39,6 +40,8 @@ import rpki.sundial import rpki.log import rpki.daemonize +logger = logging.getLogger(__name__) + rootd = None class list_pdu(rpki.up_down.list_pdu): @@ -56,15 +59,15 @@ class issue_pdu(rpki.up_down.issue_pdu): class revoke_pdu(rpki.up_down.revoke_pdu): def serve_pdu(self, q_msg, r_msg, ignored, callback, errback): - rpki.log.debug("Revocation requested for SKI %s" % self.ski) + logger.debug("Revocation requested for SKI %s" % self.ski) subject_cert = rootd.get_subject_cert() if subject_cert is None: - rpki.log.debug("No subject certificate, nothing to revoke") + logger.debug("No subject certificate, nothing to revoke") raise rpki.exceptions.NotInDatabase if subject_cert.gSKI() != self.ski: - rpki.log.debug("Subject certificate has different SKI %s, not revoking" % subject_cert.gSKI()) + logger.debug("Subject certificate has different SKI %s, not revoking" % subject_cert.gSKI()) raise rpki.exceptions.NotInDatabase - rpki.log.debug("Revoking certificate %s" % self.ski) + logger.debug("Revoking certificate %s" % self.ski) now = rpki.sundial.now() rootd.revoke_subject_cert(now) rootd.del_subject_cert() @@ -99,7 +102,7 @@ class message_pdu(rpki.up_down.message_pdu): """ Log query we're handling. """ - rpki.log.info("Serving %s query" % self.type) + logger.info("Serving %s query" % self.type) class sax_handler(rpki.up_down.sax_handler): pdu = message_pdu @@ -110,7 +113,7 @@ class cms_msg(rpki.up_down.cms_msg): class main(object): def get_root_cert(self): - rpki.log.debug("Read root cert %s" % self.rpki_root_cert_file) + logger.debug("Read root cert %s" % self.rpki_root_cert_file) self.rpki_root_cert = rpki.x509.X509(Auto_file = self.rpki_root_cert_file) def root_newer_than_subject(self): @@ -121,39 +124,39 @@ class main(object): filename = os.path.join(self.rpki_root_dir, self.rpki_subject_cert) try: x = rpki.x509.X509(Auto_file = filename) - rpki.log.debug("Read subject cert %s" % filename) + logger.debug("Read subject cert %s" % filename) return x except IOError: return None def set_subject_cert(self, cert): filename = os.path.join(self.rpki_root_dir, self.rpki_subject_cert) - rpki.log.debug("Writing subject cert %s, SKI %s" % (filename, cert.hSKI())) + logger.debug("Writing subject cert %s, SKI %s" % (filename, cert.hSKI())) f = open(filename, "wb") f.write(cert.get_DER()) f.close() def del_subject_cert(self): filename = os.path.join(self.rpki_root_dir, self.rpki_subject_cert) - rpki.log.debug("Deleting subject cert %s" % filename) + logger.debug("Deleting subject cert %s" % filename) os.remove(filename) def get_subject_pkcs10(self): try: x = rpki.x509.PKCS10(Auto_file = self.rpki_subject_pkcs10) - rpki.log.debug("Read subject PKCS #10 %s" % self.rpki_subject_pkcs10) + logger.debug("Read subject PKCS #10 %s" % self.rpki_subject_pkcs10) return x except IOError: return None def set_subject_pkcs10(self, pkcs10): - rpki.log.debug("Writing subject PKCS #10 %s" % self.rpki_subject_pkcs10) + logger.debug("Writing subject PKCS #10 %s" % self.rpki_subject_pkcs10) f = open(self.rpki_subject_pkcs10, "wb") f.write(pkcs10.get_DER()) f.close() def del_subject_pkcs10(self): - rpki.log.debug("Deleting subject PKCS #10 %s" % self.rpki_subject_pkcs10) + logger.debug("Deleting subject PKCS #10 %s" % self.rpki_subject_pkcs10) try: os.remove(self.rpki_subject_pkcs10) except OSError: @@ -166,15 +169,15 @@ class main(object): if new_pkcs10 is not None and new_pkcs10 != old_pkcs10: self.set_subject_pkcs10(new_pkcs10) if subject_cert is not None: - rpki.log.debug("PKCS #10 changed, regenerating subject certificate") + logger.debug("PKCS #10 changed, regenerating subject certificate") self.revoke_subject_cert(now) subject_cert = None if subject_cert is not None and subject_cert.getNotAfter() <= now + self.rpki_subject_regen: - rpki.log.debug("Subject certificate has reached expiration threshold, regenerating") + logger.debug("Subject certificate has reached expiration threshold, regenerating") self.revoke_subject_cert(now) subject_cert = None if subject_cert is not None and self.root_newer_than_subject(): - rpki.log.debug("Root certificate has changed, regenerating subject") + logger.debug("Root certificate has changed, regenerating subject") self.revoke_subject_cert(now) subject_cert = None self.get_root_cert() @@ -182,11 +185,11 @@ class main(object): return subject_cert pkcs10 = old_pkcs10 if new_pkcs10 is None else new_pkcs10 if pkcs10 is None: - rpki.log.debug("No PKCS #10 request, can't generate subject certificate yet") + logger.debug("No PKCS #10 request, can't generate subject certificate yet") return None resources = self.rpki_root_cert.get_3779resources() notAfter = now + self.rpki_subject_lifetime - rpki.log.info("Generating subject cert %s with resources %s, expires %s" % ( + logger.info("Generating subject cert %s with resources %s, expires %s" % ( self.rpki_base_uri + self.rpki_subject_cert, resources, notAfter)) req_key = pkcs10.getPublicKey() req_sia = pkcs10.get_SIA() @@ -218,7 +221,7 @@ class main(object): thisUpdate = now, nextUpdate = now + self.rpki_subject_regen, revokedCertificates = self.revoked) - rpki.log.debug("Writing CRL %s" % os.path.join(self.rpki_root_dir, self.rpki_root_crl)) + logger.debug("Writing CRL %s" % os.path.join(self.rpki_root_dir, self.rpki_root_crl)) f = open(os.path.join(self.rpki_root_dir, self.rpki_root_crl), "wb") f.write(crl.get_DER()) f.close() @@ -245,7 +248,7 @@ class main(object): names_and_objs = manifest_content, keypair = manifest_keypair, certs = manifest_cert) - rpki.log.debug("Writing manifest %s" % os.path.join(self.rpki_root_dir, self.rpki_root_manifest)) + logger.debug("Writing manifest %s" % os.path.join(self.rpki_root_dir, self.rpki_root_manifest)) f = open(os.path.join(self.rpki_root_dir, self.rpki_root_manifest), "wb") f.write(manifest.get_DER()) f.close() diff --git a/rpki/rpkid.py b/rpki/rpkid.py index d0918b3c..b6f2bcb2 100644 --- a/rpki/rpkid.py +++ b/rpki/rpkid.py @@ -23,6 +23,7 @@ RPKI CA engine. import os import time +import logging import argparse import sys import re @@ -42,6 +43,8 @@ import rpki.async import rpki.daemonize import rpki.rpkid_tasks +logger = logging.getLogger(__name__) + class main(object): """ Main program for rpkid. @@ -86,7 +89,7 @@ class main(object): prof.runcall(self.main) finally: prof.dump_stats(self.profile) - rpki.log.info("Dumped profile data to %s" % self.profile) + logger.info("Dumped profile data to %s" % self.profile) else: self.main() @@ -94,10 +97,10 @@ class main(object): startup_msg = self.cfg.get("startup-message", "") if startup_msg: - rpki.log.info(startup_msg) + logger.info(startup_msg) if self.profile: - rpki.log.info("Running in profile mode with output to %s" % self.profile) + logger.info("Running in profile mode with output to %s" % self.profile) self.sql = rpki.sql.session(self.cfg) @@ -155,10 +158,10 @@ class main(object): if self.use_internal_cron: self.cron_timer = rpki.async.timer(handler = self.cron) when = rpki.sundial.now() + rpki.sundial.timedelta(seconds = self.initial_delay) - rpki.log.debug("Scheduling initial cron pass at %s" % when) + logger.debug("Scheduling initial cron pass at %s" % when) self.cron_timer.set(when) else: - rpki.log.debug("Not using internal clock, start_cron() call ignored") + logger.debug("Not using internal clock, start_cron() call ignored") def irdb_query(self, callback, errback, *q_pdus, **kwargs): """ @@ -319,7 +322,7 @@ class main(object): except (rpki.async.ExitNow, SystemExit): raise except (rpki.exceptions.ChildNotFound, rpki.exceptions.BadContactURL), e: - rpki.log.warn(str(e)) + logger.warning(str(e)) cb(400, reason = str(e)) except Exception, e: rpki.log.traceback() @@ -338,11 +341,11 @@ class main(object): Add a task to the scheduler task queue, unless it's already queued. """ if task not in self.task_queue: - rpki.log.debug("Adding %r to task queue" % task) + logger.debug("Adding %r to task queue" % task) self.task_queue.append(task) return True else: - rpki.log.debug("Task %r was already in the task queue" % task) + logger.debug("Task %r was already in the task queue" % task) return False def task_next(self): @@ -374,12 +377,12 @@ class main(object): now = rpki.sundial.now() - rpki.log.debug("Starting cron run") + logger.debug("Starting cron run") def done(): self.sql.sweep() self.cron_timeout = None - rpki.log.info("Finished cron run started at %s" % now) + logger.info("Finished cron run started at %s" % now) if cb is not None: cb() @@ -387,7 +390,7 @@ class main(object): try: selves = rpki.left_right.self_elt.sql_fetch_all(self) except Exception, e: - rpki.log.warn("Error pulling self_elts from SQL, maybe SQL server is down? (%s)" % e) + logger.warning("Error pulling self_elts from SQL, maybe SQL server is down? (%s)" % e) else: for s in selves: s.schedule_cron_tasks(completion) @@ -396,12 +399,12 @@ class main(object): assert self.use_internal_cron or self.cron_timeout is None if self.cron_timeout is not None and self.cron_timeout < now: - rpki.log.warn("cron keepalive threshold %s has expired, breaking lock" % self.cron_timeout) + logger.warning("cron keepalive threshold %s has expired, breaking lock" % self.cron_timeout) self.cron_timeout = None if self.use_internal_cron: when = now + self.cron_period - rpki.log.debug("Scheduling next cron run at %s" % when) + logger.debug("Scheduling next cron run at %s" % when) self.cron_timer.set(when) if self.cron_timeout is None: @@ -409,7 +412,7 @@ class main(object): self.task_run() elif self.use_internal_cron: - rpki.log.warn("cron already running, keepalive will expire at %s" % self.cron_timeout) + logger.warning("cron already running, keepalive will expire at %s" % self.cron_timeout) if nothing_queued: done() @@ -427,7 +430,7 @@ class main(object): if self.use_internal_cron: cb(500, reason = "Running cron internally") else: - rpki.log.debug("Starting externally triggered cron") + logger.debug("Starting externally triggered cron") self.cron(done) class ca_obj(rpki.sql.sql_persistent): @@ -541,7 +544,7 @@ class ca_obj(rpki.sql.sql_persistent): sia_uri = self.construct_sia_uri(parent, rc) sia_uri_changed = self.sia_uri != sia_uri if sia_uri_changed: - rpki.log.debug("SIA changed: was %s now %s" % (self.sia_uri, sia_uri)) + logger.debug("SIA changed: was %s now %s" % (self.sia_uri, sia_uri)) self.sia_uri = sia_uri self.sql_mark_dirty() @@ -556,7 +559,7 @@ class ca_obj(rpki.sql.sql_persistent): if rc_cert is None: - rpki.log.warn("SKI %s in resource class %s is in database but missing from list_response to %s from %s, maybe parent certificate went away?" + logger.warning("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(), rc.class_name, parent.self.self_handle, parent.parent_handle)) publisher = publication_queue() ca_detail.delete(ca = ca_detail.ca, publisher = publisher) @@ -565,7 +568,7 @@ class ca_obj(rpki.sql.sql_persistent): else: if ca_detail.state == "active" and ca_detail.ca_cert_uri != rc_cert.cert_url.rsync(): - rpki.log.debug("AIA changed: was %s now %s" % (ca_detail.ca_cert_uri, rc_cert.cert_url.rsync())) + logger.debug("AIA changed: was %s now %s" % (ca_detail.ca_cert_uri, rc_cert.cert_url.rsync())) ca_detail.ca_cert_uri = rc_cert.cert_url.rsync() ca_detail.sql_mark_dirty() @@ -595,7 +598,7 @@ class ca_obj(rpki.sql.sql_persistent): def done(): if cert_map: - rpki.log.warn("Unknown certificate SKI%s %s in resource class %s in list_response " + logger.warning("Unknown certificate SKI%s %s in resource class %s in list_response " "to %s from %s, maybe you want to \"revoke_forgotten\"?" % ("" if len(cert_map) == 1 else "s", ", ".join(c.cert.gSKI() for c in cert_map.values()), @@ -613,19 +616,19 @@ class ca_obj(rpki.sql.sql_persistent): for x in ca_details if x.latest_ca_cert is not None) for ski in skis_parent & skis_me: - rpki.log.debug("Parent %s agrees that %s has SKI %s in resource class %s" + logger.debug("Parent %s agrees that %s has SKI %s in resource class %s" % (parent.parent_handle, parent.self.self_handle, ski, rc.class_name)) for ski in skis_parent - skis_me: - rpki.log.debug("Parent %s thinks %s has SKI %s in resource class %s but I don't think so" + logger.debug("Parent %s thinks %s has SKI %s in resource class %s but I don't think so" % (parent.parent_handle, parent.self.self_handle, ski, rc.class_name)) for ski in skis_me - skis_parent: - rpki.log.debug("I think %s has SKI %s in resource class %s but parent %s doesn't think so" + logger.debug("I think %s has SKI %s in resource class %s but parent %s doesn't think so" % (parent.self.self_handle, ski, rc.class_name, parent.parent_handle)) if ca_details: rpki.async.iterator(ca_details, loop, done) else: - rpki.log.warn("Existing resource class %s to %s from %s with no certificates, rekeying" % + logger.warning("Existing resource class %s to %s from %s with no certificates, rekeying" % (rc.class_name, parent.self.self_handle, parent.parent_handle)) self.gctx.checkpoint() self.rekey(cb, eb) @@ -651,7 +654,7 @@ class ca_obj(rpki.sql.sql_persistent): def done(issue_response): c = issue_response.payload.classes[0].certs[0] - rpki.log.debug("CA %r received certificate %s" % (self, c.cert_url)) + logger.debug("CA %r received certificate %s" % (self, c.cert_url)) ca_detail.activate( ca = self, cert = c.cert, @@ -659,7 +662,7 @@ class ca_obj(rpki.sql.sql_persistent): callback = cb, errback = eb) - rpki.log.debug("Sending issue request to %r from %r" % (parent, self.create)) + logger.debug("Sending issue request to %r from %r" % (parent, self.create)) rpki.up_down.issue_pdu.query(parent, self, ca_detail, done, eb) def delete(self, parent, callback): @@ -676,11 +679,11 @@ class ca_obj(rpki.sql.sql_persistent): def lose(e): rpki.log.traceback() - rpki.log.warn("Could not delete CA %r, skipping: %s" % (self, e)) + logger.warning("Could not delete CA %r, skipping: %s" % (self, e)) callback() def done(): - rpki.log.debug("Deleting %r" % self) + logger.debug("Deleting %r" % self) self.sql_delete() callback() @@ -729,7 +732,7 @@ class ca_obj(rpki.sql.sql_persistent): def done(issue_response): c = issue_response.payload.classes[0].certs[0] - rpki.log.debug("CA %r received certificate %s" % (self, c.cert_url)) + logger.debug("CA %r received certificate %s" % (self, c.cert_url)) new_detail.activate( ca = self, cert = c.cert, @@ -738,7 +741,7 @@ class ca_obj(rpki.sql.sql_persistent): callback = cb, errback = eb) - rpki.log.debug("Sending issue request to %r from %r" % (parent, self.rekey)) + logger.debug("Sending issue request to %r from %r" % (parent, self.rekey)) rpki.up_down.issue_pdu.query(parent, self, new_detail, done, eb) def revoke(self, cb, eb, revoke_all = False): @@ -985,9 +988,9 @@ class ca_detail_obj(rpki.sql.sql_persistent): handler = handler) self.gctx.sql.sweep() for cert in self.revoked_certs: # + self.child_certs - rpki.log.debug("Deleting %r" % cert) + logger.debug("Deleting %r" % cert) cert.sql_delete() - rpki.log.debug("Deleting %r" % self) + logger.debug("Deleting %r" % self) self.sql_delete() def revoke(self, cb, eb): @@ -1021,7 +1024,7 @@ class ca_detail_obj(rpki.sql.sql_persistent): if r_msg.payload.ski != self.latest_ca_cert.gSKI(): raise rpki.exceptions.SKIMismatch - rpki.log.debug("Parent revoked %s, starting cleanup" % self.latest_ca_cert.gSKI()) + logger.debug("Parent revoked %s, starting cleanup" % self.latest_ca_cert.gSKI()) crl_interval = rpki.sundial.timedelta(seconds = parent.self.crl_interval) @@ -1059,7 +1062,7 @@ class ca_detail_obj(rpki.sql.sql_persistent): self.sql_mark_dirty() publisher.call_pubd(cb, eb) - rpki.log.debug("Asking parent to revoke CA certificate %s" % self.latest_ca_cert.gSKI()) + logger.debug("Asking parent to revoke CA certificate %s" % self.latest_ca_cert.gSKI()) rpki.up_down.revoke_pdu.query(ca, self.latest_ca_cert.gSKI(), parent_revoked, eb) def update(self, parent, ca, rc, sia_uri_changed, old_resources, callback, errback): @@ -1070,7 +1073,7 @@ class ca_detail_obj(rpki.sql.sql_persistent): def issued(issue_response): c = issue_response.payload.classes[0].certs[0] - rpki.log.debug("CA %r received certificate %s" % (self, c.cert_url)) + logger.debug("CA %r received certificate %s" % (self, c.cert_url)) if self.state == "pending": return self.activate( @@ -1112,7 +1115,7 @@ class ca_detail_obj(rpki.sql.sql_persistent): publisher.call_pubd(callback, errback) - rpki.log.debug("Sending issue request to %r from %r" % (parent, self.update)) + logger.debug("Sending issue request to %r from %r" % (parent, self.update)) rpki.up_down.issue_pdu.query(parent, ca, self, issued, errback) @classmethod @@ -1197,12 +1200,12 @@ class ca_detail_obj(rpki.sql.sql_persistent): child_id = child.child_id, ca_detail_id = self.ca_detail_id, cert = cert) - rpki.log.debug("Created new child_cert %r" % child_cert) + logger.debug("Created new child_cert %r" % child_cert) else: child_cert.cert = cert del child_cert.ca_detail child_cert.ca_detail_id = self.ca_detail_id - rpki.log.debug("Reusing existing child_cert %r" % child_cert) + logger.debug("Reusing existing child_cert %r" % child_cert) child_cert.ski = cert.get_SKI() child_cert.published = rpki.sundial.now() @@ -1283,19 +1286,19 @@ class ca_detail_obj(rpki.sql.sql_persistent): nextUpdate = now + crl_interval if self.latest_manifest_cert is None or self.latest_manifest_cert.getNotAfter() < nextUpdate: - rpki.log.debug("Generating EE certificate for %s" % uri) + logger.debug("Generating EE certificate for %s" % uri) self.generate_manifest_cert() - rpki.log.debug("Latest CA cert notAfter %s, new %s EE notAfter %s" % ( + logger.debug("Latest CA cert notAfter %s, new %s EE notAfter %s" % ( self.latest_ca_cert.getNotAfter(), uri, self.latest_manifest_cert.getNotAfter())) - rpki.log.debug("Constructing manifest object list for %s" % uri) + logger.debug("Constructing manifest object list for %s" % uri) objs = [(self.crl_uri_tail, self.latest_crl)] objs.extend((c.uri_tail, c.cert) for c in self.child_certs) objs.extend((r.uri_tail, r.roa) for r in self.roas if r.roa is not None) objs.extend((g.uri_tail, g.ghostbuster) for g in self.ghostbusters) objs.extend((e.uri_tail, e.cert) for e in self.ee_certificates) - rpki.log.debug("Building manifest object %s" % uri) + logger.debug("Building manifest object %s" % uri) self.latest_manifest = rpki.x509.SignedManifest.build( serial = ca.next_manifest_number(), thisUpdate = now, @@ -1304,7 +1307,7 @@ class ca_detail_obj(rpki.sql.sql_persistent): keypair = self.manifest_private_key_id, certs = self.latest_manifest_cert) - rpki.log.debug("Manifest generation took %s" % (rpki.sundial.now() - now)) + logger.debug("Manifest generation took %s" % (rpki.sundial.now() - now)) self.manifest_published = rpki.sundial.now() self.sql_mark_dirty() @@ -1370,7 +1373,7 @@ class ca_detail_obj(rpki.sql.sql_persistent): should become configurable. """ - rpki.log.debug("Checking for failed publication for %r" % self) + logger.debug("Checking for failed publication for %r" % self) stale = rpki.sundial.now() - rpki.sundial.timedelta(seconds = 60) repository = self.ca.parent.repository @@ -1378,7 +1381,7 @@ class ca_detail_obj(rpki.sql.sql_persistent): if self.latest_crl is not None and \ self.crl_published is not None and \ self.crl_published < stale: - rpki.log.debug("Retrying publication for %s" % self.crl_uri) + logger.debug("Retrying publication for %s" % self.crl_uri) publisher.publish(cls = rpki.publication.crl_elt, uri = self.crl_uri, obj = self.latest_crl, @@ -1388,7 +1391,7 @@ class ca_detail_obj(rpki.sql.sql_persistent): if self.latest_manifest is not None and \ self.manifest_published is not None and \ self.manifest_published < stale: - rpki.log.debug("Retrying publication for %s" % self.manifest_uri) + logger.debug("Retrying publication for %s" % self.manifest_uri) publisher.publish(cls = rpki.publication.manifest_elt, uri = self.manifest_uri, obj = self.latest_manifest, @@ -1402,7 +1405,7 @@ class ca_detail_obj(rpki.sql.sql_persistent): # date, but let's avoid premature optimization for child_cert in self.unpublished_child_certs(stale): - rpki.log.debug("Retrying publication for %s" % child_cert) + logger.debug("Retrying publication for %s" % child_cert) publisher.publish( cls = rpki.publication.certificate_elt, uri = child_cert.uri, @@ -1411,7 +1414,7 @@ class ca_detail_obj(rpki.sql.sql_persistent): handler = child_cert.published_callback) for roa in self.unpublished_roas(stale): - rpki.log.debug("Retrying publication for %s" % roa) + logger.debug("Retrying publication for %s" % roa) publisher.publish( cls = rpki.publication.roa_elt, uri = roa.uri, @@ -1420,7 +1423,7 @@ class ca_detail_obj(rpki.sql.sql_persistent): handler = roa.published_callback) for ghostbuster in self.unpublished_ghostbusters(stale): - rpki.log.debug("Retrying publication for %s" % ghostbuster) + logger.debug("Retrying publication for %s" % ghostbuster) publisher.publish( cls = rpki.publication.ghostbuster_elt, uri = ghostbuster.uri, @@ -1507,7 +1510,7 @@ class child_cert_obj(rpki.sql.sql_persistent): ca_detail = self.ca_detail ca = ca_detail.ca - rpki.log.debug("Revoking %r %r" % (self, self.uri)) + logger.debug("Revoking %r %r" % (self, self.uri)) revoked_cert_obj.revoke(cert = self.cert, ca_detail = ca_detail) publisher.withdraw( cls = rpki.publication.certificate_elt, @@ -1549,42 +1552,42 @@ class child_cert_obj(rpki.sql.sql_persistent): assert resources.valid_until is not None and old_resources.valid_until is not None if resources.asn != old_resources.asn or resources.v4 != old_resources.v4 or resources.v6 != old_resources.v6: - rpki.log.debug("Resources changed for %r: old %s new %s" % (self, old_resources, resources)) + logger.debug("Resources changed for %r: old %s new %s" % (self, old_resources, resources)) needed = True if resources.valid_until != old_resources.valid_until: - rpki.log.debug("Validity changed for %r: old %s new %s" % ( + logger.debug("Validity changed for %r: old %s new %s" % ( self, old_resources.valid_until, resources.valid_until)) needed = True if sia != old_sia: - rpki.log.debug("SIA changed for %r: old %r new %r" % (self, old_sia, sia)) + logger.debug("SIA changed for %r: old %r new %r" % (self, old_sia, sia)) needed = True if ca_detail != old_ca_detail: - rpki.log.debug("Issuer changed for %r: old %r new %r" % (self, old_ca_detail, ca_detail)) + logger.debug("Issuer changed for %r: old %r new %r" % (self, old_ca_detail, ca_detail)) needed = True if ca_detail.ca_cert_uri != old_aia: - rpki.log.debug("AIA changed for %r: old %r new %r" % (self, old_aia, ca_detail.ca_cert_uri)) + logger.debug("AIA changed for %r: old %r new %r" % (self, old_aia, ca_detail.ca_cert_uri)) needed = True must_revoke = old_resources.oversized(resources) or old_resources.valid_until > resources.valid_until if must_revoke: - rpki.log.debug("Must revoke any existing cert(s) for %r" % self) + logger.debug("Must revoke any existing cert(s) for %r" % self) needed = True if not needed and force: - rpki.log.debug("No change needed for %r, forcing reissuance anyway" % self) + logger.debug("No change needed for %r, forcing reissuance anyway" % self) needed = True if not needed: - rpki.log.debug("No change to %r" % self) + logger.debug("No change to %r" % self) return self if must_revoke: for x in child.fetch_child_certs(ca_detail = ca_detail, ski = self.ski): - rpki.log.debug("Revoking child_cert %r" % x) + logger.debug("Revoking child_cert %r" % x) x.revoke(publisher = publisher) ca_detail.generate_crl(publisher = publisher) ca_detail.generate_manifest(publisher = publisher) @@ -1598,7 +1601,7 @@ class child_cert_obj(rpki.sql.sql_persistent): child_cert = None if must_revoke else self, publisher = publisher) - rpki.log.debug("New child_cert %r uri %s" % (child_cert, child_cert.uri)) + logger.debug("New child_cert %r uri %s" % (child_cert, child_cert.uri)) return child_cert @@ -1803,38 +1806,38 @@ class roa_obj(rpki.sql.sql_persistent): v6 = self.ipv6.to_resource_set() if self.ipv6 is not None else rpki.resource_set.resource_set_ipv6() if self.roa is None: - rpki.log.debug("%r doesn't exist, generating" % self) + logger.debug("%r doesn't exist, generating" % self) return self.generate(publisher = publisher, fast = fast) ca_detail = self.ca_detail if ca_detail is None: - rpki.log.debug("%r has no associated ca_detail, generating" % self) + logger.debug("%r has no associated ca_detail, generating" % self) return self.generate(publisher = publisher, fast = fast) if ca_detail.state != "active": - rpki.log.debug("ca_detail associated with %r not active (state %s), regenerating" % (self, ca_detail.state)) + logger.debug("ca_detail associated with %r not active (state %s), regenerating" % (self, ca_detail.state)) return self.regenerate(publisher = publisher, fast = fast) regen_time = self.cert.getNotAfter() - rpki.sundial.timedelta(seconds = self.self.regen_margin) if rpki.sundial.now() > regen_time: - rpki.log.debug("%r past threshold %s, regenerating" % (self, regen_time)) + logger.debug("%r past threshold %s, regenerating" % (self, regen_time)) return self.regenerate(publisher = publisher, fast = fast) ca_resources = ca_detail.latest_ca_cert.get_3779resources() ee_resources = self.cert.get_3779resources() if ee_resources.oversized(ca_resources): - rpki.log.debug("%r oversized with respect to CA, regenerating" % self) + logger.debug("%r oversized with respect to CA, regenerating" % self) return self.regenerate(publisher = publisher, fast = fast) if ee_resources.v4 != v4 or ee_resources.v6 != v6: - rpki.log.debug("%r resources do not match EE, regenerating" % self) + logger.debug("%r resources do not match EE, regenerating" % self) return self.regenerate(publisher = publisher, fast = fast) if self.cert.get_AIA()[0] != ca_detail.ca_cert_uri: - rpki.log.debug("%r AIA changed, regenerating" % self) + logger.debug("%r AIA changed, regenerating" % self) return self.regenerate(publisher = publisher, fast = fast) def generate(self, publisher, fast = False): @@ -1870,7 +1873,7 @@ class roa_obj(rpki.sql.sql_persistent): ca_detail = self.ca_detail if ca_detail is None or ca_detail.state != "active" or ca_detail.has_expired(): - rpki.log.debug("Searching for new ca_detail for ROA %r" % self) + logger.debug("Searching for new ca_detail for ROA %r" % self) ca_detail = None for parent in self.self.parents: for ca in parent.cas: @@ -1884,12 +1887,12 @@ class roa_obj(rpki.sql.sql_persistent): if ca_detail is not None: break else: - rpki.log.debug("Keeping old ca_detail for ROA %r" % self) + logger.debug("Keeping old ca_detail for ROA %r" % self) if ca_detail is None: raise rpki.exceptions.NoCoveringCertForROA, "Could not find a certificate covering %r" % self - rpki.log.debug("Using new ca_detail %r for ROA %r, ca_detail_state %s" % ( + logger.debug("Using new ca_detail %r for ROA %r, ca_detail_state %s" % ( ca_detail, self, ca_detail.state)) ca = ca_detail.ca @@ -1907,7 +1910,7 @@ class roa_obj(rpki.sql.sql_persistent): self.published = rpki.sundial.now() self.sql_store() - rpki.log.debug("Generating %r URI %s" % (self, self.uri)) + logger.debug("Generating %r URI %s" % (self, self.uri)) publisher.publish( cls = rpki.publication.roa_elt, uri = self.uri, @@ -1947,14 +1950,14 @@ class roa_obj(rpki.sql.sql_persistent): roa = self.roa uri = self.uri - rpki.log.debug("%s %r, ca_detail %r state is %s" % ( + logger.debug("%s %r, ca_detail %r state is %s" % ( "Regenerating" if regenerate else "Not regenerating", self, ca_detail, ca_detail.state)) if regenerate: self.generate(publisher = publisher, fast = fast) - rpki.log.debug("Withdrawing %r %s and revoking its EE cert" % (self, uri)) + logger.debug("Withdrawing %r %s and revoking its EE cert" % (self, uri)) rpki.rpkid.revoked_cert_obj.revoke(cert = cert, ca_detail = ca_detail) publisher.withdraw(cls = rpki.publication.roa_elt, uri = uri, obj = roa, repository = ca_detail.ca.parent.repository, @@ -2064,17 +2067,17 @@ class ghostbuster_obj(rpki.sql.sql_persistent): """ if self.ghostbuster is None: - rpki.log.debug("Ghostbuster record doesn't exist, generating") + logger.debug("Ghostbuster record doesn't exist, generating") return self.generate(publisher = publisher, fast = fast) regen_time = self.cert.getNotAfter() - rpki.sundial.timedelta(seconds = self.self.regen_margin) if rpki.sundial.now() > regen_time: - rpki.log.debug("%r past threshold %s, regenerating" % (self, regen_time)) + logger.debug("%r past threshold %s, regenerating" % (self, regen_time)) return self.regenerate(publisher = publisher, fast = fast) if self.cert.get_AIA()[0] != self.ca_detail.ca_cert_uri: - rpki.log.debug("%r AIA changed, regenerating" % self) + logger.debug("%r AIA changed, regenerating" % self) return self.regenerate(publisher = publisher, fast = fast) def generate(self, publisher, fast = False): @@ -2106,7 +2109,7 @@ class ghostbuster_obj(rpki.sql.sql_persistent): self.published = rpki.sundial.now() self.sql_store() - rpki.log.debug("Generating Ghostbuster record %r" % self.uri) + logger.debug("Generating Ghostbuster record %r" % self.uri) publisher.publish( cls = rpki.publication.ghostbuster_elt, uri = self.uri, @@ -2145,14 +2148,14 @@ class ghostbuster_obj(rpki.sql.sql_persistent): ghostbuster = self.ghostbuster uri = self.uri - rpki.log.debug("%s %r, ca_detail %r state is %s" % ( + logger.debug("%s %r, ca_detail %r state is %s" % ( "Regenerating" if regenerate else "Not regenerating", self, ca_detail, ca_detail.state)) if regenerate: self.generate(publisher = publisher, fast = fast) - rpki.log.debug("Withdrawing %r %s and revoking its EE cert" % (self, uri)) + logger.debug("Withdrawing %r %s and revoking its EE cert" % (self, uri)) rpki.rpkid.revoked_cert_obj.revoke(cert = cert, ca_detail = ca_detail) publisher.withdraw(cls = rpki.publication.ghostbuster_elt, uri = uri, obj = ghostbuster, repository = ca_detail.ca.parent.repository, @@ -2313,7 +2316,7 @@ class ee_cert_obj(rpki.sql.sql_persistent): ca_detail.generate_manifest(publisher = publisher) - rpki.log.debug("New ee_cert %r" % self) + logger.debug("New ee_cert %r" % self) return self @@ -2324,7 +2327,7 @@ class ee_cert_obj(rpki.sql.sql_persistent): ca_detail = self.ca_detail ca = ca_detail.ca - rpki.log.debug("Revoking %r %r" % (self, self.uri)) + logger.debug("Revoking %r %r" % (self, self.uri)) revoked_cert_obj.revoke(cert = self.cert, ca_detail = ca_detail) publisher.withdraw(cls = rpki.publication.certificate_elt, uri = self.uri, @@ -2364,37 +2367,37 @@ class ee_cert_obj(rpki.sql.sql_persistent): assert ca_detail.covers(resources) if ca_detail != self.ca_detail: - rpki.log.debug("ca_detail changed for %r: old %r new %r" % ( + logger.debug("ca_detail changed for %r: old %r new %r" % ( self, self.ca_detail, ca_detail)) needed = True if ca_detail.ca_cert_uri != old_cert.get_AIA()[0]: - rpki.log.debug("AIA changed for %r: old %s new %s" % ( + logger.debug("AIA changed for %r: old %s new %s" % ( self, old_cert.get_AIA()[0], ca_detail.ca_cert_uri)) needed = True if resources.valid_until != old_resources.valid_until: - rpki.log.debug("Validity changed for %r: old %s new %s" % ( + logger.debug("Validity changed for %r: old %s new %s" % ( self, old_resources.valid_until, resources.valid_until)) needed = True if resources.asn != old_resources.asn or resources.v4 != old_resources.v4 or resources.v6 != old_resources.v6: - rpki.log.debug("Resources changed for %r: old %s new %s" % ( + logger.debug("Resources changed for %r: old %s new %s" % ( self, old_resources, resources)) needed = True must_revoke = (old_resources.oversized(resources) or old_resources.valid_until > resources.valid_until) if must_revoke: - rpki.log.debug("Must revoke existing cert(s) for %r" % self) + logger.debug("Must revoke existing cert(s) for %r" % self) needed = True if not needed and force: - rpki.log.debug("No change needed for %r, forcing reissuance anyway" % self) + logger.debug("No change needed for %r, forcing reissuance anyway" % self) needed = True if not needed: - rpki.log.debug("No change to %r" % self) + logger.debug("No change to %r" % self) return cn, sn = self.cert.getSubject().extract_cn_and_sn() @@ -2467,7 +2470,7 @@ class publication_queue(object): self.repositories[rid] = repository self.msgs[rid] = rpki.publication.msg.query() if self.replace and uri in self.uris: - rpki.log.debug("Removing publication duplicate <%s %r %r>" % (self.uris[uri].action, self.uris[uri].uri, self.uris[uri].payload)) + logger.debug("Removing publication duplicate <%s %r %r>" % (self.uris[uri].action, self.uris[uri].uri, self.uris[uri].payload)) self.msgs[rid].remove(self.uris.pop(uri)) pdu = make_pdu(uri = uri, obj = obj) if handler is not None: @@ -2485,7 +2488,7 @@ class publication_queue(object): def call_pubd(self, cb, eb): def loop(iterator, rid): - rpki.log.debug("Calling pubd[%r]" % self.repositories[rid]) + logger.debug("Calling pubd[%r]" % self.repositories[rid]) self.repositories[rid].call_pubd(iterator, eb, self.msgs[rid], self.handlers) def done(): self.clear() diff --git a/rpki/rpkid_tasks.py b/rpki/rpkid_tasks.py index 04e1c0df..ab8beaa6 100644 --- a/rpki/rpkid_tasks.py +++ b/rpki/rpkid_tasks.py @@ -21,6 +21,7 @@ rpkid task objects. Split out from rpki.left_right and rpki.rpkid because interactions with rpkid scheduler were getting too complicated. """ +import logging import rpki.log import rpki.rpkid import rpki.async @@ -29,6 +30,8 @@ import rpki.sundial import rpki.publication import rpki.exceptions +logger = logging.getLogger(__name__) + task_classes = () def queue_task(cls): @@ -58,7 +61,7 @@ class CompletionHandler(object): def register(self, task): if self.debug: - rpki.log.debug("Completion handler %r registering task %r" % (self, task)) + logger.debug("Completion handler %r registering task %r" % (self, task)) self.tasks.add(task) task.register_completion(self.done) @@ -66,13 +69,13 @@ class CompletionHandler(object): try: self.tasks.remove(task) except KeyError: - rpki.log.warn("Completion handler %r called with unregistered task %r, blundering onwards" % (self, task)) + logger.warning("Completion handler %r called with unregistered task %r, blundering onwards" % (self, task)) else: if self.debug: - rpki.log.debug("Completion handler %r called with registered task %r" % (self, task)) + logger.debug("Completion handler %r called with registered task %r" % (self, task)) if not self.tasks: if self.debug: - rpki.log.debug("Completion handler %r finished, calling %r" % (self, self.cb)) + logger.debug("Completion handler %r finished, calling %r" % (self, self.cb)) self.cb() @property @@ -127,11 +130,11 @@ class AbstractTask(object): def __call__(self): self.due_date = rpki.sundial.now() + self.timeslice if self.continuation is None: - rpki.log.debug("Running task %r" % self) + logger.debug("Running task %r" % self) self.clear() self.start() else: - rpki.log.debug("Restarting task %r at %r" % (self, self.continuation)) + logger.debug("Restarting task %r at %r" % (self, self.continuation)) continuation = self.continuation self.continuation = None continuation() @@ -166,7 +169,7 @@ class PollParentTask(AbstractTask): def start(self): rpki.log.trace() self.gctx.checkpoint() - rpki.log.debug("Self %s[%d] polling parents" % (self.self_handle, self.self_id)) + logger.debug("Self %s[%d] polling parents" % (self.self_handle, self.self_id)) rpki.async.iterator(self.parents, self.parent_loop, self.exit) def parent_loop(self, parent_iterator, parent): @@ -181,7 +184,7 @@ class PollParentTask(AbstractTask): def list_failed(self, e): rpki.log.traceback() - rpki.log.warn("Couldn't get resource class list from parent %r, skipping: %s (%r)" % ( + logger.warning("Couldn't get resource class list from parent %r, skipping: %s (%r)" % ( self.parent, e, e)) self.parent_iterator() @@ -197,12 +200,12 @@ class PollParentTask(AbstractTask): def class_update_failed(self, e): rpki.log.traceback() - rpki.log.warn("Couldn't update class, skipping: %s" % e) + logger.warning("Couldn't update class, skipping: %s" % e) self.class_iterator() def class_create_failed(self, e): rpki.log.traceback() - rpki.log.warn("Couldn't create class, skipping: %s" % e) + logger.warning("Couldn't create class, skipping: %s" % e) self.class_iterator() def class_done(self): @@ -237,7 +240,7 @@ class UpdateChildrenTask(AbstractTask): def start(self): rpki.log.trace() self.gctx.checkpoint() - rpki.log.debug("Self %s[%d] updating children" % (self.self_handle, self.self_id)) + logger.debug("Self %s[%d] updating children" % (self.self_handle, self.self_id)) self.now = rpki.sundial.now() self.rsn = self.now + rpki.sundial.timedelta(seconds = self.regen_margin) self.publisher = rpki.rpkid.publication_queue() @@ -263,7 +266,7 @@ class UpdateChildrenTask(AbstractTask): def lose(self, e): rpki.log.traceback() - rpki.log.warn("Couldn't update child %r, skipping: %s" % (self.child, e)) + logger.warning("Couldn't update child %r, skipping: %s" % (self.child, e)) self.iterator() def got_resources(self, irdb_resources): @@ -278,7 +281,7 @@ class UpdateChildrenTask(AbstractTask): new_aia = ca_detail.ca_cert_uri if new_resources.empty(): - rpki.log.debug("Resources shrank to the null set, " + logger.debug("Resources shrank to the null set, " "revoking and withdrawing child %s certificate SKI %s" % ( self.child.child_handle, child_cert.cert.gSKI())) child_cert.revoke(publisher = self.publisher) @@ -291,13 +294,13 @@ class UpdateChildrenTask(AbstractTask): irdb_resources.valid_until > self.now and old_resources.valid_until != irdb_resources.valid_until)): - rpki.log.debug("Need to reissue child %s certificate SKI %s" % ( + logger.debug("Need to reissue child %s certificate SKI %s" % ( self.child.child_handle, child_cert.cert.gSKI())) if old_resources != new_resources: - rpki.log.debug("Child %s SKI %s resources changed: old %s new %s" % ( + logger.debug("Child %s SKI %s resources changed: old %s new %s" % ( self.child.child_handle, child_cert.cert.gSKI(), old_resources, new_resources)) if old_resources.valid_until != irdb_resources.valid_until: - rpki.log.debug("Child %s SKI %s validity changed: old %s new %s" % ( + logger.debug("Child %s SKI %s validity changed: old %s new %s" % ( self.child.child_handle, child_cert.cert.gSKI(), old_resources.valid_until, irdb_resources.valid_until)) @@ -308,7 +311,7 @@ class UpdateChildrenTask(AbstractTask): publisher = self.publisher) elif old_resources.valid_until < self.now: - rpki.log.debug("Child %s certificate SKI %s has expired: cert.valid_until %s, irdb.valid_until %s" + logger.debug("Child %s certificate SKI %s has expired: cert.valid_until %s, irdb.valid_until %s" % (self.child.child_handle, child_cert.cert.gSKI(), old_resources.valid_until, irdb_resources.valid_until)) child_cert.sql_delete() @@ -336,7 +339,7 @@ class UpdateChildrenTask(AbstractTask): def publication_failed(self, e): rpki.log.traceback() - rpki.log.warn("Couldn't publish for %s, skipping: %s" % (self.self_handle, e)) + logger.warning("Couldn't publish for %s, skipping: %s" % (self.self_handle, e)) self.gctx.checkpoint() self.exit() @@ -358,17 +361,17 @@ class UpdateROAsTask(AbstractTask): rpki.log.trace() self.gctx.checkpoint() self.gctx.sql.sweep() - rpki.log.debug("Self %s[%d] updating ROAs" % (self.self_handle, self.self_id)) + logger.debug("Self %s[%d] updating ROAs" % (self.self_handle, self.self_id)) - rpki.log.debug("Issuing query for ROA requests") + logger.debug("Issuing query for ROA requests") self.gctx.irdb_query_roa_requests(self.self_handle, self.got_roa_requests, self.roa_requests_failed) def got_roa_requests(self, roa_requests): self.gctx.checkpoint() - rpki.log.debug("Received response to query for ROA requests") + logger.debug("Received response to query for ROA requests") if self.gctx.sql.dirty: - rpki.log.warn("Unexpected dirty SQL cache, flushing") + logger.warning("Unexpected dirty SQL cache, flushing") self.gctx.sql.sweep() roas = {} @@ -392,15 +395,15 @@ class UpdateROAsTask(AbstractTask): for roa_request in roa_requests: k = (roa_request.asn, str(roa_request.ipv4), str(roa_request.ipv6)) if k in seen: - rpki.log.warn("Skipping duplicate ROA request %r" % roa_request) + logger.warning("Skipping duplicate ROA request %r" % roa_request) else: seen.add(k) roa = roas.pop(k, None) if roa is None: roa = rpki.rpkid.roa_obj(self.gctx, self.self_id, roa_request.asn, roa_request.ipv4, roa_request.ipv6) - rpki.log.debug("Created new %r" % roa) + logger.debug("Created new %r" % roa) else: - rpki.log.debug("Found existing %r" % roa) + logger.debug("Found existing %r" % roa) self.updates.append(roa) self.orphans.extend(roas.itervalues()) @@ -423,10 +426,10 @@ class UpdateROAsTask(AbstractTask): except (SystemExit, rpki.async.ExitNow): raise except rpki.exceptions.NoCoveringCertForROA: - rpki.log.warn("No covering certificate for %r, skipping" % roa) + logger.warning("No covering certificate for %r, skipping" % roa) except Exception, e: rpki.log.traceback() - rpki.log.warn("Could not update %r, skipping: %s" % (roa, e)) + logger.warning("Could not update %r, skipping: %s" % (roa, e)) self.count += 1 if self.overdue: self.publish(lambda: self.postpone(iterator)) @@ -436,9 +439,9 @@ class UpdateROAsTask(AbstractTask): def publish(self, done): if not self.publisher.empty(): for ca_detail in self.ca_details: - rpki.log.debug("Generating new CRL for %r" % ca_detail) + logger.debug("Generating new CRL for %r" % ca_detail) ca_detail.generate_crl(publisher = self.publisher) - rpki.log.debug("Generating new manifest for %r" % ca_detail) + logger.debug("Generating new manifest for %r" % ca_detail) ca_detail.generate_manifest(publisher = self.publisher) self.ca_details.clear() self.gctx.sql.sweep() @@ -447,7 +450,7 @@ class UpdateROAsTask(AbstractTask): def publication_failed(self, e): rpki.log.traceback() - rpki.log.warn("Couldn't publish for %s, skipping: %s" % (self.self_handle, e)) + logger.warning("Couldn't publish for %s, skipping: %s" % (self.self_handle, e)) self.gctx.checkpoint() self.exit() @@ -460,14 +463,14 @@ class UpdateROAsTask(AbstractTask): raise except Exception, e: rpki.log.traceback() - rpki.log.warn("Could not revoke %r: %s" % (roa, e)) + logger.warning("Could not revoke %r: %s" % (roa, e)) self.gctx.sql.sweep() self.gctx.checkpoint() self.publish(self.exit) def roa_requests_failed(self, e): rpki.log.traceback() - rpki.log.warn("Could not fetch ROA requests for %s, skipping: %s" % (self.self_handle, e)) + logger.warning("Could not fetch ROA requests for %s, skipping: %s" % (self.self_handle, e)) self.exit() @@ -486,7 +489,7 @@ class UpdateGhostbustersTask(AbstractTask): def start(self): rpki.log.trace() self.gctx.checkpoint() - rpki.log.debug("Self %s[%d] updating Ghostbuster records" % (self.self_handle, self.self_id)) + logger.debug("Self %s[%d] updating Ghostbuster records" % (self.self_handle, self.self_id)) self.gctx.irdb_query_ghostbuster_requests(self.self_handle, (p.parent_handle for p in self.parents), @@ -498,7 +501,7 @@ class UpdateGhostbustersTask(AbstractTask): try: self.gctx.checkpoint() if self.gctx.sql.dirty: - rpki.log.warn("Unexpected dirty SQL cache, flushing") + logger.warning("Unexpected dirty SQL cache, flushing") self.gctx.sql.sweep() ghostbusters = {} @@ -518,11 +521,11 @@ class UpdateGhostbustersTask(AbstractTask): for ghostbuster_request in ghostbuster_requests: if ghostbuster_request.parent_handle not in parents: - rpki.log.warn("Unknown parent_handle %r in Ghostbuster request, skipping" % ghostbuster_request.parent_handle) + logger.warning("Unknown parent_handle %r in Ghostbuster request, skipping" % ghostbuster_request.parent_handle) continue k = (ghostbuster_request.parent_handle, ghostbuster_request.vcard) if k in seen: - rpki.log.warn("Skipping duplicate Ghostbuster request %r" % ghostbuster_request) + logger.warning("Skipping duplicate Ghostbuster request %r" % ghostbuster_request) continue seen.add(k) for ca in parents[ghostbuster_request.parent_handle].cas: @@ -531,9 +534,9 @@ class UpdateGhostbustersTask(AbstractTask): ghostbuster = ghostbusters.pop((ca_detail.ca_detail_id, ghostbuster_request.vcard), None) if ghostbuster is None: ghostbuster = rpki.rpkid.ghostbuster_obj(self.gctx, self.self_id, ca_detail.ca_detail_id, ghostbuster_request.vcard) - rpki.log.debug("Created new %r for %r" % (ghostbuster, ghostbuster_request.parent_handle)) + logger.debug("Created new %r for %r" % (ghostbuster, ghostbuster_request.parent_handle)) else: - rpki.log.debug("Found existing %r for %s" % (ghostbuster, ghostbuster_request.parent_handle)) + logger.debug("Found existing %r for %s" % (ghostbuster, ghostbuster_request.parent_handle)) ghostbuster.update(publisher = publisher, fast = True) ca_details.add(ca_detail) @@ -555,18 +558,18 @@ class UpdateGhostbustersTask(AbstractTask): raise except Exception, e: rpki.log.traceback() - rpki.log.warn("Could not update Ghostbuster records for %s, skipping: %s" % (self.self_handle, e)) + logger.warning("Could not update Ghostbuster records for %s, skipping: %s" % (self.self_handle, e)) self.exit() def publication_failed(self, e): rpki.log.traceback() - rpki.log.warn("Couldn't publish Ghostbuster updates for %s, skipping: %s" % (self.self_handle, e)) + logger.warning("Couldn't publish Ghostbuster updates for %s, skipping: %s" % (self.self_handle, e)) self.gctx.checkpoint() self.exit() def ghostbuster_requests_failed(self, e): rpki.log.traceback() - rpki.log.warn("Could not fetch Ghostbuster record requests for %s, skipping: %s" % (self.self_handle, e)) + logger.warning("Could not fetch Ghostbuster record requests for %s, skipping: %s" % (self.self_handle, e)) self.exit() @@ -582,7 +585,7 @@ class UpdateEECertificatesTask(AbstractTask): def start(self): rpki.log.trace() self.gctx.checkpoint() - rpki.log.debug("Self %s[%d] updating EE certificates" % (self.self_handle, self.self_id)) + logger.debug("Self %s[%d] updating EE certificates" % (self.self_handle, self.self_id)) self.gctx.irdb_query_ee_certificate_requests(self.self_handle, self.got_requests, @@ -593,7 +596,7 @@ class UpdateEECertificatesTask(AbstractTask): try: self.gctx.checkpoint() if self.gctx.sql.dirty: - rpki.log.warn("Unexpected dirty SQL cache, flushing") + logger.warning("Unexpected dirty SQL cache, flushing") self.gctx.sql.sweep() publisher = rpki.rpkid.publication_queue() @@ -619,17 +622,17 @@ class UpdateEECertificatesTask(AbstractTask): for ee in ees: if ee.ca_detail in covering: - rpki.log.debug("Updating existing EE certificate for %s %s" % (req.gski, resources)) + logger.debug("Updating existing EE certificate for %s %s" % (req.gski, resources)) ee.reissue( resources = resources, publisher = publisher) covering.remove(ee.ca_detail) else: - rpki.log.debug("Existing EE certificate for %s %s is no longer covered" % (req.gski, resources)) + logger.debug("Existing EE certificate for %s %s is no longer covered" % (req.gski, resources)) ee.revoke(publisher = publisher) for ca_detail in covering: - rpki.log.debug("No existing EE certificate for %s %s" % (req.gski, resources)) + logger.debug("No existing EE certificate for %s %s" % (req.gski, resources)) rpki.rpkid.ee_cert_obj.create( ca_detail = ca_detail, subject_name = rpki.x509.X501DN.from_cn(req.cn, req.sn), @@ -659,18 +662,18 @@ class UpdateEECertificatesTask(AbstractTask): raise except Exception, e: rpki.log.traceback() - rpki.log.warn("Could not update EE certificates for %s, skipping: %s" % (self.self_handle, e)) + logger.warning("Could not update EE certificates for %s, skipping: %s" % (self.self_handle, e)) self.exit() def publication_failed(self, e): rpki.log.traceback() - rpki.log.warn("Couldn't publish EE certificate updates for %s, skipping: %s" % (self.self_handle, e)) + logger.warning("Couldn't publish EE certificate updates for %s, skipping: %s" % (self.self_handle, e)) self.gctx.checkpoint() self.exit() def get_requests_failed(self, e): rpki.log.traceback() - rpki.log.warn("Could not fetch EE certificate requests for %s, skipping: %s" % (self.self_handle, e)) + logger.warning("Could not fetch EE certificate requests for %s, skipping: %s" % (self.self_handle, e)) self.exit() @@ -690,7 +693,7 @@ class RegenerateCRLsAndManifestsTask(AbstractTask): def start(self): rpki.log.trace() self.gctx.checkpoint() - rpki.log.debug("Self %s[%d] regenerating CRLs and manifests" % (self.self_handle, self.self_id)) + logger.debug("Self %s[%d] regenerating CRLs and manifests" % (self.self_handle, self.self_id)) now = rpki.sundial.now() crl_interval = rpki.sundial.timedelta(seconds = self.crl_interval) @@ -711,7 +714,7 @@ class RegenerateCRLsAndManifestsTask(AbstractTask): raise except Exception, e: rpki.log.traceback() - rpki.log.warn("Couldn't regenerate CRLs and manifests for CA %r, skipping: %s" % (ca, e)) + logger.warning("Couldn't regenerate CRLs and manifests for CA %r, skipping: %s" % (ca, e)) self.gctx.checkpoint() self.gctx.sql.sweep() @@ -719,7 +722,7 @@ class RegenerateCRLsAndManifestsTask(AbstractTask): def lose(self, e): rpki.log.traceback() - rpki.log.warn("Couldn't publish updated CRLs and manifests for self %r, skipping: %s" % (self.self_handle, e)) + logger.warning("Couldn't publish updated CRLs and manifests for self %r, skipping: %s" % (self.self_handle, e)) self.gctx.checkpoint() self.exit() @@ -745,6 +748,6 @@ class CheckFailedPublication(AbstractTask): def publication_failed(self, e): rpki.log.traceback() - rpki.log.warn("Couldn't publish for %s, skipping: %s" % (self.self_handle, e)) + logger.warning("Couldn't publish for %s, skipping: %s" % (self.self_handle, e)) self.gctx.checkpoint() self.exit() diff --git a/rpki/sql.py b/rpki/sql.py index 65a3b85c..536ebbe2 100644 --- a/rpki/sql.py +++ b/rpki/sql.py @@ -32,6 +32,7 @@ SQL interface code. """ +import logging import weakref from rpki.mysql_import import (MySQLdb, _mysql_exceptions) @@ -41,6 +42,8 @@ import rpki.resource_set import rpki.sundial import rpki.log +logger = logging.getLogger(__name__) + class session(object): """ SQL session layer. @@ -95,7 +98,7 @@ class session(object): return func(query, args) except _mysql_exceptions.MySQLError: if self.dirty: - rpki.log.warn("MySQL exception with dirty objects in SQL cache!") + logger.warning("MySQL exception with dirty objects in SQL cache!") raise def execute(self, query, args = None): @@ -115,7 +118,7 @@ class session(object): Clear the SQL object cache. Shouldn't be necessary now that the cache uses weak references, but should be harmless. """ - rpki.log.debug("Clearing SQL cache") + logger.debug("Clearing SQL cache") self.assert_pristine() self.cache.clear() @@ -131,7 +134,7 @@ class session(object): """ for s in self.dirty.copy(): #if s.sql_cache_debug: - rpki.log.debug("Sweeping (%s) %r" % ("deleting" if s.sql_deleted else "storing", s)) + logger.debug("Sweeping (%s) %r" % ("deleting" if s.sql_deleted else "storing", s)) if s.sql_deleted: s.sql_delete() else: @@ -242,7 +245,7 @@ class sql_persistent(object): if where is None: assert args is None and also_from is None if cls.sql_debug: - rpki.log.debug("sql_fetch_where(%r)" % cls.sql_template.select) + logger.debug("sql_fetch_where(%r)" % cls.sql_template.select) gctx.sql.execute(cls.sql_template.select) else: query = cls.sql_template.select @@ -250,7 +253,7 @@ class sql_persistent(object): query += "," + also_from query += " WHERE " + where if cls.sql_debug: - rpki.log.debug("sql_fetch_where(%r, %r)" % (query, args)) + logger.debug("sql_fetch_where(%r, %r)" % (query, args)) gctx.sql.execute(query, args) results = [] for row in gctx.sql.fetchall(): @@ -279,7 +282,7 @@ class sql_persistent(object): Mark this object as needing to be written back to SQL. """ if self.sql_cache_debug and not self.sql_is_dirty: - rpki.log.debug("Marking %r SQL dirty" % self) + logger.debug("Marking %r SQL dirty" % self) self.gctx.sql.dirty.add(self) def sql_mark_clean(self): @@ -287,7 +290,7 @@ class sql_persistent(object): Mark this object as not needing to be written back to SQL. """ if self.sql_cache_debug and self.sql_is_dirty: - rpki.log.debug("Marking %r SQL clean" % self) + logger.debug("Marking %r SQL clean" % self) self.gctx.sql.dirty.discard(self) @property @@ -311,14 +314,14 @@ class sql_persistent(object): args = self.sql_encode() if not self.sql_in_db: if self.sql_debug: - rpki.log.debug("sql_store(%r, %r)" % (self.sql_template.insert, args)) + logger.debug("sql_store(%r, %r)" % (self.sql_template.insert, args)) self.gctx.sql.execute(self.sql_template.insert, args) setattr(self, self.sql_template.index, self.gctx.sql.lastrowid()) self.gctx.sql.cache[(self.__class__, self.gctx.sql.lastrowid())] = self self.sql_insert_hook() else: if self.sql_debug: - rpki.log.debug("sql_store(%r, %r)" % (self.sql_template.update, args)) + logger.debug("sql_store(%r, %r)" % (self.sql_template.update, args)) self.gctx.sql.execute(self.sql_template.update, args) self.sql_update_hook() key = (self.__class__, getattr(self, self.sql_template.index)) @@ -333,7 +336,7 @@ class sql_persistent(object): if self.sql_in_db: id = getattr(self, self.sql_template.index) # pylint: disable=W0622 if self.sql_debug: - rpki.log.debug("sql_delete(%r, %r)" % (self.sql_template.delete, id)) + logger.debug("sql_delete(%r, %r)" % (self.sql_template.delete, id)) self.sql_delete_hook() self.gctx.sql.execute(self.sql_template.delete, (id,)) key = (self.__class__, id) diff --git a/rpki/up_down.py b/rpki/up_down.py index d2ad85d3..15596eff 100644 --- a/rpki/up_down.py +++ b/rpki/up_down.py @@ -22,6 +22,7 @@ RPKI "up-down" protocol. """ import base64 +import logging import lxml.etree import rpki.resource_set import rpki.x509 @@ -30,6 +31,8 @@ import rpki.log import rpki.xml_utils import rpki.relaxng +logger = logging.getLogger(__name__) + xmlns = "http://www.apnic.net/specs/rescerts/up-down/" nsmap = { None : xmlns } @@ -246,17 +249,17 @@ class list_pdu(base_elt): r_msg.payload = list_response_pdu() if irdb_resources.valid_until < rpki.sundial.now(): - rpki.log.debug("Child %s's resources expired %s" % (child.child_handle, irdb_resources.valid_until)) + logger.debug("Child %s's resources expired %s" % (child.child_handle, irdb_resources.valid_until)) else: for parent in child.parents: for ca in parent.cas: ca_detail = ca.active_ca_detail if not ca_detail: - rpki.log.debug("No active ca_detail, can't issue to %s" % child.child_handle) + logger.debug("No active ca_detail, can't issue to %s" % child.child_handle) continue resources = ca_detail.latest_ca_cert.get_3779resources() & irdb_resources if resources.empty(): - rpki.log.debug("No overlap between received resources and what child %s should get ([%s], [%s])" % (child.child_handle, ca_detail.latest_ca_cert.get_3779resources(), irdb_resources)) + logger.debug("No overlap between received resources and what child %s should get ([%s], [%s])" % (child.child_handle, ca_detail.latest_ca_cert.get_3779resources(), irdb_resources)) continue rc = class_elt() rc.class_name = str(ca.ca_id) @@ -280,7 +283,7 @@ class list_pdu(base_elt): Send a "list" query to parent. """ try: - rpki.log.info('Sending "list" request to parent %s' % parent.parent_handle) + logger.info('Sending "list" request to parent %s' % parent.parent_handle) parent.query_up_down(cls(), cb, eb) except (rpki.async.ExitNow, SystemExit): raise @@ -437,7 +440,7 @@ class issue_pdu(base_elt): is_ca = True, caRepository = ca.sia_uri, rpkiManifest = ca_detail.manifest_uri) - rpki.log.info('Sending "issue" request to parent %s' % parent.parent_handle) + logger.info('Sending "issue" request to parent %s' % parent.parent_handle) parent.query_up_down(self, callback, errback) class issue_response_pdu(class_response_syntax): @@ -506,7 +509,7 @@ class revoke_pdu(revoke_syntax): self = cls() self.class_name = ca.parent_resource_class self.ski = gski - rpki.log.info('Sending "revoke" request for SKI %s to parent %s' % (gski, parent.parent_handle)) + logger.info('Sending "revoke" request for SKI %s to parent %s' % (gski, parent.parent_handle)) parent.query_up_down(self, cb, eb) class revoke_response_pdu(revoke_syntax): @@ -544,10 +547,10 @@ class error_response_pdu(base_elt): """ base_elt.__init__(self) if exception is not None: - rpki.log.debug("Constructing up-down error response from exception %s" % exception) + logger.debug("Constructing up-down error response from exception %s" % exception) exception_type = type(exception) request_type = None if request_payload is None else type(request_payload) - rpki.log.debug("Constructing up-down error response: exception_type %s, request_type %s" % ( + logger.debug("Constructing up-down error response: exception_type %s, request_type %s" % ( exception_type, request_type)) if False: self.status = self.exceptions.get((exception_type, request_type), @@ -556,13 +559,13 @@ class error_response_pdu(base_elt): else: self.status = self.exceptions.get((exception_type, request_type)) if self.status is None: - rpki.log.debug("No request-type-specific match, trying exception match") + logger.debug("No request-type-specific match, trying exception match") self.status = self.exceptions.get(exception_type) if self.status is None: - rpki.log.debug("No exception match either, defaulting") + logger.debug("No exception match either, defaulting") self.status = 2001 self.description = str(exception) - rpki.log.debug("Chosen status code: %s" % self.status) + logger.debug("Chosen status code: %s" % self.status) def endElement(self, stack, name, text): """ @@ -681,7 +684,7 @@ class message_pdu(base_elt): """ Log query we're handling. Separate method so rootd can override. """ - rpki.log.info("Serving %s query from child %s [sender %s, recipient %s]" % (self.type, child.child_handle, self.sender, self.recipient)) + logger.info("Serving %s query from child %s [sender %s, recipient %s]" % (self.type, child.child_handle, self.sender, self.recipient)) def serve_error(self, exception): """ diff --git a/rpki/x509.py b/rpki/x509.py index fb1a5a2b..41daade5 100644 --- a/rpki/x509.py +++ b/rpki/x509.py @@ -39,6 +39,7 @@ import os import subprocess import email.mime.application import email.utils +import logging import mailbox import time import rpki.exceptions @@ -49,6 +50,8 @@ import rpki.log import rpki.async import rpki.relaxng +logger = logging.getLogger(__name__) + def base64_with_linebreaks(der): """ Encode DER (really, anything) as Base64 text, with linebreaks to @@ -127,8 +130,8 @@ class X501DN(object): import traceback for chunk in traceback.format_stack(limit = 5): for line in chunk.splitlines(): - rpki.log.debug("== %s" % line) - rpki.log.debug("++ %r %r" % (self, self.dn)) + logger.debug("== %s" % line) + logger.debug("++ %r %r" % (self, self.dn)) @classmethod def from_cn(cls, cn, sn = None): @@ -279,7 +282,7 @@ class DER_object(object): filename = self.filename timestamp = os.stat(self.filename).st_mtime if self.timestamp is None or self.timestamp < timestamp: - rpki.log.debug("Updating %s, timestamp %s" % (filename, rpki.sundial.datetime.fromtimestamp(timestamp))) + logger.debug("Updating %s, timestamp %s" % (filename, rpki.sundial.datetime.fromtimestamp(timestamp))) f = open(filename, "rb") value = f.read() f.close() @@ -293,7 +296,7 @@ class DER_object(object): except (IOError, OSError), e: now = rpki.sundial.now() if self.lastfail is None or now > self.lastfail + self.failure_threshold: - rpki.log.warn("Could not auto_update %r (last failure %s): %s" % (self, self.lastfail, e)) + logger.warning("Could not auto_update %r (last failure %s): %s" % (self, self.lastfail, e)) self.lastfail = now else: self.lastfail = None @@ -1126,7 +1129,7 @@ class insecure_debug_only_rsa_key_generator(object): self.filename = filename self.db = dbm_du_jour.open(filename, "c") except: - rpki.log.warn("insecure_debug_only_rsa_key_generator initialization FAILED, hack inoperative") + logger.warning("insecure_debug_only_rsa_key_generator initialization FAILED, hack inoperative") raise def __call__(self): @@ -1268,7 +1271,7 @@ class RSA(PrivateKey): Generate a new keypair. """ if not quiet: - rpki.log.debug("Generating new %d-bit RSA key" % keylength) + logger.debug("Generating new %d-bit RSA key" % keylength) if generate_insecure_debug_only_rsa_key is not None: return cls(POW = generate_insecure_debug_only_rsa_key()) else: @@ -1287,13 +1290,13 @@ class ECDSA(PrivateKey): if params is None: if not quiet: - rpki.log.debug("Generating new ECDSA key parameters") + logger.debug("Generating new ECDSA key parameters") params = KeyParams.generateEC() assert isinstance(params, KeyParams) if not quiet: - rpki.log.debug("Generating new ECDSA key") + logger.debug("Generating new ECDSA key") return cls(POW = rpki.POW.Asymmetric.generateFromParams(params.get_POW())) @@ -1383,7 +1386,7 @@ class CMS_object(DER_object): raise except Exception: if self.print_on_der_error: - rpki.log.debug("Problem parsing DER CMS message, might not really be DER: %r" % + logger.debug("Problem parsing DER CMS message, might not really be DER: %r" % self.get_DER()) raise rpki.exceptions.UnparsableCMSDER @@ -1396,10 +1399,10 @@ class CMS_object(DER_object): if self.debug_cms_certs: for x in certs: - rpki.log.debug("Received CMS cert issuer %s subject %s SKI %s" % ( + logger.debug("Received CMS cert issuer %s subject %s SKI %s" % ( x.getIssuer(), x.getSubject(), x.hSKI())) for c in crls: - rpki.log.debug("Received CMS CRL issuer %r" % (c.getIssuer(),)) + logger.debug("Received CMS CRL issuer %r" % (c.getIssuer(),)) store = rpki.POW.X509Store() @@ -1409,7 +1412,7 @@ class CMS_object(DER_object): for x in X509.normalize_chain(ta): if self.debug_cms_certs: - rpki.log.debug("CMS trusted cert issuer %s subject %s SKI %s" % ( + logger.debug("CMS trusted cert issuer %s subject %s SKI %s" % ( x.getIssuer(), x.getSubject(), x.hSKI())) if x.getNotAfter() < now: raise rpki.exceptions.TrustedCMSCertHasExpired("Trusted CMS certificate has expired", @@ -1424,7 +1427,7 @@ class CMS_object(DER_object): if trusted_ee: if self.debug_cms_certs: - rpki.log.debug("Trusted CMS EE cert issuer %s subject %s SKI %s" % ( + logger.debug("Trusted CMS EE cert issuer %s subject %s SKI %s" % ( trusted_ee.getIssuer(), trusted_ee.getSubject(), trusted_ee.hSKI())) if len(certs) > 1 or (len(certs) == 1 and (certs[0].getSubject() != trusted_ee.getSubject() or @@ -1446,7 +1449,7 @@ class CMS_object(DER_object): if self.require_crls: raise rpki.exceptions.MissingCMSCRL else: - rpki.log.warn("MISSING CMS CRL! Ignoring per self.require_crls setting") + logger.warning("MISSING CMS CRL! Ignoring per self.require_crls setting") if len(crls) > 1 and not self.allow_extra_crls: raise rpki.exceptions.UnexpectedCMSCRLs("Unexpected CRLs", *("%s (%s)" % ( c.getIssuer(), c.hAKI()) for c in crls)) @@ -1458,7 +1461,7 @@ class CMS_object(DER_object): for c in crls: if c.getNextUpdate() < now: - rpki.log.warn("Stale BPKI CMS CRL (%s %s %s)" % (c.getNextUpdate(), c.getIssuer(), c.hAKI())) + logger.warning("Stale BPKI CMS CRL (%s %s %s)" % (c.getNextUpdate(), c.getIssuer(), c.hAKI())) try: content = cms.verify(store) @@ -1470,9 +1473,9 @@ class CMS_object(DER_object): dbg = self.dumpasn1() else: dbg = cms.pprint() - rpki.log.warn("CMS verification failed, dumping ASN.1 (%d octets):" % len(self.get_DER())) + logger.warning("CMS verification failed, dumping ASN.1 (%d octets):" % len(self.get_DER())) for line in dbg.splitlines(): - rpki.log.warn(line) + logger.warning(line) raise rpki.exceptions.CMSVerificationFailed("CMS verification failed") return content @@ -1526,10 +1529,10 @@ class CMS_object(DER_object): crls = (crls,) if self.debug_cms_certs: - rpki.log.debug("Signing with cert issuer %s subject %s SKI %s" % ( + logger.debug("Signing with cert issuer %s subject %s SKI %s" % ( cert.getIssuer(), cert.getSubject(), cert.hSKI())) for i, c in enumerate(certs): - rpki.log.debug("Additional cert %d issuer %s subject %s SKI %s" % ( + logger.debug("Additional cert %d issuer %s subject %s SKI %s" % ( i, c.getIssuer(), c.getSubject(), c.hSKI())) self._sign(cert.get_POW(), @@ -1761,7 +1764,7 @@ class DeadDrop(object): self.warned = False except Exception, e: if not self.warned: - rpki.log.warn("Could not write to mailbox %s: %s" % (self.name, e)) + logger.warning("Could not write to mailbox %s: %s" % (self.name, e)) self.warned = True class XML_CMS_object(Wrapped_CMS_object): @@ -1824,9 +1827,9 @@ class XML_CMS_object(Wrapped_CMS_object): try: self.schema.assertValid(self.get_content()) except lxml.etree.DocumentInvalid: - rpki.log.error("PDU failed schema check") + logger.error("PDU failed schema check") for line in self.pretty_print_content().splitlines(): - rpki.log.warn(line) + logger.warning(line) raise def dump_to_disk(self, prefix): |