aboutsummaryrefslogtreecommitdiff
path: root/ca/tests/smoketest.py
diff options
context:
space:
mode:
Diffstat (limited to 'ca/tests/smoketest.py')
-rw-r--r--ca/tests/smoketest.py125
1 files changed, 64 insertions, 61 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
generated by cgit v1.2.3 (git 2.25.1) at 2025-05-10 13:52:38 +0000